From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-2.2 required=3.0 tests=HEADER_FROM_DIFFERENT_DOMAINS, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_SANE_2 autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id AD8BCC47255 for ; Mon, 11 May 2020 18:58:15 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 91DC320736 for ; Mon, 11 May 2020 18:58:15 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1731278AbgEKS6O convert rfc822-to-8bit (ORCPT ); Mon, 11 May 2020 14:58:14 -0400 Received: from mail.kernel.org ([198.145.29.99]:50908 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729892AbgEKS6O (ORCPT ); Mon, 11 May 2020 14:58:14 -0400 Received: from gandalf.local.home (cpe-66-24-58-225.stny.res.rr.com [66.24.58.225]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPSA id 5CBBF20720; Mon, 11 May 2020 18:58:13 +0000 (UTC) Date: Mon, 11 May 2020 14:58:12 -0400 From: Steven Rostedt To: Paul Menzel Cc: Ingo Molnar , 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> X-Mailer: Claws Mail 3.17.3 (GTK+ 2.24.32; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8BIT Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Sat, 9 May 2020 12:16:30 +0200 Paul Menzel 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) -0 | 2.662 us | local_touch_nmi(); > 2.910888 | 0) -0 | 0.497 us | local_touch_nmi(); > 2.910888 | 0) -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) -0 | 0.473 us | do_sync_core(); > 2.910889 | 1) systemd-1 | 0.572 us | do_sync_core(); > 2.910889 | 0) -0 | 0.365 us | > arch_cpu_idle_enter(); > 2.910889 | 1) systemd-1 | 0.830 us | __text_poke(); > 2.910889 | 0) -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