[ 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]
[ 45.588539] irq_enter+0xa/0x60
[ 45.589194] smp_call_function_interrupt+0xb/0x1e0
[ 45.590071] call_function_interrupt+0xf/0x20
[ 45.590850]
[ 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): [] __do_softirq+0x370/0x460
[ 45.621536] softirqs last disabled at (27545): [] 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]
[ 45.645471] smp_call_function_interrupt+0x49/0x1e0
[ 45.647632] call_function_interrupt+0xf/0x20
[ 45.648396]
[ 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): [] __do_softirq+0x370/0x460
[ 45.678233] softirqs last disabled at (27545): [] 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]
[ 45.702277] irq_exit+0x5c/0xd0
[ 45.702866] call_function_interrupt+0xf/0x20
[ 45.703605]
[ 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): [] __do_softirq+0x370/0x460
[ 45.735493] softirqs last disabled at (27545): [] 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]
[ 45.763525] __do_softirq+0x370/0x460
[ 45.764237] irq_exit+0xc1/0xd0
[ 45.764857] reschedule_interrupt+0xf/0x20
[ 45.765623]
[ 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 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): [] irq_enter+0x5d/0x60
[ 45.787824] softirqs last disabled at (5071117): [] irq_exit+0xc1/0xd0
[ 45.789209] ---[ end trace 574d547106ecd2db ]---
[ 45.790609] OK
[ 45.791162] Testing event system sched: OK