LTTng » LTTng-modules

While tracing Varnish on a Linux kernel 4.11.0-rc3 and LTTng-modules as current as 0147ae6413de42a6f254a17793414c7f25e4f28a, I ran into a number BUG warnings in dmesg. While many contain processes related to the tracer or what was being traced, there was a number of processes unrelated to any tracing session, such as tar and a web browser.

[3111850.056164] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:115
[3111850.056168] in_atomic(): 1, irqs_disabled(): 0, pid: 27013, name: lttng-sessiond
[3111850.056170] no locks held by lttng-sessiond/27013.
[3111850.056174] CPU: 5 PID: 27013 Comm: lttng-sessiond Tainted: G        W  O    4.11.0-rc3 #1
[3111850.056176] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3111850.056178] Call Trace:
[3111850.056187]  dump_stack+0x4d/0x72
[3111850.056193]  ___might_sleep+0xd4/0x120
[3111850.056197]  __might_sleep+0x4a/0x80
[3111850.056203]  __might_fault+0x2e/0x30
[3111850.056242]  __event_probe__syscall_entry_accept+0x111/0x2b0 [lttng_tracer]
[3111850.056278]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3111850.056284]  syscall_trace_enter+0x2ce/0x300
[3111850.056303]  ? syscall_exit_probe+0x195/0x320 [lttng_tracer]
[3111850.056312]  do_syscall_64+0xa2/0xc0
[3111850.056317]  entry_SYSCALL64_slow_path+0x25/0x25
[3111850.056320] RIP: 0033:0x7f787cd4620d
[3111850.056322] RSP: 002b:00007f7878eee970 EFLAGS: 00000293 ORIG_RAX: 000000000000002b
[3111850.056326] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f787cd4620d
[3111850.056329] RDX: 00007f7878eee98c RSI: 00007f7878eee990 RDI: 0000000000000017
[3111850.056331] RBP: ffffffffffffffc8 R08: 0000000000000000 R09: 0000000000000000
[3111850.056333] R10: 00000000ffffffff R11: 0000000000000293 R12: 00000000ffffffff
[3111850.056335] R13: 0000000000001763 R14: 000000000000000c R15: 00007f78600a1b80

[3111851.056335] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:53
[3111851.056339] in_atomic(): 1, irqs_disabled(): 0, pid: 17308, name: fork12-ust
[3111851.056341] no locks held by fork12-ust/17308.
[3111851.056344] CPU: 5 PID: 17308 Comm: fork12-ust Tainted: G        W  O    4.11.0-rc3 #1
[3111851.056346] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3111851.056348] Call Trace:
[3111851.056357]  dump_stack+0x4d/0x72
[3111851.056362]  ___might_sleep+0xd4/0x120
[3111851.056367]  __might_sleep+0x4a/0x80
[3111851.056373]  __might_fault+0x2e/0x30
[3111851.056407]  __event_probe__syscall_entry_connect+0x3ca/0x5e0 [lttng_tracer]
[3111851.056411]  ? sched_clock_cpu+0x16/0xc0
[3111851.056414]  ? __handle_mm_fault+0x827/0xda0
[3111851.056419]  ? grab_cache_page_write_begin+0x31/0x40
[3111851.056429]  ? _raw_spin_unlock+0x27/0x40
[3111851.056433]  ? __handle_mm_fault+0x827/0xda0
[3111851.056436]  ? sched_clock_cpu+0x16/0xc0
[3111851.056438]  ? handle_mm_fault+0x95/0x2c0
[3111851.056442]  ? sched_clock_cpu+0x16/0xc0
[3111851.056445]  ? __do_page_fault+0x291/0x4e0
[3111851.056470]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3111851.056475]  syscall_trace_enter+0x2ce/0x300
[3111851.056478]  ? up_read+0x1f/0x40
[3111851.056482]  ? __do_page_fault+0x291/0x4e0
[3111851.056489]  do_syscall_64+0xa2/0xc0
[3111851.056493]  entry_SYSCALL64_slow_path+0x25/0x25
[3111851.056496] RIP: 0033:0x7f2d9c426e3d
[3111851.056498] RSP: 002b:00007f2d9b2410c0 EFLAGS: 00000297 ORIG_RAX: 000000000000002a
[3111851.056503] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2d9c426e3d
[3111851.056505] RDX: 000000000000006e RSI: 00007f2d9b2410e0 RDI: 0000000000000003
[3111851.056507] RBP: 00007f2d9b241450 R08: 000000000000000e R09: 0000000000000000
[3111851.056509] R10: 000000000000001d R11: 0000000000000297 R12: 00007f2d9bad99e4
[3111851.056511] R13: 00007f2d9bad99e4 R14: 00007f2d9bad99c0 R15: 00007f2d9b241b70

