Re: [PATCH 4/4 v2] rcu: Have the RCU tracepoints use the tracepoint_string infrastructure

Sasha Levin
2014-04-30T22:30:16Z

On 08/01/2013 10:39 PM, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
>
> Currently, RCU tracepoints save only a pointer to strings in the
> ring buffer. When displayed via the /sys/kernel/debug/tracing/trace file
> they are referenced like the printf "%s" that looks at the address
> in the ring buffer and prints out the string it points too. This requires
> that the strings are constant and persistent in the kernel.
>
> The problem with this is for tools like trace-cmd and perf that read the
> binary data from the buffers but have no access to the kernel memory to
> find out what string is represented by the address in the buffer.
>
> By using the tracepoint_string infrastructure, the RCU tracepoint strings
> can be exported such that userspace tools can map the addresses to
> the strings.
>
> # cat /sys/kernel/debug/tracing/printk_formats
> 0xffffffff81a4a0e8 : "rcu_preempt"
> 0xffffffff81a4a0f4 : "rcu_bh"
> 0xffffffff81a4a100 : "rcu_sched"
> 0xffffffff818437a0 : "cpuqs"
> 0xffffffff818437a6 : "rcu_sched"
> 0xffffffff818437a0 : "cpuqs"
> 0xffffffff818437b0 : "rcu_bh"
> 0xffffffff818437b7 : "Start context switch"
> 0xffffffff818437cc : "End context switch"
> 0xffffffff818437a0 : "cpuqs"
> [...]
>
> Now userspaces tools can display:
>
> rcu_utilization: Start context switch
> rcu_dyntick: Start 1 0
> rcu_utilization: End context switch
> rcu_batch_start: rcu_preempt CBs=0/5 bl=10
> rcu_dyntick: End 0 140000000000000
> rcu_invoke_callback: rcu_preempt rhp=0xffff880071c0d600 func=proc_i_callback
> rcu_invoke_callback: rcu_preempt rhp=0xffff880077b5b230 func=__d_free
> rcu_dyntick: Start 140000000000000 0
> rcu_invoke_callback: rcu_preempt rhp=0xffff880077563980 func=file_free_rcu
> rcu_batch_end: rcu_preempt CBs-invoked=3 idle=>c<>c<>c<>c<
> rcu_utilization: End RCU core
> rcu_grace_period: rcu_preempt 9741 start
> rcu_dyntick: Start 1 0
> rcu_dyntick: End 0 140000000000000
> rcu_dyntick: Start 140000000000000 0
>
> Instead of:
>
> rcu_utilization: ffffffff81843110
> rcu_future_grace_period: ffffffff81842f1d 9939 9939 9940 0 0 3 ffffffff81842f32
> rcu_batch_start: ffffffff81842f1d CBs=0/4 bl=10
> rcu_future_grace_period: ffffffff81842f1d 9939 9939 9940 0 0 3 ffffffff81842f3c
> rcu_grace_period: ffffffff81842f1d 9939 ffffffff81842f80
> rcu_invoke_callback: ffffffff81842f1d rhp=0xffff88007888aac0 func=file_free_rcu
> rcu_grace_period: ffffffff81842f1d 9939 ffffffff81842f95
> rcu_invoke_callback: ffffffff81842f1d rhp=0xffff88006aeb4600 func=proc_i_callback
> rcu_future_grace_period: ffffffff81842f1d 9939 9939 9940 0 0 3 ffffffff81842f32
> rcu_future_grace_period: ffffffff81842f1d 9939 9939 9940 0 0 3 ffffffff81842f3c
> rcu_invoke_callback: ffffffff81842f1d rhp=0xffff880071cb9fc0 func=__d_free
> rcu_grace_period: ffffffff81842f1d 9939 ffffffff81842f80
> rcu_invoke_callback: ffffffff81842f1d rhp=0xffff88007888ae80 func=file_free_rcu
> rcu_batch_end: ffffffff81842f1d CBs-invoked=4 idle=>c<>c<>c<>c<
> rcu_utilization: ffffffff8184311f
>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

Hi Steven,

It seems that this patch is causing the following for me on -next kernel:

