[ftrace] kernel panics during my attempt to use ftrace
From: Enrico Mioso
Date: Tue Jun 21 2016 - 08:53:34 EST
Hello guys.
First of all - thank you for your great work in ftrace, and in general in the
Linux tracing infrastructure. I am a newbie: so I am not able to use it at it's
full power, still I find it's capabilities impressive.
I am asking for help, since I am encountering some problems in using ftrace.
I am trying to come up with a solution to trace a specific workload (a
program): to understand what are the functions the kernel spends most of his
time in.
To do so, I inspired myself to some code I found around (I can mention it if
needed). I took free inspiration: so my editing may be very very wrong.
When I run this script, the kernel panics. the output is below. the kernel is
Ubuntu 16.04 stock, running in a qemu virtual machine (using kvm).
Any help would be greatly apreciated. Thank you very much guys.
Fort any needed infos, contact me.
Enrico
Script:
#!/bin/sh
if [ `whoami` != root ]
then
echo you need to run this script as root
exit 1
fi
tdir=/sys/kernel/debug/tracing
start()
{
# echo 50000 > $tdir/buffer_size_kb
echo function_graph > $tdir/current_tracer
echo 1000 >$tdir/tracing_thresh
echo >$tdir/trace
echo 1 >$tdir/tracing_on # ** this is wrong, interface changed?
}
stop()
{
echo >set_event
echo 0 >$tdir/tracing_on
output=trace`date +%y-%m-%d-%H-%M-%S`.txt
echo funcgraph-abstime >$tdir/trace_options
echo funcgraph-proc >$tdir/trace_options
cat $tdir/trace > $output
echo trace written to $output
}
COMMAND="$1"
case $COMMAND in
start|stop)
$COMMAND
;;
*)
echo "usage: $0 [start|stop]"
;;
esac
Kernel panic output:
[ 825.336708] BUG: unable to handle kernel paging request at 55501e06
[ 825.340572] IP: [<c17aa9ca>] ftrace_regs_caller+0xa/0x35
[ 825.340572] *pdpt = 000000001ef4c001 *pde = 0000000000000000
[ 825.340572] Oops: 0000 [#1] SMP
[ 825.340572] Modules linked in: isofs ppdev joydev serio_raw parport_pc parpor
t ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tc
p libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov a
sync_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multi
path linear psmouse e1000 floppy
[ 825.340572] CPU: 0 PID: 7 Comm: rcu_sched Not tainted 4.4.0-24-generic #43-Ub
untu
[ 825.340572] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.2
-20160422_131301-anatol 04/01/2014
[ 825.340572] task: de8f3480 ti: de988000 task.ti: de988000
[ 825.340572] EIP: 0060:[<c17aa9ca>] EFLAGS: 00010202 CPU: 0
[ 825.340572] EIP is at ftrace_regs_caller+0xa/0x35
[ 825.340572] EAX: de989e4e EBX: c10db072 ECX: 00000000 EDX: 00000268
[ 825.340572] ESI: de8f3480 EDI: dee08800 EBP: de989f10 ESP: de989ec4
[ 825.340572] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 825.340572] CR0: 8005003b CR2: 55501e06 CR3: 1e073e20 CR4: 000006e0
[ 825.340572] Stack:
[ 825.340572] c113f017 de8f3480 d4d1dc00 de989f0c c17a5b75 de9d4ec0 de989f60 d
e989f60
[ 825.340572] c17a60e8 edf05431 00000268 f2ee631c 00000268 00000000 00000000 8
aced3dc
[ 825.340572] c1ae0490 00000000 c1ae0300 de989f60 c17aaa46 dffbbdc0 00000000 0
0000000
[ 825.340572] Call Trace:
[ 825.340572] [<c113f017>] ? ftrace_return_to_handler+0x97/0x170
[ 825.340572] [<c17a5b75>] ? __schedule+0x305/0x790
[ 825.340572] [<c17a60e8>] ? yield_to+0x68/0x170
[ 825.340572] [<c17aaa46>] return_to_handler+0x9/0xf
[ 825.340572] [<c10afbd0>] ? wake_atomic_t_function+0x70/0x70
[ 825.340572] [<c10d5800>] ? force_qs_rnp+0x140/0x140
[ 825.340572] [<c108ce06>] kthread+0xa6/0xc0
[ 825.340572] [<c17a9949>] ret_from_kernel_thread+0x21/0x38
[ 825.340572] [<c108cd60>] ? kthread_create_on_node+0x170/0x170
[ 825.340572] Code: 6a 00 8b 44 24 10 8b 55 04 8b 0d 94 14 b7 c1 83 e8 05 e8 08
00 00 00 83 c4 04 5a 59 58 e9 63 00 00 00 ff 74 24 04 6a 00 0f a8 0f <a0> 06 1e
50 55 57 56 52 51 53 8b 44 24 34 89 44 24 38 c7 44 24
[ 825.340572] EIP: [<c17aa9ca>] ftrace_regs_caller+0xa/0x35 SS:ESP 0068:de989ec
4
[ 825.340572] CR2: 0000000055501e06
[ 825.340572] ---[ end trace 4f291f60e8d43d37 ]---
[ 825.996200] invalid opcode: 0000 [#2] SMP
[ 826.000050] Modules linked in: isofs ppdev joydev serio_raw parport_pc parpor
t ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tc
p libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov a
sync_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multi
path linear psmouse e1000 floppy
[ 826.000050] CPU: 0 PID: 1044 Comm: iscsid Tainted: G D 4.4.0-24-
generic #43-Ubuntu
[ 826.000050] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.2
-20160422_131301-anatol 04/01/2014
[ 826.000050] task: d4679180 ti: dee54000 task.ti: dee54000
[ 826.000050] EIP: 0060:[<c17aa9be>] EFLAGS: 00010217 CPU: 0
[ 826.000050] EIP is at ftrace_stub+0x0/0x2
[ 826.000050] EAX: dee55adc EBX: c17a8d92 ECX: 00000000 EDX: 00000269
[ 826.000050] ESI: d4679180 EDI: de0e9800 EBP: dee55b08 ESP: dee55abc
[ 826.000050] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 826.000050] CR0: 8005003b CR2: b7362010 CR3: 1f0d3080 CR4: 000006e0
[ 826.000050] Stack:
[ 826.000050] c113f017 d4679180 de29f400 dee55b04 c17a5b75 d4fe2300 dee55b88 d
ee55b88
[ 826.000050] c17a6004 edebaa8f 00000268 1a3d53a3 00000269 00000000 00000006 9
7ca1d76
[ 826.000050] dee55b34 0003d083 000000c0 dee55b88 c17aaa46 dffbbdc0 00000000 0
003d083
[ 826.000050] Call Trace:
[ 826.000050] [<c113f017>] ? ftrace_return_to_handler+0x97/0x170
[ 826.000050] [<c17a5b75>] ? __schedule+0x305/0x790
[ 826.000050] [<c17a6004>] ? schedule+0x4/0x80
[ 826.000050] [<c17aaa46>] return_to_handler+0x9/0xf
[ 826.000050] [<c10dc330>] ? __hrtimer_init+0x90/0x90
[ 826.000050] [<c17aaa3d>] ? ftrace_graph_caller+0x19/0x19
[ 826.000050] [<c17a8eb7>] schedule_hrtimeout_range+0x17/0x20
[ 826.000050] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 826.000050] [<c11efca6>] poll_schedule_timeout+0x36/0x60
[ 826.000050] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 826.000050] [<c11f13d8>] do_sys_poll+0x4c8/0x570
[ 826.000050] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 826.000050] [<c11f154e>] SyS_poll+0x5e/0x100
[ 826.000050] [<c1179368>] ? __alloc_pages_nodemask+0x128/0xa40
[ 826.000050] [<c1067736>] ? kmap_atomic_prot+0x36/0x100
[ 826.000050] [<c11efe00>] ? poll_select_copy_remaining+0x130/0x130
[ 826.000050] [<c11efe00>] ? poll_select_copy_remaining+0x130/0x130
[ 826.000050] [<c105bb07>] ? kvm_clock_read+0x17/0x20
[ 826.000050] [<c105cadb>] ? pvclock_clocksource_read+0xab/0x150
[ 826.000050] [<c105cadb>] ? pvclock_clocksource_read+0xab/0x150
[ 826.000050] [<c105bb07>] ? kvm_clock_read+0x17/0x20
[ 826.000050] [<c105cadb>] ? pvclock_clocksource_read+0xab/0x150
[ 826.000050] [<c105bb07>] ? kvm_clock_read+0x17/0x20
[ 826.000050] [<c1032918>] ? sched_clock+0x8/0x10
[ 826.000050] [<c11267a8>] ? trace_clock_local+0x8/0x10
[ 826.000050] [<c112de75>] ? rb_reserve_next_event+0x75/0x430
[ 826.000050] [<c112efc2>] ? ring_buffer_unlock_commit+0x22/0x240
[ 826.000050] [<c1135760>] ? __buffer_unlock_commit+0x10/0x20
[ 826.000050] [<c113f409>] ? __trace_graph_return+0x89/0xa0
[ 826.000050] [<c11f1542>] ? SyS_poll+0x52/0x100
[ 826.000050] [<c113f017>] ? ftrace_return_to_handler+0x97/0x170
[ 826.000050] [<c11effb8>] ? poll_select_set_timeout+0x8/0xa0
[ 826.000050] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 826.000050] [<c100393d>] do_fast_syscall_32+0x8d/0x150
[ 826.000050] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 826.000050] [<c17a99dc>] sysenter_past_esp+0x3d/0x61
[ 826.000050] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 826.000050] Code: ff ff 8d 76 00 c3 8d 76 00 50 51 52 6a 00 8b 44 24 10 8b 55
04 8b 0d 94 14 b7 c1 83 e8 05 e8 08 00 00 00 83 c4 04 5a 59 58 e9 fd <ff> ff ff
ff 74 24 04 6a 00 0f a8 0f a0 06 1e 50 55 57 56 52 51
[ 826.000050] EIP: [<c17aa9be>] ftrace_stub+0x0/0x2 SS:ESP 0068:dee55abc
[ 826.640678] ---[ end trace 4f291f60e8d43d38 ]---
[ 826.649117] invalid opcode: 0000 [#3] SMP
[ 826.652668] Modules linked in: isofs ppdev joydev serio_raw parport_pc parpor
t ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tc
p libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov a
sync_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multi
path linear psmouse e1000 floppy
[ 826.652668] CPU: 0 PID: 4 Comm: kworker/0:0 Tainted: G D 4.4.0-2
4-generic #43-Ubuntu
[ 826.652668] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.2
-20160422_131301-anatol 04/01/2014
[ 826.652668] task: de8f1a40 ti: de8fe000 task.ti: de8fe000
[ 826.652668] EIP: 0060:[<c17aa9be>] EFLAGS: 00010246 CPU: 0
[ 826.652668] EIP is at ftrace_stub+0x0/0x2
[ 826.652668] EAX: de8fff00 EBX: c10879d2 ECX: 00000000 EDX: 00000269
[ 826.652668] ESI: de8f1a40 EDI: de167800 EBP: de8fff2c ESP: de8ffee0
[ 826.652668] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 826.652668] CR0: 8005003b CR2: 00000068 CR3: 1f0d3080 CR4: 000006e0
[ 826.652668] Stack:
[ 826.652668] c113f017 de8f1a40 deb1a600 de8fff28 c17a5b75 d467e040 de8fff60 d
e8fff60
[ 826.652668] c17a6004 edd8153d 00000268 41282712 00000269 00000000 00000000 b
4d9c50e
[ 826.652668] dffbb8c0 de821a98 de821a80 de8fff60 c17aaa46 dffbbdc0 00000000 d
ffbba54
[ 826.652668] Call Trace:
[ 826.652668] [<c113f017>] ? ftrace_return_to_handler+0x97/0x170
[ 826.652668] [<c17a5b75>] ? __schedule+0x305/0x790
[ 826.652668] [<c17a6004>] ? schedule+0x4/0x80
[ 826.652668] [<c17aaa46>] return_to_handler+0x9/0xf
[ 826.652668] [<c1087920>] ? process_one_work+0x3f0/0x3f0
[ 826.652668] [<c108ce06>] kthread+0xa6/0xc0
[ 826.652668] [<c17a9949>] ret_from_kernel_thread+0x21/0x38
[ 826.652668] [<c108cd60>] ? kthread_create_on_node+0x170/0x170
[ 826.652668] Code: ff ff 8d 76 00 c3 8d 76 00 50 51 52 6a 00 8b 44 24 10 8b 55
04 8b 0d 94 14 b7 c1 83 e8 05 e8 08 00 00 00 83 c4 04 5a 59 58 e9 fd <ff> ff ff
ff 74 24 04 6a 00 0f a8 0f a0 06 1e 50 55 57 56 52 51
[ 826.652668] EIP: [<c17aa9be>] ftrace_stub+0x0/0x2 SS:ESP 0068:de8ffee0
[ 827.033592] ---[ end trace 4f291f60e8d43d39 ]---
[ 827.041794] invalid opcode: 0000 [#4] SMP
[ 827.045579] Modules linked in: isofs ppdev joydev serio_raw parport_pc parpor
t ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tc
p libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov a
sync_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multi
path linear psmouse e1000 floppy
[ 827.045579] CPU: 0 PID: 76 Comm: kworker/u2:3 Tainted: G D 4.4.0
-24-generic #43-Ubuntu
[ 827.045579] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.2
-20160422_131301-anatol 04/01/2014
[ 827.045579] task: d4fe2300 ti: d4ff0000 task.ti: d4ff0000
[ 827.045579] EIP: 0060:[<c17aa9be>] EFLAGS: 00010246 CPU: 0
[ 827.045579] EIP is at ftrace_stub+0x0/0x2
[ 827.045579] EAX: d4ff1f00 EBX: c10879d2 ECX: 00000000 EDX: 00000269
[ 827.045579] ESI: d4fe2300 EDI: de04a000 EBP: d4ff1f2c ESP: d4ff1ee0
[ 827.045579] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 827.045579] CR0: 8005003b CR2: 00000068 CR3: 1f0d3080 CR4: 000006e0
[ 827.045579] Stack:
[ 827.045579] c113f017 d4fe2300 deb1a600 d4ff1f28 c17a5b75 de8f3480 d4ff1f60 d
4ff1f60
[ 827.045579] c17a6004 edee6883 00000268 588ffd18 00000269 00000000 00000000 9
f590057
[ 827.045579] de8a5c00 d4f91b58 d4f91b40 d4ff1f60 c17aaa46 dffbbdc0 00000000 d
e8a5d94
[ 827.045579] Call Trace:
[ 827.045579] [<c113f017>] ? ftrace_return_to_handler+0x97/0x170
[ 827.045579] [<c17a5b75>] ? __schedule+0x305/0x790
[ 827.045579] [<c17a6004>] ? schedule+0x4/0x80
[ 827.045579] [<c17aaa46>] return_to_handler+0x9/0xf
[ 827.045579] [<c1087920>] ? process_one_work+0x3f0/0x3f0
[ 827.045579] [<c108ce06>] kthread+0xa6/0xc0
[ 827.045579] [<c17a9949>] ret_from_kernel_thread+0x21/0x38
[ 827.045579] [<c108cd60>] ? kthread_create_on_node+0x170/0x170
[ 827.045579] Code: ff ff 8d 76 00 c3 8d 76 00 50 51 52 6a 00 8b 44 24 10 8b 55
04 8b 0d 94 14 b7 c1 83 e8 05 e8 08 00 00 00 83 c4 04 5a 59 58 e9 fd <ff> ff ff
ff 74 24 04 6a 00 0f a8 0f a0 06 1e 50 55 57 56 52 51
[ 827.045579] EIP: [<c17aa9be>] ftrace_stub+0x0/0x2 SS:ESP 0068:d4ff1ee0
[ 827.426561] ---[ end trace 4f291f60e8d43d3a ]---
[ 827.856521] BUG: unable to handle kernel paging request at ffffffec
[ 827.860060] IP: [<c108d3bf>] kthread_data+0xf/0x20
[ 827.860060] *pdpt = 0000000001c6b001 *pde = 0000000001c6c063 *pte = 000000000
0000000
[ 827.860060] Oops: 0000 [#5] SMP
[ 827.860060] Modules linked in: isofs ppdev joydev serio_raw parport_pc parpor
t ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tc
p libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov a
sync_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multi
path linear psmouse e1000 floppy
[ 827.860060] CPU: 0 PID: 76 Comm: kworker/u2:3 Tainted: G D 4.4.0
-24-generic #43-Ubuntu
[ 827.860060] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.2
-20160422_131301-anatol 04/01/2014
[ 827.860060] task: d4fe2300 ti: d4ff0000 task.ti: d4ff0000
[ 827.860060] EIP: 0060:[<c108d3bf>] EFLAGS: 00010086 CPU: 0
[ 827.860060] EIP is at kthread_data+0xf/0x20
[ 827.860060] EAX: 00000000 EBX: 00000000 ECX: c17a5944 EDX: 00000000
[ 827.860060] ESI: c1c62dc0 EDI: dffbbdc0 EBP: d4ff1d08 ESP: d4ff1d00
[ 827.860060] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 827.860060] CR0: 8005003b CR2: 00000014 CR3: 1ee9a040 CR4: 000006e0
[ 827.860060] Stack:
[ 827.860060] c17aaa3d d4fe2300 d4ff1d44 c17aaa3d c10546d2 d4ff1d9c d4ff1d9c c
17a6004
[ 827.860060] 00000000 9f590057 00000000 d4ff1d84 dffbbdc0 d4fe2300 d4ff2000 d
4ff1d84
[ 827.860060] d4fe2300 d4ff1d50 c17a602d d4ff1a4c d4ff1d9c c17aaa3d d4ff1d78 c
10c7ca1
[ 827.860060] Call Trace:
[ 827.860060] [<c17aaa3d>] ? ftrace_graph_caller+0x19/0x19
[ 827.860060] [<c102cea6>] print_context_stack+0xc6/0xd0
[ 827.860060] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 827.860060] [<c102c445>] dump_trace+0xc5/0x1e0
[ 827.860060] [<c10546d2>] ? prepare_ftrace_return+0x92/0xc0
[ 827.860060] [<c17a6004>] ? schedule+0x4/0x80
[ 827.860060] [<c17a602d>] schedule+0x2d/0x80
[ 827.860060] [<c17aaa3d>] ftrace_graph_caller+0x19/0x19
[ 827.860060] [<c102cfe6>] show_trace_log_lvl+0x46/0x50
[ 827.860060] [<c10c7ca1>] ? vprintk_default+0x41/0x60
[ 827.860060] [<c116fb07>] ? printk+0x17/0x19
[ 827.860060] [<c102cc42>] oops_end+0x92/0xd0
[ 827.860060] [<c102d10e>] die+0x4e/0x70
[ 827.860060] [<c102a269>] do_trap+0x99/0xc0
[ 827.860060] [<c102a58a>] do_error_trap+0x8a/0x120
[ 827.860060] [<c17aa9be>] ? ftrace_graph_call+0x2/0x2
[ 827.860060] [<c112efc2>] ? ring_buffer_unlock_commit+0x22/0x240
[ 827.860060] [<c1135760>] ? __buffer_unlock_commit+0x10/0x20
[ 827.860060] [<c113f409>] ? __trace_graph_return+0x89/0xa0
[ 827.860060] [<c10879d2>] ? worker_thread+0xb2/0x490
[ 827.860060] [<c102abb0>] ? do_overflow+0x30/0x30
[ 827.860060] [<c102abd4>] do_invalid_op+0x24/0x30
[ 827.860060] [<c17aaac7>] error_code+0x67/0x6c
[ 827.860060] [<c10879d2>] ? worker_thread+0xb2/0x490
[ 827.860060] [<c10500d8>] ? assign_irq_vector+0x228/0x2c0
[ 827.860060] [<c17aa9be>] ? ftrace_graph_call+0x2/0x2
[ 827.860060] [<c113f017>] ? ftrace_return_to_handler+0x97/0x170
[ 827.860060] [<c17a5b75>] ? __schedule+0x305/0x790
[ 827.860060] [<c17a6004>] ? schedule+0x4/0x80
[ 827.860060] [<c17aaa46>] return_to_handler+0x9/0xf
[ 827.860060] [<c1087920>] ? process_one_work+0x3f0/0x3f0
[ 827.860060] [<c108ce06>] kthread+0xa6/0xc0
[ 827.860060] [<c17a9949>] ret_from_kernel_thread+0x21/0x38
[ 827.860060] [<c108cd60>] ? kthread_create_on_node+0x170/0x170
[ 827.860060] Code: 00 00 00 00 ba 46 02 00 00 b8 04 6c 9b c1 e8 19 30 fe ff e9
df fe ff ff 8d 74 26 00 55 89 e5 e8 6c d6 71 00 8b 80 74 03 00 00 5d <8b> 40 ec
c3 8d b6 00 00 00 00 8d bc 27 00 00 00 00 55 89 e5 83
[ 827.860060] EIP: [<c108d3bf>] kthread_data+0xf/0x20 SS:ESP 0068:d4ff1d00
[ 827.860060] CR2: 00000000ffffffec
[ 827.860060] ---[ end trace 4f291f60e8d43d3b ]---
[ 827.860060] Fixing recursive fault but reboot is needed!