[3111851.056335] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:53
[3111851.056339] in_atomic(): 1, irqs_disabled(): 0, pid: 17308, name: fork12-ust
[3111851.056341] no locks held by fork12-ust/17308.
[3111851.056344] CPU: 5 PID: 17308 Comm: fork12-ust Tainted: G        W  O    4.11.0-rc3 #1
[3111851.056346] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3111851.056348] Call Trace:
[3111851.056357]  dump_stack+0x4d/0x72
[3111851.056362]  ___might_sleep+0xd4/0x120
[3111851.056367]  __might_sleep+0x4a/0x80
[3111851.056373]  __might_fault+0x2e/0x30
[3111851.056407]  __event_probe__syscall_entry_connect+0x3ca/0x5e0 [lttng_tracer]
[3111851.056411]  ? sched_clock_cpu+0x16/0xc0
[3111851.056414]  ? __handle_mm_fault+0x827/0xda0
[3111851.056419]  ? grab_cache_page_write_begin+0x31/0x40
[3111851.056429]  ? _raw_spin_unlock+0x27/0x40
[3111851.056433]  ? __handle_mm_fault+0x827/0xda0
[3111851.056436]  ? sched_clock_cpu+0x16/0xc0
[3111851.056438]  ? handle_mm_fault+0x95/0x2c0
[3111851.056442]  ? sched_clock_cpu+0x16/0xc0
[3111851.056445]  ? __do_page_fault+0x291/0x4e0
[3111851.056470]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3111851.056475]  syscall_trace_enter+0x2ce/0x300
[3111851.056478]  ? up_read+0x1f/0x40
[3111851.056482]  ? __do_page_fault+0x291/0x4e0
[3111851.056489]  do_syscall_64+0xa2/0xc0
[3111851.056493]  entry_SYSCALL64_slow_path+0x25/0x25
[3111851.056496] RIP: 0033:0x7f2d9c426e3d
[3111851.056498] RSP: 002b:00007f2d9b2410c0 EFLAGS: 00000297 ORIG_RAX: 000000000000002a
[3111851.056503] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2d9c426e3d
[3111851.056505] RDX: 000000000000006e RSI: 00007f2d9b2410e0 RDI: 0000000000000003
[3111851.056507] RBP: 00007f2d9b241450 R08: 000000000000000e R09: 0000000000000000
[3111851.056509] R10: 000000000000001d R11: 0000000000000297 R12: 00007f2d9bad99e4
[3111851.056511] R13: 00007f2d9bad99e4 R14: 00007f2d9bad99c0 R15: 00007f2d9b241b70

[3111854.166421] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:53
[3111854.166425] in_atomic(): 1, irqs_disabled(): 0, pid: 28917, name: fork12-ust
[3111854.166427] no locks held by fork12-ust/28917.
[3111854.166430] CPU: 3 PID: 28917 Comm: fork12-ust Tainted: G        W  O    4.11.0-rc3 #1
[3111854.166432] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3111854.166434] Call Trace:
[3111854.166443]  dump_stack+0x4d/0x72
[3111854.166448]  ___might_sleep+0xd4/0x120
[3111854.166453]  __might_sleep+0x4a/0x80
[3111854.166458]  __might_fault+0x2e/0x30
[3111854.166495]  __event_probe__syscall_entry_connect+0x3ca/0x5e0 [lttng_tracer]
[3111854.166502]  ? lttng_event_reserve+0xe1/0xaea [lttng_ring_buffer_client_discard]
[3111854.166526]  ? __event_probe__syscall_exit_fcntl+0x17c/0x220 [lttng_tracer]
[3111854.166530]  ? __lock_acquire.isra.34+0x1ec/0x890
[3111854.166559]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3111854.166565]  syscall_trace_enter+0x2ce/0x300
[3111854.166583]  ? syscall_exit_probe+0x1c4/0x320 [lttng_tracer]
[3111854.166588]  ? SyS_fcntl+0x67/0x660
[3111854.166595]  do_syscall_64+0xa2/0xc0
[3111854.166601]  entry_SYSCALL64_slow_path+0x25/0x25
[3111854.166604] RIP: 0033:0x7f2d9c426e3d
[3111854.166606] RSP: 002b:00007f2d9aa400c0 EFLAGS: 00000297 ORIG_RAX: 000000000000002a
[3111854.166610] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f2d9c426e3d
[3111854.166612] RDX: 000000000000006e RSI: 00007f2d9aa400e0 RDI: 0000000000000003
[3111854.166614] RBP: 00007f2d9aa40450 R08: 000000000000000e R09: 0000000000000000
[3111854.166616] R10: 000000000000001d R11: 0000000000000297 R12: 00007f2d9badba24
[3111854.166618] R13: 00007f2d9badba24 R14: 00007f2d9badba00 R15: 00007f2d9aa40b70

