Linux 3.9.0 Ftrace function_graph not working

[Altera_Forum]

Hello,

I'm using Arria V SoC developpement board with HPS (2x Cortex A9) core.

I'm currently using the Linux Kernel 3.9.0 sources from RocketBoards.org .

I would like to use ftrace tool in order to profile the Kernel however i'm having some trouble using it.

Indeed ftrace tool is working for "function" tracer:

# tracer: function

#

# entries-in-buffer/entries-written: 132578/132578 #P:2

#

# _-----=> irqs-off

# / _----=> need-resched

# | / _---=> hardirq/softirq

# || / _--=> preempt-depth

# ||| / delay

# TASK-PID CPU# |||| TIMESTAMP FUNCTION

# | | | |||| | |

sh-685 [001] .... 467.461516: mutex_unlock <-rb_simple_write

sh-685 [001] .... 467.461526: sys_dup2 <-ret_fast_syscall

sh-685 [001] .... 467.461528: sys_dup3 <-sys_dup2

sh-685 [001] .... 467.461530: _raw_spin_lock <-sys_dup3

sh-685 [001] .... 467.461531: expand_files <-sys_dup3

sh-685 [001] .... 467.461533: do_dup2 <-sys_dup3

sh-685 [001] .... 467.461534: filp_close <-do_dup2

sh-685 [001] .... 467.461536: locks_remove_posix <-filp_close

sh-685 [001] .... 467.461538: fput <-filp_close

sh-685 [001] .... 467.461539: file_sb_list_del <-fput

sh-685 [001] .... 467.461541: lg_local_lock_cpu <-file_sb_lis

But when i want to use "function_graph" tracer Kernel stop running and report a kernel error:

root@socfpga:/sys/kernel/debug/tracing# echo function_graph > current_tracer

root@socfpga:/sys/kernel/debug/tracing# echo 1 > tracing_on

Unable to handle kernel NULL pointer dereference at virtual address 00000394

pgd = bf088000

[00000394] *pgd=3f229831Unable to handle kernel paging request at virtual address 1d45d9c0

pgd = 80004000

[1d45d9c0] *pgd=00000000

