On Sat, 9 May 2020 12:16:30 +0200 Paul Menzel <[email protected]> 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
