Re: [PATCH 00/18] [ANNOUNCE] Dynamically created function based events

[Juri Lelli]

Hi Steve,

On 02/02/18 18:04, Steven Rostedt wrote:
> 
> At Kernel Summit back in October, we tried to bring up trace markers, which
> would be nops within the kernel proper, that would allow modules to hook
> arbitrary trace events to them. The reaction to this proposal was less than
> favorable. We were told that we were trying to make a work around for a
> problem, and not solving it. The problem in our minds is the notion of a
> "stable trace event".
> 
> There are maintainers that do not want trace events, or more trace events in
> their subsystems. This is due to the fact that trace events post an
> interface to user space, and this interface could become required by some
> tool. This may cause the trace event to become stable where it must not
> break the tool, and thus prevent the code from changing.
> 
> Or, the trace event may just have to add padding for fields that tools
> may require. The "success" field of the sched_wakeup trace event is one such
> instance. There is no more "success" variable, but tools may fail if it were
> to go away, so a "1" is simply added to the trace event wasting ring buffer
> real estate.
> 
> I talked with Linus about this, and he told me that we already have these
> markers in the kernel. They are from the mcount/__fentry__ used by function
> tracing. Have the trace events be created by these, and see if this will
> satisfy most areas that want trace events.
> 
> I decided to implement this idea, and here's the patch set.
> 
> Introducing "function based events". These are created dynamically by a
> tracefs file called "function_events". By writing a pseudo prototype into
> this file, you create an event.
> 
>  # mount -t tracefs nodev /sys/kernel/tracing
>  # cd /sys/kernel/tracing
>  # echo 'do_IRQ(symbol ip[16] | x64[6] irq_stack[16])' > function_events
>  # cat events/functions/do_IRQ/format
> name: do_IRQ
> ID: 1399
> format:
> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
> 	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
> 	field:int common_pid;	offset:4;	size:4;	signed:1;
> 
> 	field:unsigned long __parent_ip;	offset:8;	size:8;	signed:0;
> 	field:unsigned long __ip;	offset:16;	size:8;	signed:0;
> 	field:symbol ip;	offset:24;	size:8;	signed:0;
> 	field:x64 irq_stack[6];	offset:32;	size:48;	signed:0;
> 
> print fmt: "%pS->%pS(ip=%pS, irq_stack=%llx:%llx:%llx:%llx:%llx:%llx)", REC->__ip, REC->__parent_ip,
> REC->ip, REC->irq_stack[0], REC->irq_stack[1], REC->irq_stack[2], REC->irq_stack[3], REC->irq_stack[4],
> REC->irq_stack[5]
> 
>  # echo 1 > events/functions/do_IRQ/enable

Got the following:

[  110.433602] =============================
[  110.435671] WARNING: suspicious RCU usage
[  110.437173] 4.15.0-rc9+ #42 Not tainted
[  110.438698] -----------------------------
[  110.440343] /home/juri/Work/kernel/linux/include/linux/rcupdate.h:749 rcu_read_lock_sched() used illegally while idle!
[  110.444480]
[  110.444480] other info that might help us debug this:
[  110.444480]
[  110.447616]
[  110.447616] RCU used illegally from idle CPU!
[  110.447616] rcu_scheduler_active = 2, debug_locks = 1
[  110.452047] RCU used illegally from extended quiescent state!
[  110.454072] 1 lock held by swapper/0/0:
[  110.455447]  #0:  (rcu_read_lock_sched){....}, at: [<00000000de240ad4>] func_event_call+0x0/0x3c0
[  110.458532]
[  110.458532] stack backtrace:
[  110.460066] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.15.0-rc9+ #42
[  110.462300] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-2.fc27 04/01/2014
[  110.464477] Call Trace:
[  110.465095]  <IRQ>
[  110.465600]  dump_stack+0x85/0xc5
[  110.466417]  func_event_call+0x378/0x3c0
[  110.467373]  ? find_held_lock+0x34/0xa0
[  110.468216]  ? common_interrupt+0xa2/0xa2
[  110.468978]  ? irq_work_interrupt+0xb0/0xb0
[  110.470021]  ? hrtimer_start_range_ns+0x1bf/0x3e0
[  110.471031]  ftrace_ops_assist_func+0x64/0xf0
[  110.471941]  ? _raw_spin_unlock_irqrestore+0x55/0x60
[  110.472926]  0xffffffffc02e30bf
[  110.473491]  ? do_IRQ+0x5/0x100
[  110.473977]  do_IRQ+0x5/0x100
[  110.474430]  common_interrupt+0xa2/0xa2
[  110.475014]  </IRQ>
[  110.475341] RIP: 0010:native_safe_halt+0x2/0x10
[  110.476020] RSP: 0018:ffffffff96a03ec8 EFLAGS: 00000206 ORIG_RAX: ffffffffffffffdd
[  110.477137] RAX: ffffffff96a2a500 RBX: 0000000000000000 RCX: 0000000000000000
[  110.478110] RDX: ffffffff96a2a500 RSI: 0000000000000001 RDI: ffffffff96a2a500
[  110.478997] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
[  110.479880] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[  110.480764] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[  110.481661]  default_idle+0x1f/0x1a0
[  110.482118]  do_idle+0x166/0x1e0
[  110.482530]  cpu_startup_entry+0x19/0x20
[  110.482985]  start_kernel+0x40a/0x412
[  110.483385]  secondary_startup_64+0xa5/0xb0

continuing to test this. :)

Thanks,

- Juri