lkml.org 
[lkml]   [2020]   [May]   [11]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: ftrace: function radeon_init not traceable
On Sat, 9 May 2020 12:16:30 +0200
Paul Menzel <pmenzel@molgen.mpg.de> wrote:

> Dear Linux folks,
>
>
> Linux master and Linux 5.6.7 (from Debian Sid/unstable) are used.
>
> Instrumenting Linux’ start-up time, I’d like to trace the init function
> of the Radeon graphics driver `radeon_init()` (built as a module).
>
> drivers/gpu/drm/radeon/radeon_drv.c:static int __init radeon_init(void)
> drivers/gpu/drm/radeon/radeon_drv.c:module_init(radeon_init);
>
> With `initcall_debug` I can see:
>
> [ 1.079920] calling radeon_init+0x0/0x1000 [radeon] @ 138
> [ 1.663200] initcall radeon_init+0x0/0x1000 [radeon] returned 0
> after 129346 usecs
>
> With `function_graph` as the trace, I am adding the string below to the
> Linux kernel CLI.
>
> initcall_debug log_buf_len=32M trace_buf_size=57074K
> trace_clock=global
> trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,funcgraph-duration,funcgraph-proc,funcgraph-tail,nofuncgraph-overhead,context-info,graph-time
> ftrace=function_graph ftrace_graph_max_depth=1
> ftrace_graph_filter=radeon_init
>
> But ftrace “rejects” that:
>
> [ 0.075538] ftrace: allocating 30958 entries in 61 pages
> [ 0.084542] ftrace: allocated 61 pages with 5 groups
> [ 0.094184] ftrace: function radeon_init not traceable
>
> I believe it worked in the past. Is there a way to trace that init function?

Did it every work for modules? radeon_init() isn't in the symbol table at
boot up.

[ 15.066951] systemd-journald[124]: Successfully sent stream file descriptor to service manager.
[ 15.098265] hub 1-0:1.0: USB hub found
[ 15.104006] systemd-journald[124]: Successfully sent stream file descriptor to service manager.
[ 15.112965] hub 1-0:1.0: 2 ports detected
[ 15.118116] probe of 1-0:1.0 returned 1 after 19873 usecs
[ 15.124007] calling radeon_init+0x0/0x1000 [radeon] @ 133


The radeon_init is called after systemd is running, so it is definitely
from a module.

Perhaps you had it built in before?


>
> Despite the function not being traceable, the trace file is still
> filled. I’d would have expected to be empty.
>
> ```
> # tracer: function_graph
> #
> # TIME CPU TASK/PID DURATION
> FUNCTION CALLS
> # | | | | | | | |
> | |
> 2.910887 | 0) <idle>-0 | 2.662 us | local_touch_nmi();
> 2.910888 | 0) <idle>-0 | 0.497 us | local_touch_nmi();
> 2.910888 | 0) <idle>-0 | 0.346 us | local_touch_nmi();
> 2.910888 | 1) systemd-1 | 1.440 us | __text_poke();
> 2.910888 | 1) systemd-1 | 0.588 us | __text_poke();
> 2.910888 | 1) systemd-1 | 0.556 us | __text_poke();
> 2.910888 | 1) systemd-1 | 0.489 us | __text_poke();
> […]
> 2.910889 | 1) systemd-1 | 0.530 us | __text_poke();
> 2.910889 | 0) <idle>-0 | 0.473 us | do_sync_core();
> 2.910889 | 1) systemd-1 | 0.572 us | do_sync_core();
> 2.910889 | 0) <idle>-0 | 0.365 us |
> arch_cpu_idle_enter();
> 2.910889 | 1) systemd-1 | 0.830 us | __text_poke();
> 2.910889 | 0) <idle>-0 | ! 278.143 us | arch_cpu_idle();
> 2.910889 | 1) systemd-1 | 0.582 us | __text_poke();
> […]
> ```

Probably because the filtering failed, so there is no filter.

-- Steve

\
 
 \ /
  Last update: 2020-05-11 20:59    [W:0.039 / U:0.420 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site