Re: [PATCH v12 00/16] tracing: Hist trigger snapshot and onchange additions
From: Namhyung Kim
Date: Wed Jan 16 2019 - 01:43:35 EST
Hi Tom,
On Tue, Jan 15, 2019 at 04:05:44PM -0600, Tom Zanussi wrote:
> From: Tom Zanussi <tom.zanussi@xxxxxxxxxxxxxxx>
>
> Hi,
>
> This is v12 of the hist trigger snapshot and onchange additions
> patchset.
>
> It addresses some comments from Namhyung regarding the 'tracing: Add
> alternative synthetic event trace action syntax' patch to remove
> parens and change the documentation to emphasize the trace() form of
> the synthetic event generation command.
I got below from the following test:
# echo 'hist:key=comm:p=prio:onchange($p).snapshot()' > \
events/sched/sched_waking/trigger
# echo 1 > snapshot
Thanks,
Namhyung
[ 2217.403818] BUG: sleeping function called from invalid context at arch/x86/mm/fault.c:1369
[ 2217.406394] in_atomic(): 0, irqs_disabled(): 1, pid: 65, name: sh
[ 2217.406394] 3 locks held by sh/65:
[ 2217.406394] #0: 000000006082fdb2 (sb_writers#5){.+.+}, at: vfs_write+0x109/0x130
[ 2217.406394] #1: 000000003e4def73 (trace_types_lock){+.+.}, at: tracing_snapshot_write+0x93/0x170
[ 2217.406394] #2: 0000000050fd4c4a (&mm->mmap_sem){++++}, at: __do_page_fault+0x19a/0x4e0
[ 2217.406394] irq event stamp: 173368
[ 2217.406394] hardirqs last enabled at (173367): [<ffffffff815369e9>] _raw_spin_unlock_irq+0x29/0x40
[ 2217.406394] hardirqs last disabled at (173368): [<ffffffff811079b2>] tracing_snapshot_write+0xf2/0x170
[ 2217.406394] softirqs last enabled at (173258): [<ffffffff81800288>] __do_softirq+0x288/0x47c
[ 2217.406394] softirqs last disabled at (173253): [<ffffffff8105a682>] irq_exit+0x62/0xa0
[ 2217.406394] CPU: 0 PID: 65 Comm: sh Not tainted 4.20.0-rc3+ #259
[ 2217.406394] Call Trace:
[ 2217.406394] dump_stack+0x67/0x90
[ 2217.406394] ___might_sleep.cold.5+0x9f/0xb1
[ 2217.406394] __do_page_fault+0x1b7/0x4e0
[ 2217.406394] page_fault+0x1e/0x30
[ 2217.406394] RIP: 0010:cond_snapshot_update+0x26/0xa0
[ 2217.406394] Code: ff ff 66 90 55 48 89 e5 41 55 41 54 53 48 8b 87 c8 16 00 00 48 8b 18 48 83 e4 f0 48 85 db 74 20 48 8b 43 50 49 89 f4 48 8b 3b <48> 8b 36 48 8b 80 e0 00 00 00 e8 1b 43 6e 00 41 89 c5 84 c0 75 11
[ 2217.406394] RSP: 0018:ffffc90000163dc0 EFLAGS: 00010082
[ 2217.406394] RAX: ffff88803dc07000 RBX: ffff88803df7b720 RCX: ffff88800008e408
[ 2217.406394] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000078
[ 2217.406394] RBP: ffffc90000163de0 R08: 0000000000000000 R09: 0000000000000001
[ 2217.406394] R10: ffffc90000163e18 R11: 0000000000000002 R12: 0000000000000000
[ 2217.406394] R13: 0000000000000000 R14: ffffc90000163f08 R15: 0000000000000000
[ 2217.406394] update_max_tr+0x82/0xe0
[ 2217.406394] tracing_snapshot_write+0x15c/0x170
[ 2217.406394] __vfs_write+0x36/0x180
[ 2217.406394] ? rcu_read_lock_sched_held+0x76/0x80
[ 2217.406394] ? rcu_sync_lockdep_assert+0x2e/0x60
[ 2217.406394] ? __sb_start_write+0x14c/0x1b0
[ 2217.406394] ? vfs_write+0x109/0x130
[ 2217.406394] vfs_write+0xb7/0x130
[ 2217.406394] ksys_write+0x52/0xc0
[ 2217.406394] do_syscall_64+0x50/0x180
[ 2217.406394] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 2217.406394] RIP: 0033:0x7f9bc3170818
[ 2217.406394] Code: 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 f3 0f 1e fa 48 8d 05 25 6d 0d 00 8b 00 85 c0 75 17 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 58 c3 0f 1f 80 00 00 00 00 41 54 49 89 d4 55
[ 2217.406394] RSP: 002b:00007ffdef643888 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 2217.406394] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f9bc3170818
[ 2217.406394] RDX: 0000000000000002 RSI: 00005651d6bf0db0 RDI: 0000000000000001
[ 2217.406394] RBP: 00005651d6bf0db0 R08: 000000000000000a R09: 00007ffdef643410
[ 2217.406394] R10: 000000000000000a R11: 0000000000000246 R12: 00007f9bc32435c0
[ 2217.406394] R13: 0000000000000002 R14: 00007f9bc323e5c0 R15: 0000000000000002
[ 2217.406394] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[ 2217.406394] PGD 0 P4D 0
[ 2217.406394] Oops: 0000 [#1] SMP PTI
[ 2217.406394] CPU: 0 PID: 65 Comm: sh Tainted: G W 4.20.0-rc3+ #259
[ 2217.406394] RIP: 0010:cond_snapshot_update+0x26/0xa0
[ 2217.406394] Code: ff ff 66 90 55 48 89 e5 41 55 41 54 53 48 8b 87 c8 16 00 00 48 8b 18 48 83 e4 f0 48 85 db 74 20 48 8b 43 50 49 89 f4 48 8b 3b <48> 8b 36 48 8b 80 e0 00 00 00 e8 1b 43 6e 00 41 89 c5 84 c0 75 11
[ 2217.406394] RSP: 0018:ffffc90000163dc0 EFLAGS: 00010082
[ 2217.406394] RAX: ffff88803dc07000 RBX: ffff88803df7b720 RCX: ffff88800008e408
[ 2217.406394] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000078
[ 2217.406394] RBP: ffffc90000163de0 R08: 0000000000000000 R09: 0000000000000001
[ 2217.406394] R10: ffffc90000163e18 R11: 0000000000000002 R12: 0000000000000000
[ 2217.406394] R13: 0000000000000000 R14: ffffc90000163f08 R15: 0000000000000000
[ 2217.406394] FS: 00007f9bc3013b80(0000) GS:ffff88803e400000(0000) knlGS:0000000000000000
[ 2217.406394] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2217.406394] CR2: 0000000000000000 CR3: 000000003d138001 CR4: 0000000000060eb0
[ 2217.406394] Call Trace:
[ 2217.406394] update_max_tr+0x82/0xe0
[ 2217.406394] tracing_snapshot_write+0x15c/0x170
[ 2217.406394] __vfs_write+0x36/0x180
[ 2217.406394] ? rcu_read_lock_sched_held+0x76/0x80
[ 2217.406394] ? rcu_sync_lockdep_assert+0x2e/0x60
[ 2217.406394] ? __sb_start_write+0x14c/0x1b0
[ 2217.406394] ? vfs_write+0x109/0x130
[ 2217.406394] vfs_write+0xb7/0x130
[ 2217.406394] ksys_write+0x52/0xc0
[ 2217.406394] do_syscall_64+0x50/0x180
[ 2217.406394] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 2217.406394] RIP: 0033:0x7f9bc3170818
[ 2217.406394] Code: 89 02 48 c7 c0 ff ff ff ff eb b3 0f 1f 80 00 00 00 00 f3 0f 1e fa 48 8d 05 25 6d 0d 00 8b 00 85 c0 75 17 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 58 c3 0f 1f 80 00 00 00 00 41 54 49 89 d4 55
[ 2217.406394] RSP: 002b:00007ffdef643888 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 2217.406394] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f9bc3170818
[ 2217.406394] RDX: 0000000000000002 RSI: 00005651d6bf0db0 RDI: 0000000000000001
[ 2217.406394] RBP: 00005651d6bf0db0 R08: 000000000000000a R09: 00007ffdef643410
[ 2217.406394] R10: 000000000000000a R11: 0000000000000246 R12: 00007f9bc32435c0
[ 2217.406394] R13: 0000000000000002 R14: 00007f9bc323e5c0 R15: 0000000000000002
[ 2217.406394] Modules linked in:
[ 2217.406394] CR2: 0000000000000000
[ 2217.406394] ---[ end trace 832915071760c624 ]---
[ 2217.406394] RIP: 0010:cond_snapshot_update+0x26/0xa0
[ 2217.406394] Code: ff ff 66 90 55 48 89 e5 41 55 41 54 53 48 8b 87 c8 16 00 00 48 8b 18 48 83 e4 f0 48 85 db 74 20 48 8b 43 50 49 89 f4 48 8b 3b <48> 8b 36 48 8b 80 e0 00 00 00 e8 1b 43 6e 00 41 89 c5 84 c0 75 11
[ 2217.406394] RSP: 0018:ffffc90000163dc0 EFLAGS: 00010082
[ 2217.406394] RAX: ffff88803dc07000 RBX: ffff88803df7b720 RCX: ffff88800008e408
[ 2217.406394] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000078
[ 2217.406394] RBP: ffffc90000163de0 R08: 0000000000000000 R09: 0000000000000001
[ 2217.406394] R10: ffffc90000163e18 R11: 0000000000000002 R12: 0000000000000000
[ 2217.406394] R13: 0000000000000000 R14: ffffc90000163f08 R15: 0000000000000000
[ 2217.406394] FS: 00007f9bc3013b80(0000) GS:ffff88803e400000(0000) knlGS:0000000000000000
[ 2217.406394] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2217.406394] CR2: 0000000000000000 CR3: 000000003d138001 CR4: 0000000000060eb0