Re: [PATCH v12 0/3] tracing: Centralize preemptirq tracepoints and unify their usage
From: Masami Hiramatsu
Date: Thu Aug 02 2018 - 12:04:48 EST
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 <joel@xxxxxxxxxxxxxxxxx> wrote:
> From: "Joel Fernandes (Google)" <joel@xxxxxxxxxxxxxxxxx>
>
> 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 <mhiramat@xxxxxxxxxx>
[ 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
Attachment:
.config
Description: Binary data