Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Date:   Mon, 11 May 2020 14:58:12 -0400
From:   Steven Rostedt <rostedt@goodmis.org>
To:     Paul Menzel <pmenzel@molgen.mpg.de>
Cc:     Ingo Molnar <mingo@kernel.org>, linux-kernel@vger.kernel.org
Subject: Re: ftrace: function radeon_init not traceable
Message-ID: <20200511145812.7206b095@gandalf.local.home>
In-Reply-To: <01e29852-c9db-8181-e4fa-dda50f774cf6@molgen.mpg.de>
References: <01e29852-c9db-8181-e4fa-dda50f774cf6@molgen.mpg.de>
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8BIT
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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