linux-kernel - Re: ftrace: function radeon

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <d38aacb6-58ef-b1e5-431b-c945380d20cc@molgen.mpg.de>
Date:   Tue, 12 May 2020 01:07:44 +0200
From:   Paul Menzel <pmenzel@...gen.mpg.de>
To:     Steven Rostedt <rostedt@...dmis.org>
Cc:     Ingo Molnar <mingo@...nel.org>, linux-kernel@...r.kernel.org
Subject: Re: ftrace: function radeon_init not traceable

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