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
--
To unsubscribe from this list: send the line "unsubscribe linux-trace-users" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
|