[3114898.742684] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:53
[3114898.742687] in_atomic(): 1, irqs_disabled(): 0, pid: 2830, name: varnishd-ust
[3114898.742689] no locks held by varnishd-ust/2830.
[3114898.742692] CPU: 7 PID: 2830 Comm: varnishd-ust Tainted: G        W  O    4.11.0-rc3 #1
[3114898.742693] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3114898.742695] Call Trace:
[3114898.742703]  dump_stack+0x4d/0x72
[3114898.742707]  ___might_sleep+0xd4/0x120
[3114898.742711]  __might_sleep+0x4a/0x80
[3114898.742715]  __might_fault+0x2e/0x30
[3114898.742747]  __event_probe__syscall_entry_connect+0x3ca/0x5e0 [lttng_tracer]
[3114898.742750]  ? sched_clock_cpu+0x16/0xc0
[3114898.742752]  ? __handle_mm_fault+0x827/0xda0
[3114898.742756]  ? grab_cache_page_write_begin+0x31/0x40
[3114898.742764]  ? _raw_spin_unlock+0x27/0x40
[3114898.742767]  ? __handle_mm_fault+0x827/0xda0
[3114898.742769]  ? sched_clock_cpu+0x16/0xc0
[3114898.742771]  ? handle_mm_fault+0x95/0x2c0
[3114898.742774]  ? sched_clock_cpu+0x16/0xc0
[3114898.742776]  ? __do_page_fault+0x291/0x4e0
[3114898.742796]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3114898.742800]  syscall_trace_enter+0x2ce/0x300
[3114898.742802]  ? up_read+0x1f/0x40
[3114898.742804]  ? __do_page_fault+0x291/0x4e0
[3114898.742809]  do_syscall_64+0xa2/0xc0
[3114898.742813]  entry_SYSCALL64_slow_path+0x25/0x25
[3114898.742815] RIP: 0033:0x7f204450326d
[3114898.742817] RSP: 002b:00007f20423fd080 EFLAGS: 00000297 ORIG_RAX: 000000000000002a
[3114898.742820] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f204450326d
[3114898.742821] RDX: 000000000000006e RSI: 00007f20423fd0a0 RDI: 0000000000000003
[3114898.742823] RBP: 00007f20423fd410 R08: 000000000000000e R09: 0000000000000000
[3114898.742824] R10: 0000000000000017 R11: 0000000000000297 R12: 00007f2043d099e4
[3114898.742826] R13: 00007f2043d099e4 R14: 00007f2043d099c0 R15: 00007f20423fdb30