[ 1202.780629] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 1202.782056] Dumping ftrace buffer:
[ 1202.783243] (ftrace buffer empty)
[ 1202.784253] Modules linked in:
[ 1202.784778] CPU: 7 PID: 65 Comm: rcuos/0 Tainted: G W 3.15.0-rc3-next-201
40429-sasha-00015-g7c7e0a7-dirty #427
[ 1202.787872] task: ffff880035c63000 ti: ffff880035c5c000 task.ti: ffff880035c5c000
[ 1202.788722] RIP: rcu_note_context_switch (include/trace/events/rcu.h:20 kernel/rcu/tree.c:216)
[ 1202.790083] RSP: 0018:ffff880035c5dcc8 EFLAGS: 00010286
[ 1202.790468] RAX: 6b6b6b6b6b6b6b6b RBX: ffff880034608de8 RCX: 0000000000000001
[ 1202.790468] RDX: 0000000000000000 RSI: ffffffffa56dd9ef RDI: 6b6b6b6b6b6b6b6b
[ 1202.790468] RBP: ffff880035c5dce8 R08: 0000000000000000 R09: 0000000000000000
[ 1202.790468] R10: 0000000000000001 R11: 0000000000000000 R12: ffffffffa56dd9ef
[ 1202.790468] R13: 0000000000000007 R14: ffffffffa6aca2c3 R15: ffff880036dd0080
[ 1202.790468] FS: 0000000000000000(0000) GS:ffff8801ecc00000(0000) knlGS:0000000000000000
[ 1202.790468] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1202.790468] CR2: 0000000000000004 CR3: 0000000025e2d000 CR4: 00000000000006a0
[ 1202.790468] DR0: 00000000006de000 DR1: 00000000006de000 DR2: 0000000000000000
[ 1202.790468] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[ 1202.790468] Stack:
[ 1202.790468] 0000000000000000 ffff880036dd01f0 ffff8801ecdd7840 0000000000000007
[ 1202.790468] ffff880035c5dd68 ffffffffa4571dee ffff880035c5dd08 ffff880036dd01f0
[ 1202.790468] ffff880035c5dfd8 00000000001d7840 00000000001d7840 00000000001d7840
[ 1202.790468] Call Trace:
[ 1202.790468] __schedule (arch/x86/include/asm/preempt.h:22 kernel/sched/core.c:2585 kernel/sched/core.c:2678)
[ 1202.790468] ? prepare_to_wait_event (kernel/sched/wait.c:218 kernel/sched/wait.c:216)
[ 1202.790468] schedule (kernel/sched/core.c:2765)
[ 1202.790468] rcu_nocb_kthread (kernel/rcu/tree_plugin.h:2234 (discriminator 9))
[ 1202.790468] ? rcu_nocb_kthread (kernel/rcu/rcu.h:84 kernel/rcu/tree_plugin.h:2280)
[ 1202.790468] ? preempt_count_sub (kernel/sched/core.c:2541)
[ 1202.790468] ? bit_waitqueue (kernel/sched/wait.c:291)
[ 1202.790468] ? rcu_cpu_notify (kernel/rcu/tree_plugin.h:2220)
[ 1202.790468] kthread (kernel/kthread.c:210)
[ 1202.790468] ? kthread_create_on_node (kernel/kthread.c:176)
[ 1202.790468] ret_from_fork (arch/x86/kernel/entry_64.S:552)
[ 1202.790468] ? kthread_create_on_node (kernel/kthread.c:176)
[ 1202.790468] Code: 65 ff 0c 25 a0 da 00 00 0f 84 fa 00 00 00 eb 28 0f 1f 84 00 00 00 00 00 48 8b 03 0f 1f 44 00 00 48 8b 7b 08 4c 89 e6 48 83 c3 10 <ff> d0 48 8b 03 48 85 c0 75 eb eb c9 90 44 89 ef e8 e8 71 ff ff
[ 1202.790468] RIP rcu_note_context_switch (include/trace/events/rcu.h:20 kernel/rcu/tree.c:216)
[ 1202.790468] RSP <ffff880035c5dcc8>

Thanks,
Sasha