Hi Joel, I found this caused several issues when testing ftrace.
#1) ftrace boottest (FTRACE_STARTUP_TEST) fails #2) mmiotrace reports "IRQs not enabled as expected" error #3) lock subsystem event boottest causes "IRQs not disabled as expected" error (sometimes) #4) ftracetest test.d/event/toplevel-enable.tc causes "suspicious RCU usage" warning #1-#3 were resolved if I reverted this [3/3] patch. #4 is resolved if I revered this [2/3] patch. See attached logs for details. I also attached my kernel .config. I guess the first one comes from PREEMPTIRQ_TRACEPOINTS=n, so it should also disable preemptirq tracer. But #2-#4 we should look into it. Could you help us to solve these issues? Thank you, On Mon, 30 Jul 2018 15:24:20 -0700 Joel Fernandes <j...@joelfernandes.org> wrote: > From: "Joel Fernandes (Google)" <j...@joelfernandes.org> > > This series contains the last 2 patches with minor changes suggested by Peter > and Steven, and an additional clean up of get_lock_stats as suggested by > Peter. > > The preempt/irq tracepoints exist but not everything in the kernel is using it > whenever they need to be notified that a preempt disable/enable or an irq > disable/enable has occurred. This makes things not work simultaneously (for > example, only either lockdep or irqsoff trace-events can be used at a time). > > This is particularly painful to deal with, since turning on lockdep breaks > tracers that install probes on IRQ events, such as the BCC atomic critical > section tracer [1]. This constraint also makes it not possible to use > synthetic > events to trace irqsoff sections with lockdep simulataneously turned on. > > This series solves that, and also results in a nice clean up of relevant parts > of the kernel. Several ifdefs are simpler, and the design is more unified and > better. Also as a result of this, we also speeded performance all rcuidle > tracepoints since their handling is simpler. > > [1] https://github.com/iovisor/bcc/pull/1801/ > > v11->v12: > - minor corrections to changelog > - Added PeterZ's Acks > - Squashed in fix for get_lock_stats > > v10->v11: > - Dropped extra unneeded else statement since > rcu_read_lock_sched_notrace is same as prempt_disable_notrace (PeterZ) > > v9->v10: > - Dropped first 3 and last 2 patches that were applied previously > - Folded SPDK license into the main patch introducing trace_preemptirq.c > (Steve) > - Dropped lockdep_recursing & use simplify get_cpu_var instead (PeterZ) > - Simplify __DO_TRACE and use rcu_dereference_raw for both RCU and SRCU > (PeterZ) > > v8->v9: > - Small style changes to tracepoint code (Mathieu) > - Minor style fix to use PTR_ERR_OR_ZERO (0-day bot) > - Minor fix to test_atomic_sections to use unsigned long. > - Added Namhyung's, Mathieu's Reviewed-by to some patches. > > v7->v8: > - Refactored irqsoff tracer probe defines (Namhyung) > > v6->v7: > - Added a module to simulate an atomic section, a kselftest to load and > and trigger it which verifies the preempt-tracer and this series. > > - Fixed a new warning after I rebased in early boot, this is because > early_boot_irqs_disabled was set too early, I moved it after the lockdep > initialization. > > - added back the softirq fix since it appears it wasn't picked up. > > - Ran Ingo's locking API selftest suite which are passing with this > series. > > - Mathieu suggested ifdef'ing the tracepoint_synchronize_unregister > function incase tracepoints aren't enabled, did that. > > Joel Fernandes (Google) (3): > lockdep: use this_cpu_ptr instead of get_cpu_var stats > tracepoint: Make rcuidle tracepoint callers use SRCU > tracing: Centralize preemptirq tracepoints and unify their usage > > include/linux/ftrace.h | 11 +- > include/linux/irqflags.h | 11 +- > include/linux/lockdep.h | 8 +- > include/linux/preempt.h | 2 +- > include/linux/tracepoint.h | 41 ++++-- > include/trace/events/preemptirq.h | 23 +-- > init/main.c | 5 +- > kernel/locking/lockdep.c | 45 ++---- > kernel/sched/core.c | 2 +- > kernel/trace/Kconfig | 22 ++- > kernel/trace/Makefile | 2 +- > kernel/trace/trace_irqsoff.c | 231 ++++++++---------------------- > kernel/trace/trace_preemptirq.c | 72 ++++++++++ > kernel/tracepoint.c | 16 ++- > 14 files changed, 244 insertions(+), 247 deletions(-) > create mode 100644 kernel/trace/trace_preemptirq.c > > -- > 2.18.0.345.g5c9ce644c3-goog -- Masami Hiramatsu <mhira...@kernel.org>
[ 2.271078] Testing tracer preemptirqsoff: .. no entries found ..FAILED! [ 2.381015] WARNING: CPU: 0 PID: 1 at /home/mhiramat/ksrc/linux/kernel/trace/trace.c:1512 run_tracer_selftest+0xf3/0x154 [ 2.382000] Modules linked in: [ 2.382000] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6+ #15 [ 2.382000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1.fc26 04/01/2014 [ 2.382000] RIP: 0010:run_tracer_selftest+0xf3/0x154 [ 2.382000] Code: 43 60 48 c7 c6 40 f8 07 82 48 89 df e8 9a 5a 8b 00 85 c0 89 c5 4c 89 25 5f 38 f3 00 74 13 48 c7 c7 42 17 de 81 e8 ff 1e f7 ff <0f> 0b 83 cd ff eb 4c 48 c7 c7 58 f8 07 82 e8 4e a0 ff ff 80 bb a2 [ 2.382000] RSP: 0000:ffffc900000d3e68 EFLAGS: 00010286 [ 2.382000] RAX: 0000000000000007 RBX: ffffffff82120a60 RCX: 0000000000000000 [ 2.382000] RDX: 0000000000000000 RSI: ffffffff810bea4f RDI: ffffffff810bea4f [ 2.382000] RBP: 00000000ffffffff R08: 0000000000000000 R09: 0000000000000000 [ 2.382000] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff82120fa0 [ 2.382000] R13: 0000000000000002 R14: ffffffff823fe81d R15: 0000000000000000 [ 2.382000] FS: 0000000000000000(0000) GS:ffff88001f600000(0000) knlGS:0000000000000000 [ 2.382000] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 2.382000] CR2: 0000000000000000 CR3: 000000000201e000 CR4: 00000000000006b0 [ 2.382000] Call Trace: [ 2.382000] register_tracer+0x11b/0x1d1 [ 2.382000] ? trace_event_define_fields_preemptirq_template+0x55/0x55 [ 2.382000] init_irqsoff_tracer+0x24/0x27 [ 2.382000] do_one_initcall+0x5d/0x2f0 [ 2.382000] ? set_debug_rodata+0x11/0x11 [ 2.382000] ? rcu_read_lock_sched_held+0x6b/0x80 [ 2.382000] kernel_init_freeable+0x200/0x28c [ 2.382000] ? rest_init+0xd0/0xd0 [ 2.382000] kernel_init+0xa/0x110 [ 2.382000] ret_from_fork+0x3a/0x50 [ 2.382000] irq event stamp: 604926 [ 2.382000] hardirqs last enabled at (604925): [<0000000000000000>] (null) [ 2.382000] hardirqs last disabled at (604926): [<ffffffff8180115f>] error_entry+0x7f/0x100 [ 2.382000] softirqs last enabled at (604922): [<ffffffff81a00370>] __do_softirq+0x370/0x460 [ 2.382000] softirqs last disabled at (604915): [<ffffffff81062781>] irq_exit+0xc1/0xd0 [ 2.382000] ---[ end trace ee62aecc90f6b764 ]---
/sys/kernel/debug/tracing # echo mmiotrace > current_tracer [ 106.528373] mmiotrace: Disabling non-boot CPUs... [ 106.546027] Unregister pv shared memory for cpu 1 [ 106.550758] ------------[ cut here ]------------ [ 106.551354] IRQs not enabled as expected [ 106.551785] WARNING: CPU: 1 PID: 0 at /home/mhiramat/ksrc/linux/kernel/time/tick-sched.c:982 tick_nohz_idle_enter+0x99/0xb0 [ 106.552964] Modules linked in: [ 106.553299] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G W 4.18.0-rc6+ #15 [ 106.554129] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1.fc26 04/01/2014 [ 106.555058] RIP: 0010:tick_nohz_idle_enter+0x99/0xb0 [ 106.555608] Code: 00 00 5b c3 8b 80 48 08 00 00 85 c0 75 a6 80 3d 59 8d 01 01 00 75 9d 48 c7 c7 9b 8f dc 81 c6 05 49 8d 01 01 01 e8 f7 4d f6 ff <0f> 0b eb 86 0f 0b eb ae 0f 1f 44 00 00 66 2e 0f 1f 84 00 00 00 00 [ 106.557796] RSP: 0018:ffffc9000013bec8 EFLAGS: 00010286 [ 106.558307] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 0000000000000000 [ 106.558997] RDX: 0000000000000002 RSI: 0000000000000001 RDI: 0000000000000001 [ 106.559680] RBP: ffff88001f27c140 R08: 0000000000000000 R09: 0000000000000000 [ 106.560374] R10: ffffc9000013bda8 R11: a8b925c7f0ce6f64 R12: 0000000000000000 [ 106.561072] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 106.561785] FS: 0000000000000000(0000) GS:ffff88001f640000(0000) knlGS:0000000000000000 [ 106.562590] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 106.563141] CR2: 000000000045d6a0 CR3: 000000000201e000 CR4: 00000000000006a0 [ 106.563821] Call Trace: [ 106.564074] do_idle+0x3b/0x250 [ 106.564384] cpu_startup_entry+0x6f/0x80 [ 106.564768] start_secondary+0x1a2/0x1d0 [ 106.565153] secondary_startup_64+0xa5/0xb0 [ 106.565568] irq event stamp: 4848732 [ 106.565922] hardirqs last enabled at (4848731): [<0000000000000000>] (null) [ 106.566679] hardirqs last disabled at (4848732): [<0000000000000000>] (null) [ 106.567441] softirqs last enabled at (4848726): [<ffffffff810626bd>] irq_enter+0x5d/0x60 [ 106.568224] softirqs last disabled at (4848725): [<ffffffff810626a2>] irq_enter+0x42/0x60 [ 106.569004] ---[ end trace 574d547106ecd2dc ]--- [ 106.569557] smpboot: CPU 1 is now offline [ 106.571199] mmiotrace: CPU1 is down. [ 106.582201] Unregister pv shared memory for cpu 2 [ 106.584933] smpboot: CPU 2 is now offline [ 106.586182] mmiotrace: CPU2 is down. [ 106.597164] Unregister pv shared memory for cpu 3 [ 106.599613] smpboot: CPU 3 is now offline [ 106.600605] mmiotrace: CPU3 is down. [ 106.610152] Unregister pv shared memory for cpu 4 [ 106.612392] smpboot: CPU 4 is now offline [ 106.613499] mmiotrace: CPU4 is down. [ 106.628214] Unregister pv shared memory for cpu 5 [ 106.631070] smpboot: CPU 5 is now offline [ 106.632484] mmiotrace: CPU5 is down. [ 106.644250] Unregister pv shared memory for cpu 6 [ 106.647179] smpboot: CPU 6 is now offline [ 106.648693] mmiotrace: CPU6 is down. [ 106.654288] Unregister pv shared memory for cpu 7 [ 106.657585] smpboot: CPU 7 is now offline [ 106.659339] mmiotrace: CPU7 is down. [ 106.660576] mmiotrace: enabled.
[ 45.529609] Testing event system lock: [ 45.558594] ------------[ cut here ]------------ [ 45.562094] IRQs not disabled as expected [ 45.563669] WARNING: CPU: 1 PID: 57 at /home/mhiramat/ksrc/linux/kernel/rcu/tree.c:999 rcu_irq_enter+0x52/0x60 [ 45.566601] Modules linked in: [ 45.567658] CPU: 1 PID: 57 Comm: kworker/1:1 Tainted: G W 4.18.0-rc6+ #15 [ 45.569870] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1.fc26 04/01/2014 [ 45.571468] Workqueue: events free_work [ 45.572235] RIP: 0010:rcu_irq_enter+0x52/0x60 [ 45.573064] Code: 80 48 08 00 00 85 c0 74 09 80 3d a6 65 03 01 00 74 05 e9 31 fe ff ff 48 c7 c7 a0 fd db 81 c6 05 91 65 03 01 01 e8 4e 26 f8 ff <0f> 0b eb e4 66 2e 0f 1f 84 00 00 00 00 00 e8 6b 7b f3 1e 53 9c 58 [ 45.576509] RSP: 0000:ffff88001f643fd8 EFLAGS: 00010082 [ 45.577579] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000 [ 45.578865] RDX: 0000000000000003 RSI: 0000000000000003 RDI: 0000000000000001 [ 45.580108] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 45.581321] R10: 0000000000000000 R11: 26a1dedaa330a26e R12: 0000000000000000 [ 45.582571] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 45.583796] FS: 0000000000000000(0000) GS:ffff88001f640000(0000) knlGS:0000000000000000 [ 45.585260] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 45.586277] CR2: ffffc90000294000 CR3: 000000000201e000 CR4: 00000000000006a0 [ 45.587492] Call Trace: [ 45.588049] <IRQ> [ 45.588539] irq_enter+0xa/0x60 [ 45.589194] smp_call_function_interrupt+0xb/0x1e0 [ 45.590071] call_function_interrupt+0xf/0x20 [ 45.590850] </IRQ> [ 45.591319] RIP: 0010:check_preemption_disabled+0x2/0xe0 [ 45.592214] Code: e7 fc e9 1a ff ff ff e8 9c 02 c3 ff 48 c7 00 00 00 00 00 c7 40 08 00 00 00 00 e9 31 ff ff ff 90 90 90 90 90 90 90 90 90 41 55 <41> 54 55 53 65 8b 1d 53 46 be 7e 65 8b 05 ec a1 be 7e a9 ff ff ff [ 45.595956] RSP: 0000:ffffc9000030bcc0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff03 [ 45.597394] RAX: 0000000000000000 RBX: ffff88001f018600 RCX: 0000000000000246 [ 45.598622] RDX: ffff88001f2bdc68 RSI: ffffffff81df3a3f RDI: ffffffff81e0adbf [ 45.599704] RBP: 0000000000000246 R08: 0000000000000000 R09: 0000000000000000 [ 45.600783] R10: ffff88001f2bdc68 R11: ffff88001f086000 R12: 0000000000000000 [ 45.601860] R13: 0000000000000000 R14: ffffffff8207f840 R15: ffff88001f2bdc68 [ 45.602962] trace_buffer_unlock_commit_regs+0x28/0xa0 [ 45.603798] function_test_events_call+0x14c/0x1a1 [ 45.604590] ? function_test_events_call+0x14c/0x1a1 [ 45.605405] 0xffffffffa0010061 [ 45.606007] ? 0xffffffffa0010061 [ 45.606636] ? find_held_lock+0x2d/0x90 [ 45.607401] ? _raw_spin_lock+0x5/0x40 [ 45.608063] ? find_vmap_area+0x5/0x60 [ 45.608769] ? preempt_count_sub+0x9b/0xd0 [ 45.609565] _raw_spin_lock+0x5/0x40 [ 45.610234] find_vmap_area+0x15/0x60 [ 45.610900] remove_vm_area+0xc/0x70 [ 45.611572] __vunmap+0x5a/0xe0 [ 45.612153] free_work+0x21/0x30 [ 45.612762] process_one_work+0x291/0x640 [ 45.613534] worker_thread+0x2d/0x3d0 [ 45.614196] ? process_one_work+0x640/0x640 [ 45.614919] kthread+0x113/0x130 [ 45.615517] ? kthread_create_worker_on_cpu+0x70/0x70 [ 45.616350] ret_from_fork+0x3a/0x50 [ 45.617013] irq event stamp: 30223 [ 45.617630] hardirqs last enabled at (30223): [<0000000000000000>] (null) [ 45.618900] hardirqs last disabled at (30222): [<0000000000000000>] (null) [ 45.620170] softirqs last enabled at (27564): [<ffffffff81a00370>] __do_softirq+0x370/0x460 [ 45.621536] softirqs last disabled at (27545): [<ffffffff81062781>] irq_exit+0xc1/0xd0 [ 45.622821] ---[ end trace 574d547106ecd2d8 ]--- [ 45.623593] ------------[ cut here ]------------ [ 45.624417] IRQs not disabled as expected [ 45.625130] WARNING: CPU: 1 PID: 57 at /home/mhiramat/ksrc/linux/kernel/smp.c:216 flush_smp_call_function_queue+0xd0/0x150 [ 45.626835] Modules linked in: [ 45.627410] CPU: 1 PID: 57 Comm: kworker/1:1 Tainted: G W 4.18.0-rc6+ #15 [ 45.628751] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1.fc26 04/01/2014 [ 45.630188] Workqueue: events free_work [ 45.630878] RIP: 0010:flush_smp_call_function_queue+0xd0/0x150 [ 45.631810] Code: 00 00 85 c0 0f 84 79 ff ff ff 80 3d e7 3b 01 01 00 0f 85 6c ff ff ff 48 c7 c7 a0 fd db 81 c6 05 d3 3b 01 01 01 e8 80 fc f5 ff <0f> 0b e9 52 ff ff ff 0f 0b eb 99 e8 50 fd 32 00 89 c0 48 0f a3 05 [ 45.634885] RSP: 0000:ffff88001f643fc8 EFLAGS: 00010086 [ 45.635739] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000 [ 45.636832] RDX: 0000000000010003 RSI: 0000000000000003 RDI: 0000000000000001 [ 45.637920] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 45.639008] R10: 0000000000000000 R11: a8b925c7f0ce6f64 R12: 0000000000000001 [ 45.640097] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 45.641195] FS: 0000000000000000(0000) GS:ffff88001f640000(0000) knlGS:0000000000000000 [ 45.642523] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 45.643433] CR2: ffffc90000294000 CR3: 000000000201e000 CR4: 00000000000006a0 [ 45.644537] Call Trace: [ 45.645029] <IRQ> [ 45.645471] smp_call_function_interrupt+0x49/0x1e0 [ 45.647632] call_function_interrupt+0xf/0x20 [ 45.648396] </IRQ> [ 45.648863] RIP: 0010:check_preemption_disabled+0x2/0xe0 [ 45.649724] Code: e7 fc e9 1a ff ff ff e8 9c 02 c3 ff 48 c7 00 00 00 00 00 c7 40 08 00 00 00 00 e9 31 ff ff ff 90 90 90 90 90 90 90 90 90 41 55 <41> 54 55 53 65 8b 1d 53 46 be 7e 65 8b 05 ec a1 be 7e a9 ff ff ff [ 45.652776] RSP: 0000:ffffc9000030bcc0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff03 [ 45.654047] RAX: 0000000000000000 RBX: ffff88001f018600 RCX: 0000000000000246 [ 45.655241] RDX: ffff88001f2bdc68 RSI: ffffffff81df3a3f RDI: ffffffff81e0adbf [ 45.656468] RBP: 0000000000000246 R08: 0000000000000000 R09: 0000000000000000 [ 45.657598] R10: ffff88001f2bdc68 R11: ffff88001f086000 R12: 0000000000000000 [ 45.658693] R13: 0000000000000000 R14: ffffffff8207f840 R15: ffff88001f2bdc68 [ 45.659812] trace_buffer_unlock_commit_regs+0x28/0xa0 [ 45.660694] function_test_events_call+0x14c/0x1a1 [ 45.661544] ? function_test_events_call+0x14c/0x1a1 [ 45.662365] 0xffffffffa0010061 [ 45.662955] ? 0xffffffffa0010061 [ 45.663567] ? find_held_lock+0x2d/0x90 [ 45.664245] ? _raw_spin_lock+0x5/0x40 [ 45.664983] ? find_vmap_area+0x5/0x60 [ 45.665657] ? preempt_count_sub+0x9b/0xd0 [ 45.666361] _raw_spin_lock+0x5/0x40 [ 45.667005] find_vmap_area+0x15/0x60 [ 45.667658] remove_vm_area+0xc/0x70 [ 45.668298] __vunmap+0x5a/0xe0 [ 45.668892] free_work+0x21/0x30 [ 45.669486] process_one_work+0x291/0x640 [ 45.670198] worker_thread+0x2d/0x3d0 [ 45.670858] ? process_one_work+0x640/0x640 [ 45.671573] kthread+0x113/0x130 [ 45.672167] ? kthread_create_worker_on_cpu+0x70/0x70 [ 45.673001] ret_from_fork+0x3a/0x50 [ 45.673681] irq event stamp: 30223 [ 45.674308] hardirqs last enabled at (30223): [<0000000000000000>] (null) [ 45.675591] hardirqs last disabled at (30222): [<0000000000000000>] (null) [ 45.676866] softirqs last enabled at (27564): [<ffffffff81a00370>] __do_softirq+0x370/0x460 [ 45.678233] softirqs last disabled at (27545): [<ffffffff81062781>] irq_exit+0xc1/0xd0 [ 45.679542] ---[ end trace 574d547106ecd2d9 ]--- [ 45.680310] ------------[ cut here ]------------ [ 45.681102] IRQs not disabled as expected [ 45.681795] WARNING: CPU: 1 PID: 57 at /home/mhiramat/ksrc/linux/kernel/rcu/tree.c:846 rcu_irq_exit+0x52/0x60 [ 45.683407] Modules linked in: [ 45.683982] CPU: 1 PID: 57 Comm: kworker/1:1 Tainted: G W 4.18.0-rc6+ #15 [ 45.685295] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1.fc26 04/01/2014 [ 45.686696] Workqueue: events free_work [ 45.687573] RIP: 0010:rcu_irq_exit+0x52/0x60 [ 45.688386] Code: 80 48 08 00 00 85 c0 74 09 80 3d c8 69 03 01 00 74 05 e9 41 fd ff ff 48 c7 c7 a0 fd db 81 c6 05 b3 69 03 01 01 e8 6e 2a f8 ff <0f> 0b eb e4 66 2e 0f 1f 84 00 00 00 00 00 e8 8b 7f f3 1e 53 9c 58 [ 45.691628] RSP: 0000:ffff88001f643fe8 EFLAGS: 00010086 [ 45.692472] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000 [ 45.693571] RDX: 0000000000000003 RSI: 0000000000000003 RDI: 0000000000000001 [ 45.694707] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 45.695790] R10: 0000000000000000 R11: a8b925c7f0ce6f64 R12: 0000000000000000 [ 45.696880] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 45.697979] FS: 0000000000000000(0000) GS:ffff88001f640000(0000) knlGS:0000000000000000 [ 45.699301] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 45.700244] CR2: ffffc90000294000 CR3: 000000000201e000 CR4: 00000000000006a0 [ 45.701339] Call Trace: [ 45.701839] <IRQ> [ 45.702277] irq_exit+0x5c/0xd0 [ 45.702866] call_function_interrupt+0xf/0x20 [ 45.703605] </IRQ> [ 45.704053] RIP: 0010:check_preemption_disabled+0x2/0xe0 [ 45.704907] Code: e7 fc e9 1a ff ff ff e8 9c 02 c3 ff 48 c7 00 00 00 00 00 c7 40 08 00 00 00 00 e9 31 ff ff ff 90 90 90 90 90 90 90 90 90 41 55 <41> 54 55 53 65 8b 1d 53 46 be 7e 65 8b 05 ec a1 be 7e a9 ff ff ff [ 45.707968] RSP: 0000:ffffc9000030bcc0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff03 [ 45.709224] RAX: 0000000000000000 RBX: ffff88001f018600 RCX: 0000000000000246 [ 45.710310] RDX: ffff88001f2bdc68 RSI: ffffffff81df3a3f RDI: ffffffff81e0adbf [ 45.711397] RBP: 0000000000000246 R08: 0000000000000000 R09: 0000000000000000 [ 45.712477] R10: ffff88001f2bdc68 R11: ffff88001f086000 R12: 0000000000000000 [ 45.713571] R13: 0000000000000000 R14: ffffffff8207f840 R15: ffff88001f2bdc68 [ 45.714684] trace_buffer_unlock_commit_regs+0x28/0xa0 [ 45.715525] function_test_events_call+0x14c/0x1a1 [ 45.716316] ? function_test_events_call+0x14c/0x1a1 [ 45.717224] 0xffffffffa0010061 [ 45.717812] ? 0xffffffffa0010061 [ 45.718463] ? find_held_lock+0x2d/0x90 [ 45.719336] ? _raw_spin_lock+0x5/0x40 [ 45.720041] ? find_vmap_area+0x5/0x60 [ 45.720986] ? preempt_count_sub+0x9b/0xd0 [ 45.721761] _raw_spin_lock+0x5/0x40 [ 45.722394] find_vmap_area+0x15/0x60 [ 45.723045] remove_vm_area+0xc/0x70 [ 45.723686] __vunmap+0x5a/0xe0 [ 45.724266] free_work+0x21/0x30 [ 45.724861] process_one_work+0x291/0x640 [ 45.725565] worker_thread+0x2d/0x3d0 [ 45.726212] ? process_one_work+0x640/0x640 [ 45.726922] kthread+0x113/0x130 [ 45.727523] ? kthread_create_worker_on_cpu+0x70/0x70 [ 45.728185] ------------[ cut here ]------------ [ 45.728429] ret_from_fork+0x3a/0x50 [ 45.729574] IRQs not disabled as expected [ 45.730235] irq event stamp: 30223 [ 45.731222] WARNING: CPU: 0 PID: 0 at /home/mhiramat/ksrc/linux/kernel/softirq.c:144 __local_bh_enable+0x77/0xc0 [ 45.731834] hardirqs last enabled at (30223): [<0000000000000000>] (null) [ 45.731838] hardirqs last disabled at (30222): [<0000000000000000>] (null) [ 45.734188] Modules linked in: [ 45.735488] softirqs last enabled at (27564): [<ffffffff81a00370>] __do_softirq+0x370/0x460 [ 45.735493] softirqs last disabled at (27545): [<ffffffff81062781>] irq_exit+0xc1/0xd0 [ 45.737925] ---[ end trace 574d547106ecd2da ]--- [ 45.742704] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W 4.18.0-rc6+ #15 [ 45.744255] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1.fc26 04/01/2014 [ 45.745944] RIP: 0010:__local_bh_enable+0x77/0xc0 [ 45.746972] Code: 7e 5b 5d c3 8b 80 48 08 00 00 85 c0 74 cb 80 3d ee d0 0a 01 00 75 c2 48 c7 c7 a0 fd db 81 c6 05 de d0 0a 01 01 e8 a9 91 ff ff <0f> 0b eb ab 48 8b 7c 24 10 e8 3b 4a 05 00 eb be 48 8b 6c 24 10 48 [ 45.750773] RSP: 0000:ffff88001f603f78 EFLAGS: 00010086 [ 45.751744] RAX: 0000000000000000 RBX: 0000000000000100 RCX: 0000000000000000 [ 45.753077] RDX: 0000000000000102 RSI: 0000000000000001 RDI: 0000000000000001 [ 45.754389] RBP: 0000000000000040 R08: 0000000000000000 R09: 0000000000000000 [ 45.755709] R10: ffff88001f018600 R11: ffff88001f080800 R12: ffffffff82005138 [ 45.756974] R13: 0000000000000007 R14: 0000000000000007 R15: 0000000000000000 [ 45.758291] FS: 0000000000000000(0000) GS:ffff88001f600000(0000) knlGS:0000000000000000 [ 45.759868] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 45.761080] CR2: 0000000000000000 CR3: 000000000201e000 CR4: 00000000000006b0 [ 45.762517] Call Trace: [ 45.763049] <IRQ> [ 45.763525] __do_softirq+0x370/0x460 [ 45.764237] irq_exit+0xc1/0xd0 [ 45.764857] reschedule_interrupt+0xf/0x20 [ 45.765623] </IRQ> [ 45.766103] RIP: 0010:native_safe_halt+0x2/0x10 [ 45.766919] Code: 72 8b 7e ff ff ff 7f 5b c3 65 48 8b 04 25 40 4d 01 00 f0 80 48 02 20 48 8b 00 a8 08 74 8b eb c1 90 90 90 90 90 90 90 90 fb f4 <c3> 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 f4 c3 90 90 90 90 90 90 [ 45.770400] RSP: 0000:ffffffff82003e80 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff02 [ 45.771735] RAX: 000000000001c6c0 RBX: 0000000000000000 RCX: 0000000000000000 [ 45.772888] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffffffff8207e080 [ 45.774082] RBP: ffffffff82120198 R08: 0000000000000001 R09: 0000000000000000 [ 45.775236] R10: ffff88001f018600 R11: ffff88001f080800 R12: 0000000000000000 [ 45.776387] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 [ 45.777585] default_idle+0x1f/0x160 [ 45.778269] default_idle_call+0x24/0x40 [ 45.778997] do_idle+0x210/0x250 [ 45.779627] ? do_idle+0x1ab/0x250 [ 45.780291] cpu_startup_entry+0x6f/0x80 [ 45.781023] start_kernel+0x49d/0x4bd [ 45.781745] secondary_startup_64+0xa5/0xb0 [ 45.782586] irq event stamp: 5071134 [ 45.783293] hardirqs last enabled at (5071134): [<0000000000000000>] (null) [ 45.784893] hardirqs last disabled at (5071133): [<0000000000000000>] (null) [ 45.786407] softirqs last enabled at (5071116): [<ffffffff810626bd>] irq_enter+0x5d/0x60 [ 45.787824] softirqs last disabled at (5071117): [<ffffffff81062781>] irq_exit+0xc1/0xd0 [ 45.789209] ---[ end trace 574d547106ecd2db ]--- [ 45.790609] OK [ 45.791162] Testing event system sched: OK
/mnt/ftrace # ./ftracetest test.d/event/toplevel-enable.tc
=== Ftrace unit tests ===
[1] event tracing - enable/disable with top level files[ 282.060356]
[ 282.060593] WARNING: can't dereference registers at 00000000f3c7f62b for ip
interrupt_entry+0xc4/0xe0
[ 282.063200] =============================
[ 282.064082] WARNING: suspicious RCU usage
[ 282.064963] 4.18.0-rc6+ #15 Tainted: G W
[ 282.066048] -----------------------------
[ 282.066923] /home/mhiramat/ksrc/linux/kernel/trace/trace_events.c:242
suspicious rcu_dereference_check() usage!
[ 282.068974]
[ 282.068974] other info that might help us debug this:
[ 282.068974]
[ 282.070770]
[ 282.070770] RCU used illegally from idle CPU!
[ 282.070770] rcu_scheduler_active = 2, debug_locks = 1
[ 282.072938] RCU used illegally from extended quiescent state!
[ 282.074183] no locks held by swapper/0/0.
[ 282.075071]
[ 282.075071] stack backtrace:
[ 282.076121] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W
4.18.0-rc6+ #15
[ 282.077782] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-1.fc26 04/01/2014
[ 282.079604] Call Trace:
[ 282.080212] <IRQ>
[ 282.080755] dump_stack+0x85/0xcb
[ 282.081523] trace_event_ignore_this_pid+0x66/0x70
[ 282.082541] trace_event_raw_event_preemptirq_template+0xa2/0xb0
[ 282.083774] ? interrupt_entry+0xc4/0xe0
[ 282.084665] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.085669] trace_hardirqs_off_caller+0x90/0xd0
[ 282.086597] trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.087433] ? call_function_interrupt+0xa/0x20
[ 282.088201] interrupt_entry+0xc4/0xe0
[ 282.088848] ? call_function_interrupt+0xa/0x20
[ 282.089579] </IRQ>
[ 282.090029] ? native_safe_halt+0x2/0x10
[ 282.090695] ? default_idle+0x1f/0x160
[ 282.091330] ? default_idle_call+0x24/0x40
[ 282.091997] ? do_idle+0x210/0x250
[ 282.092658] ? cpu_startup_entry+0x6f/0x80
[ 282.093338] ? start_kernel+0x49d/0x4bd
[ 282.093987] ? secondary_startup_64+0xa5/0xb0
[ 282.094748]
[ 282.094749] =============================
[ 282.094751] WARNING: suspicious RCU usage
[ 282.094752] 4.18.0-rc6+ #15 Tainted: G W
[ 282.094753] -----------------------------
[ 282.094754] /home/mhiramat/ksrc/linux/include/linux/rcupdate.h:633
rcu_read_lock() used illegally while idle!
[ 282.094754]
[ 282.094755] other info that might help us debug this:
[ 282.094756]
[ 282.094757]
[ 282.094760] RCU used illegally from idle CPU!
[ 282.094761] rcu_scheduler_active = 2, debug_locks = 1
[ 282.094763] RCU used illegally from extended quiescent state!
[ 282.094764] 4 locks held by swapper/0/0:
[ 282.094765] #0: 00000000129c45e9 (console_lock){+.+.}, at:
vprintk_emit+0x23c/0x470
[ 282.094771] #1: 0000000098f3ac4c (console_owner){-...}, at:
console_unlock+0x135/0x600
[ 282.094778] #2: 00000000168da4c3 (printing_lock){....}, at:
vt_console_print+0x78/0x420
[ 282.094784] #3: 0000000033907247 (rcu_read_lock){....}, at:
atomic_notifier_call_chain+0x5/0x100
[ 282.094791]
[ 282.094792] stack backtrace:
[ 282.094792] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W
4.18.0-rc6+ #15
[ 282.094793] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-1.fc26 04/01/2014
[ 282.094794] Call Trace:
[ 282.094795] <IRQ>
[ 282.094795] dump_stack+0x85/0xcb
[ 282.094796] atomic_notifier_call_chain+0xcc/0x100
[ 282.094797] vt_console_print+0x173/0x420
[ 282.094798] console_unlock+0x4b1/0x600
[ 282.094799] vprintk_emit+0x249/0x470
[ 282.094799] printk+0x52/0x6e
[ 282.094800] lockdep_rcu_suspicious+0x1b/0xf0
[ 282.094801] ? interrupt_entry+0xc4/0xe0
[ 282.094801] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.094802] trace_event_ignore_this_pid+0x66/0x70
[ 282.094803] trace_event_raw_event_preemptirq_template+0xa2/0xb0
[ 282.094804] ? interrupt_entry+0xc4/0xe0
[ 282.094804] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.094805] trace_hardirqs_off_caller+0x90/0xd0
[ 282.094806] trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.094806] ? call_function_interrupt+0xa/0x20
[ 282.094807] interrupt_entry+0xc4/0xe0
[ 282.094808] ? call_function_interrupt+0xa/0x20
[ 282.094809] </IRQ>
[ 282.094809] ? native_safe_halt+0x2/0x10
[ 282.094810] ? default_idle+0x1f/0x160
[ 282.094811] ? default_idle_call+0x24/0x40
[ 282.094811] ? do_idle+0x210/0x250
[ 282.094812] ? cpu_startup_entry+0x6f/0x80
[ 282.094813] ? start_kernel+0x49d/0x4bd
[ 282.094814] ? secondary_startup_64+0xa5/0xb0
[ 282.094814]
[ 282.094815] =============================
[ 282.094816] WARNING: suspicious RCU usage
[ 282.094816] 4.18.0-rc6+ #15 Tainted: G W
[ 282.094817] -----------------------------
[ 282.094818] /home/mhiramat/ksrc/linux/include/linux/rcupdate.h:682
rcu_read_unlock() used illegally while idle!
[ 282.094819]
[ 282.094819] other info that might help us debug this:
[ 282.094820]
[ 282.094821]
[ 282.094821] RCU used illegally from idle CPU!
[ 282.094822] rcu_scheduler_active = 2, debug_locks = 1
[ 282.094823] RCU used illegally from extended quiescent state!
[ 282.094823] 4 locks held by swapper/0/0:
[ 282.094824] #0: 00000000129c45e9 (console_lock){+.+.}, at:
vprintk_emit+0x23c/0x470
[ 282.094828] #1: 0000000098f3ac4c (console_owner){-...}, at:
console_unlock+0x135/0x600
[ 282.094831] #2: 00000000168da4c3 (printing_lock){....}, at:
vt_console_print+0x78/0x420
[ 282.094836] #3: 0000000033907247 (rcu_read_lock){....}, at:
atomic_notifier_call_chain+0x5/0x100
[ 282.094839]
[ 282.094840] stack backtrace:
[ 282.094841] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W
4.18.0-rc6+ #15
[ 282.094842] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.10.2-1.fc26 04/01/2014
[ 282.094842] Call Trace:
[ 282.094843] <IRQ>
[ 282.094844] dump_stack+0x85/0xcb
[ 282.094845] atomic_notifier_call_chain+0xf6/0x100
[ 282.094845] vt_console_print+0x173/0x420
[ 282.094846] console_unlock+0x4b1/0x600
[ 282.094847] vprintk_emit+0x249/0x470
[ 282.094847] printk+0x52/0x6e
[ 282.094848] lockdep_rcu_suspicious+0x1b/0xf0
[ 282.094849] ? interrupt_entry+0xc4/0xe0
[ 282.094850] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.094850] trace_event_ignore_this_pid+0x66/0x70
[ 282.094851] trace_event_raw_event_preemptirq_template+0xa2/0xb0
[ 282.094852] ? interrupt_entry+0xc4/0xe0
[ 282.094853] ? trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.094853] trace_hardirqs_off_caller+0x90/0xd0
[ 282.094854] trace_hardirqs_off_thunk+0x1a/0x1c
[ 282.094855] ? call_function_interrupt+0xa/0x20
[ 282.094855] interrupt_entry+0xc4/0xe0
[ 282.094856] ? call_function_interrupt+0xa/0x20
[ 282.094857] </IRQ>
[ 282.094858] ? native_safe_halt+0x2/0x10
[ 282.094858] ? default_idle+0x1f/0x160
[ 282.094859] ? default_idle_call+0x24/0x40
[ 282.094860] ? do_idle+0x210/0x250
[ 282.094860] ? cpu_startup_entry+0x6f/0x80
[ 282.094861] ? start_kernel+0x49d/0x4bd
[ 282.094862] ? secondary_startup_64+0xa5/0xb0
[PASS]
# of passed: 1
# of failed: 0
# of unresolved: 0
# of untested: 0
# of unsupported: 0
# of xfailed: 0
# of undefined(test bug): 0
.config
Description: Binary data