[3117439.929019] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:53
[3117439.929024] in_atomic(): 1, irqs_disabled(): 0, pid: 32363, name: Chrome_IOThread
[3117439.929027] no locks held by Chrome_IOThread/32363.
[3117439.929032] CPU: 3 PID: 32363 Comm: Chrome_IOThread Tainted: G        W  O    4.11.0-rc3 #1
[3117439.929035] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3117439.929037] Call Trace:
[3117439.929049]  dump_stack+0x4d/0x72
[3117439.929055]  ___might_sleep+0xd4/0x120
[3117439.929062]  __might_sleep+0x4a/0x80
[3117439.929068]  __might_fault+0x2e/0x30
[3117439.929108]  __event_probe__syscall_entry_connect+0x3ca/0x5e0 [lttng_tracer]
[3117439.929116]  ? lttng_event_reserve+0xe1/0xaea [lttng_ring_buffer_client_discard]
[3117439.929149]  ? __event_probe__syscall_exit_fcntl+0x17c/0x220 [lttng_tracer]
[3117439.929189]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3117439.929196]  syscall_trace_enter+0x2ce/0x300
[3117439.929223]  ? syscall_exit_probe+0x1c4/0x320 [lttng_tracer]
[3117439.929229]  ? SyS_fcntl+0x67/0x660
[3117439.929239]  do_syscall_64+0xa2/0xc0
[3117439.929246]  entry_SYSCALL64_slow_path+0x25/0x25
[3117439.929249] RIP: 0033:0x7ff66a06926d
[3117439.929252] RSP: 002b:00007ff65471fba0 EFLAGS: 00000293 ORIG_RAX: 000000000000002a
[3117439.929258] RAX: ffffffffffffffda RBX: 00000000ffffff94 RCX: 00007ff66a06926d
[3117439.929261] RDX: 000000000000001c RSI: 00007ff65471fbc0 RDI: 000000000000009d
[3117439.929264] RBP: 00001f450e79a360 R08: 00007ff65471fc88 R09: 00001f4514b4ca78
[3117439.929267] R10: 0000161be1694dae R11: 0000000000000293 R12: 00007ff65471fc88
[3117439.929269] R13: 00001f4514b4ca78 R14: 00001f450e79a370 R15: 00007ff65471fd10

[3117458.958511] BUG: sleeping function called from invalid context at /home/rnsanchez/apps/lttng/lttng-modules/instrumentation/syscalls/headers/x86-64-syscalls-3.10.0-rc7_pointers_override.h:53
[3117458.958515] in_atomic(): 1, irqs_disabled(): 0, pid: 17665, name: tar
[3117458.958518] no locks held by tar/17665.
[3117458.958522] CPU: 3 PID: 17665 Comm: tar Tainted: G        W  O    4.11.0-rc3 #1
[3117458.958524] Hardware name:                  /DH67BL, BIOS BLH6710H.86A.0105.2011.0301.1654 03/01/2011
[3117458.958527] Call Trace:
[3117458.958538]  dump_stack+0x4d/0x72
[3117458.958544]  ___might_sleep+0xd4/0x120
[3117458.958549]  __might_sleep+0x4a/0x80
[3117458.958555]  __might_fault+0x2e/0x30
[3117458.958591]  __event_probe__syscall_entry_connect+0x3ca/0x5e0 [lttng_tracer]
[3117458.958596]  ? sched_clock_cpu+0x16/0xc0
[3117458.958631]  ? __event_probe__syscall_exit_socket+0x15c/0x200 [lttng_tracer]
[3117458.958666]  syscall_entry_probe+0x1b1/0x310 [lttng_tracer]
[3117458.958673]  syscall_trace_enter+0x2ce/0x300
[3117458.958696]  ? syscall_exit_probe+0x1c4/0x320 [lttng_tracer]
[3117458.958701]  ? fd_install+0x25/0x30
[3117458.958705]  ? sock_map_fd+0x44/0x70
[3117458.958714]  do_syscall_64+0xa2/0xc0
[3117458.958720]  entry_SYSCALL64_slow_path+0x25/0x25
[3117458.958724] RIP: 0033:0x7f1994f67e20
[3117458.958726] RSP: 002b:00007ffdfb051988 EFLAGS: 00000246 ORIG_RAX: 000000000000002a
[3117458.958731] RAX: ffffffffffffffda RBX: 00007ffdfb051990 RCX: 00007f1994f67e20
[3117458.958734] RDX: 000000000000006e RSI: 00007ffdfb051a00 RDI: 0000000000000005
[3117458.958736] RBP: 00007ffdfb051aa0 R08: 0000000000000001 R09: 0000000000000000
[3117458.958738] R10: 0000000000000006 R11: 0000000000000246 R12: 0000000000000005
[3117458.958741] R13: 0000000000000013 R14: 0000000000000007 R15: 000000000000000b