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?
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();
[…]
```
Kind regards,
Paul
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
Dear Steven,
Thank you for your quick response.
Am 11.05.20 um 20:58 schrieb Steven Rostedt:
> On Sat, 9 May 2020 12:16:30 +0200 Paul Menzel wrote:
>> 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?
You are right. Probably I did. Can you suggest how to set up ftrace to
trace a module?
>> 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.
Is that the intended behavior? Or should nothing be traced?
Kind regards,
Paul
On Tue, 12 May 2020 01:07:44 +0200
Paul Menzel <[email protected]> wrote:
> >>
> >> 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?
>
> You are right. Probably I did. Can you suggest how to set up ftrace to
> trace a module?
In recent kernels there was a feature to function trace modules before
they are loaded, but that feature isn't yet available on mainline. I
could add it when I get a chance, but that wont be in the near future.
Also, the function graph wont work for that either, as that isn't set
up to preload before functions. But since you have
ftrace_graph_max_depth of one, you don't need the graph, the limiting
of the function (set_ftrace_filter) is good enough. But again, that
only works after boot up.
> >
> > Probably because the filtering failed, so there is no filter.
>
> Is that the intended behavior? Or should nothing be traced?
Well, it's just like writing something not acceptable in the filter
functions. If it fails, it does not filter. So yes, it is expected
behavior.
-- Steve