Internal error: Oops: 805 [#1] SMP ARM

Modules linked in:

CPU: 0 Not tainted (3.9.0-00161-ged01b8c #2)

PC is at ftrace_push_return_trace+0x7c/0x100

LR is at sched_clock+0x18/0x9c

pc : [<8009dab8>] lr : [<80011b14>] psr: 90000193

sp : bf8da0c8 ip : e1a0c00e fp : bf8da0fc

r10: 80011b14 r9 : bf8da104 r8 : 803763c4

r7 : 341801c0 r6 : bf8da000 r5 : 00000093 r4 : bbd5184a

r3 : 00000093 r2 : e92dd800 r1 : 00000093 r0 : 00000000

Flags: NzcV IRQs off FIQs on Mode SVC_32 ISA ARM Segment kernel

Control: 10c5387d Table: 3f23c04a DAC: 00000015

Process rcu_sched (pid: 10, stack limit = 0xbf8d8240)

Stack: (0xbf8da0c8 to 0xbf8da000)

[<8009dab8>] (ftrace_push_return_trace+0x7c/0x100) from [<800153c0>] (prepare_ftrace_return+0x8c/0xa0)

[<800153c0>] (prepare_ftrace_return+0x8c/0xa0) from [<8000e8f4>] (ftrace_graph_caller+0x18/0x20)

Code: e596200c e1a0728c e3a00000 e5922384 (e782a28c)

---[ end trace 8aef5c797f34b103 ]---

, *pte=00000000, *ppte=00000000

Internal error: Oops: 17 [#2] SMP ARM

Modules linked in:

CPU: 0 Tainted: G D (3.9.0-00161-ged01b8c #2)

PC is at prepare_ftrace_return+0x30/0xa0

LR is at ftrace_graph_caller+0x18/0x20

pc : [<80015364>] lr : [<8000e8f4>] psr: 200f0193

sp : bf1f6060 ip : 00000000 fp : bf1f608c

r10: 80011b14 r9 : bf20e25c r8 : bf1f6144

r7 : 8000e8fc r6 : 806469b8 r5 : 8001b578 r4 : bf1f6140

r3 : bf1f6000 r2 : bf1f6144 r1 : 8001b578 r0 : bf1f6140

Flags: nzCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment user

Control: 10c5387d Table: 3f05404a DAC: 00000015

Process getty (pid: 686, stack limit = 0xbf1f4240)

Stack: (0xbf1f6060 to 0xbf1f6000)

[<80015364>] (prepare_ftrace_return+0x30/0xa0) from [<8000e8f4>] (ftrace_graph_caller+0x18/0x20)

Code: e3c3303f e1a08002 e593c00c e59f7064 (e59c1394)

---[ end trace 8aef5c797f34b104 ]---

Unable to handle kernel paging request at virtual address 7ce7add0

pgd = 80004000

[7ce7add0] *pgd=00000000

Internal error: Oops: 5 [#3] SMP ARM

Modules linked in:

CPU: 0 Tainted: G D (3.9.0-00161-ged01b8c #2)

PC is at check_preempt_wakeup+0x40/0x218

LR is at check_preempt_curr+0x90/0x9c

pc : [<800582f0>] lr : [<80052308>] psr: 600f0193

sp : bf1f5990 ip : 80ecc600 fp : bf1f59d4

r10: 80639600 r9 : 80639600 r8 : bfbcc7b8

r7 : 80642d50 r6 : bfbd96b8 r5 : bfbd9680 r4 : bfbcc780

r3 : 80639600 r2 : 00000000 r1 : bf20e000 r0 : bf20e020

Flags: nZCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment user

Control: 10c5387d Table: 3f05404a DAC: 00000015

Process getty (pid: 686, stack limit = 0xbf1f4240)

Stack: (0xbf1f5990 to 0xbf1f6000)

5980: 80052288 00000000 8009318c becb62d8

59a0: bfbd9680 80ecc600 00000000 80460128 bfbcc780 80ecc600 00000000 00000000

59c0: 00893000 80639600 bf1f59f4 bf1f59d8 80052308 800582bc 00000000 becb62d8

59e0: bfbd9680 80ecc600 bf1f5a14 bf1f59f8 80052354 80052284 bfbd9680 80ecc600

5a00: 600f0193 bfbd9680 bf1f5a2c bf1f5a18 8005255c 80052320 80ecc600 bfbd9958

........ too long for the post........

5fe0: 00000000 7eb798c4 0000b387 76e841cc 40000010 80015364 200f0193 ffffffff

[<800582f0>] (check_preempt_wakeup+0x40/0x218) from [<80052308>] (check_preempt_curr+0x90/0x9c)

[<80052308>] (check_preempt_curr+0x90/0x9c) from [<80052354>] (ttwu_do_wakeup+0x40/0x124)

[<80052354>] (ttwu_do_wakeup+0x40/0x124) from [<8005255c>] (ttwu_do_activate.constprop.66+0x68/0x6c)

[<8005255c>] (ttwu_do_activate.constprop.66+0x68/0x6c) from [<80054710>] (try_to_wake_up+0x248/0x2d8)

[<80054710>] (try_to_wake_up+0x248/0x2d8) from [<800547bc>] (default_wake_function+0x1c/0x20)

[<800547bc>] (default_wake_function+0x1c/0x20) from [<80046580>] (autoremove_wake_function+0x1c/0x44)

[<80046580>] (autoremove_wake_function+0x1c/0x44) from [<8004e2c8>] (__wake_up_common+0x60/0xa0)

[<8004e2c8>] (__wake_up_common+0x60/0xa0) from [<8004f134>] (__wake_up+0x48/0x5c)

[<8004f134>] (__wake_up+0x48/0x5c) from [<80025b48>] (wake_up_klogd_work_func+0x50/0x74)

[<80025b48>] (wake_up_klogd_work_func+0x50/0x74) from [<800a6ee8>] (__irq_work_run+0x94/0xcc)

[<800a6ee8>] (__irq_work_run+0x94/0xcc) from [<800a6fc4>] (irq_work_run+0x34/0x3c)

[<800a6fc4>] (irq_work_run+0x34/0x3c) from [<80033758>] (update_process_times+0x64/0x74)

[<80033758>] (update_process_times+0x64/0x74) from [<800682a8>] (tick_sched_timer+0x78/0x200)

[<800682a8>] (tick_sched_timer+0x78/0x200) from [<80049198>] (__run_hrtimer+0x88/0x1b8)

[<80049198>] (__run_hrtimer+0x88/0x1b8) from [<80049bb4>] (hrtimer_interrupt+0x120/0x2d4)

[<80049bb4>] (hrtimer_interrupt+0x120/0x2d4) from [<80014f0c>] (twd_handler+0x3c/0x50)

[<80014f0c>] (twd_handler+0x3c/0x50) from [<80081f78>] (handle_percpu_devid_irq+0x84/0x120)

[<80081f78>] (handle_percpu_devid_irq+0x84/0x120) from [<8007e2c8>] (generic_handle_irq+0x30/0x40)

[<8007e2c8>] (generic_handle_irq+0x30/0x40) from [<8000f790>] (handle_IRQ+0x48/0xa4)

[<8000f790>] (handle_IRQ+0x48/0xa4) from [<80008560>] (gic_handle_irq+0x38/0x6c)

[<80008560>] (gic_handle_irq+0x38/0x6c) from [<8000e3c0>] (__irq_svc+0x40/0x50)

Exception stack(0xbf1f5cf0 to 0xbf1f5d38)

5ce0: 00017000 bf6e125c 00000007 0000001b

5d00: bf6e1244 bf094e70 bf6e1268 bf6e1244 bf1f5da8 806838c0 00000000 bf1f5d4c

5d20: 00000007 bf1f5d38 800da954 800da970 600f0113 ffffffff

[<8000e3c0>] (__irq_svc+0x40/0x50) from [<800da970>] (__remove_shared_vm_struct+0x94/0xb8)

[<800da970>] (__remove_shared_vm_struct+0x94/0xb8) from [<800dae34>] (unlink_file_vma+0x44/0x50)

[<800dae34>] (unlink_file_vma+0x44/0x50) from [<800d5540>] (free_pgtables+0x44/0xd8)

[<800d5540>] (free_pgtables+0x44/0xd8) from [<800dd5d8>] (exit_mmap+0xf0/0x1fc)

[<800dd5d8>] (exit_mmap+0xf0/0x1fc) from [<80020974>] (mmput+0x4c/0x100)

[<80020974>] (mmput+0x4c/0x100) from [<800287a4>] (do_exit+0x254/0x918)

[<800287a4>] (do_exit+0x254/0x918) from [<80013194>] (die+0x200/0x2c4)

[<80013194>] (die+0x200/0x2c4) from [<80455d64>] (__do_kernel_fault.part.9+0x64/0x84)

[<80455d64>] (__do_kernel_fault.part.9+0x64/0x84) from [<8001b840>] (do_page_fault+0x2dc/0x38c)

[<8001b840>] (do_page_fault+0x2dc/0x38c) from [<800083dc>] (do_DataAbort+0x44/0xac)

Code: e2848038 e59f91d4 e5910014 e1a03009 (e7970100)

---[ end trace 8aef5c797f34b105 ]---

Kernel panic - not syncing: Fatal exception in interrupt

SMP: failed to stop secondary CPUs

Any idea how to fix this problem ? Am i missing a special configuration in the kernel ?

Thanks