From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751528AbcFUMxb (ORCPT ); Tue, 21 Jun 2016 08:53:31 -0400 Received: from mail-lf0-f67.google.com ([209.85.215.67]:33406 "EHLO mail-lf0-f67.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750885AbcFUMx3 (ORCPT ); Tue, 21 Jun 2016 08:53:29 -0400 Date: Tue, 21 Jun 2016 14:53:24 +0200 (CEST) From: Enrico Mioso X-X-Sender: mrkiko@localhost.localdomain To: linux-kernel@vger.kernel.org cc: Ingo Molnar , Steven Rostedt , mattia.bonomi@studenti.unitn.it Subject: [ftrace] kernel panics during my attempt to use ftrace Message-ID: MIME-Version: 1.0 Content-Type: text/plain; format=flowed; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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: [] 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:[] 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] [] ? ftrace_return_to_handler+0x97/0x170 [ 825.340572] [] ? __schedule+0x305/0x790 [ 825.340572] [] ? yield_to+0x68/0x170 [ 825.340572] [] return_to_handler+0x9/0xf [ 825.340572] [] ? wake_atomic_t_function+0x70/0x70 [ 825.340572] [] ? force_qs_rnp+0x140/0x140 [ 825.340572] [] kthread+0xa6/0xc0 [ 825.340572] [] ret_from_kernel_thread+0x21/0x38 [ 825.340572] [] ? 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 06 1e 50 55 57 56 52 51 53 8b 44 24 34 89 44 24 38 c7 44 24 [ 825.340572] EIP: [] 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:[] 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] [] ? ftrace_return_to_handler+0x97/0x170 [ 826.000050] [] ? __schedule+0x305/0x790 [ 826.000050] [] ? schedule+0x4/0x80 [ 826.000050] [] return_to_handler+0x9/0xf [ 826.000050] [] ? __hrtimer_init+0x90/0x90 [ 826.000050] [] ? ftrace_graph_caller+0x19/0x19 [ 826.000050] [] schedule_hrtimeout_range+0x17/0x20 [ 826.000050] [] ftrace_graph_caller+0x19/0x19 [ 826.000050] [] poll_schedule_timeout+0x36/0x60 [ 826.000050] [] ftrace_graph_caller+0x19/0x19 [ 826.000050] [] do_sys_poll+0x4c8/0x570 [ 826.000050] [] ftrace_graph_caller+0x19/0x19 [ 826.000050] [] SyS_poll+0x5e/0x100 [ 826.000050] [] ? __alloc_pages_nodemask+0x128/0xa40 [ 826.000050] [] ? kmap_atomic_prot+0x36/0x100 [ 826.000050] [] ? poll_select_copy_remaining+0x130/0x130 [ 826.000050] [] ? poll_select_copy_remaining+0x130/0x130 [ 826.000050] [] ? kvm_clock_read+0x17/0x20 [ 826.000050] [] ? pvclock_clocksource_read+0xab/0x150 [ 826.000050] [] ? pvclock_clocksource_read+0xab/0x150 [ 826.000050] [] ? kvm_clock_read+0x17/0x20 [ 826.000050] [] ? pvclock_clocksource_read+0xab/0x150 [ 826.000050] [] ? kvm_clock_read+0x17/0x20 [ 826.000050] [] ? sched_clock+0x8/0x10 [ 826.000050] [] ? trace_clock_local+0x8/0x10 [ 826.000050] [] ? rb_reserve_next_event+0x75/0x430 [ 826.000050] [] ? ring_buffer_unlock_commit+0x22/0x240 [ 826.000050] [] ? __buffer_unlock_commit+0x10/0x20 [ 826.000050] [] ? __trace_graph_return+0x89/0xa0 [ 826.000050] [] ? SyS_poll+0x52/0x100 [ 826.000050] [] ? ftrace_return_to_handler+0x97/0x170 [ 826.000050] [] ? poll_select_set_timeout+0x8/0xa0 [ 826.000050] [] ftrace_graph_caller+0x19/0x19 [ 826.000050] [] do_fast_syscall_32+0x8d/0x150 [ 826.000050] [] ftrace_graph_caller+0x19/0x19 [ 826.000050] [] sysenter_past_esp+0x3d/0x61 [ 826.000050] [] 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 74 24 04 6a 00 0f a8 0f a0 06 1e 50 55 57 56 52 51 [ 826.000050] EIP: [] 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:[] 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] [] ? ftrace_return_to_handler+0x97/0x170 [ 826.652668] [] ? __schedule+0x305/0x790 [ 826.652668] [] ? schedule+0x4/0x80 [ 826.652668] [] return_to_handler+0x9/0xf [ 826.652668] [] ? process_one_work+0x3f0/0x3f0 [ 826.652668] [] kthread+0xa6/0xc0 [ 826.652668] [] ret_from_kernel_thread+0x21/0x38 [ 826.652668] [] ? 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 74 24 04 6a 00 0f a8 0f a0 06 1e 50 55 57 56 52 51 [ 826.652668] EIP: [] 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:[] 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] [] ? ftrace_return_to_handler+0x97/0x170 [ 827.045579] [] ? __schedule+0x305/0x790 [ 827.045579] [] ? schedule+0x4/0x80 [ 827.045579] [] return_to_handler+0x9/0xf [ 827.045579] [] ? process_one_work+0x3f0/0x3f0 [ 827.045579] [] kthread+0xa6/0xc0 [ 827.045579] [] ret_from_kernel_thread+0x21/0x38 [ 827.045579] [] ? 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 74 24 04 6a 00 0f a8 0f a0 06 1e 50 55 57 56 52 51 [ 827.045579] EIP: [] 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: [] 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:[] 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] [] ? ftrace_graph_caller+0x19/0x19 [ 827.860060] [] print_context_stack+0xc6/0xd0 [ 827.860060] [] ftrace_graph_caller+0x19/0x19 [ 827.860060] [] dump_trace+0xc5/0x1e0 [ 827.860060] [] ? prepare_ftrace_return+0x92/0xc0 [ 827.860060] [] ? schedule+0x4/0x80 [ 827.860060] [] schedule+0x2d/0x80 [ 827.860060] [] ftrace_graph_caller+0x19/0x19 [ 827.860060] [] show_trace_log_lvl+0x46/0x50 [ 827.860060] [] ? vprintk_default+0x41/0x60 [ 827.860060] [] ? printk+0x17/0x19 [ 827.860060] [] oops_end+0x92/0xd0 [ 827.860060] [] die+0x4e/0x70 [ 827.860060] [] do_trap+0x99/0xc0 [ 827.860060] [] do_error_trap+0x8a/0x120 [ 827.860060] [] ? ftrace_graph_call+0x2/0x2 [ 827.860060] [] ? ring_buffer_unlock_commit+0x22/0x240 [ 827.860060] [] ? __buffer_unlock_commit+0x10/0x20 [ 827.860060] [] ? __trace_graph_return+0x89/0xa0 [ 827.860060] [] ? worker_thread+0xb2/0x490 [ 827.860060] [] ? do_overflow+0x30/0x30 [ 827.860060] [] do_invalid_op+0x24/0x30 [ 827.860060] [] error_code+0x67/0x6c [ 827.860060] [] ? worker_thread+0xb2/0x490 [ 827.860060] [] ? assign_irq_vector+0x228/0x2c0 [ 827.860060] [] ? ftrace_graph_call+0x2/0x2 [ 827.860060] [] ? ftrace_return_to_handler+0x97/0x170 [ 827.860060] [] ? __schedule+0x305/0x790 [ 827.860060] [] ? schedule+0x4/0x80 [ 827.860060] [] return_to_handler+0x9/0xf [ 827.860060] [] ? process_one_work+0x3f0/0x3f0 [ 827.860060] [] kthread+0xa6/0xc0 [ 827.860060] [] ret_from_kernel_thread+0x21/0x38 [ 827.860060] [] ? 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: [] 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!