linux-kernel - Re: [PATCH] initcall_debug: add deferred probe times

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] [day] [month] [year] [list]

Date:   Thu, 3 Aug 2017 17:47:12 -0700
From:   Greg Kroah-Hartman <gregkh@...uxfoundation.org>
To:     Todd Poynor <toddpoynor@...gle.com>
Cc:     LKML <linux-kernel@...r.kernel.org>,
        android-kernel <android-kernel@...gle.com>,
        Todd E Brandt <todd.e.brandt@...ux.intel.com>,
        "Rafael J. Wysocki" <rafael.j.wysocki@...el.com>
Subject: Re: [PATCH] initcall_debug: add deferred probe times

On Tue, Jul 25, 2017 at 08:01:49PM -0700, Todd Poynor wrote:
> On Tue, Jul 25, 2017 at 4:40 PM, Greg Kroah-Hartman
> <gregkh@...uxfoundation.org> wrote:
> > On Tue, Jul 25, 2017 at 04:31:59PM -0700, Todd Poynor wrote:
> >> initcall_debug attributes all deferred device probe retries for the
> >> late_initcall level to function deferred_probe_initcall.  Add logs of
> >> the individual device probe routines called, to identify which drivers
> >> are executing for how long during the initcall path.  Deferred probes
> >> that occur after initcall processing are not shown.
> >>
> >> Example log messages added:
> >>
> >> [    0.505119] deferred probe my-sound-device @ 6
> >> [    0.517656] deferred probe my-sound-device returned after 1227 usecs
> >
> > Can't you subtract the timestamp number right there?
> 
> This patch extends the existing initcall_debug functionality; I've
> copied the methods used by do_one_initcall_debug() to compute and
> report timing info in a compatible format.  If it's better to change
> the way this is reported, I can also suggest changes to the existing
> initcall_debug code.  cc'ed the maintainers (I should have in the
> first place).

Ah, ok, I missed that, I was looking at the driver probe debug path,
this makes a lot more sense then.

> > And doesn't the tools/power/pm-graph/ scripts do this type of thing
> > automatically for you to give you pretty graphs you can use to drill
> > down on what is taking how long and such?
> 
> analyze_boot.py parses the dmesg output printed by initcall_debug to
> produce those graphs (and can also produce ftrace-based function
> callgraphs).  The initcall_debug output printed (and graphed) for
> deferred probe calls are lumped into a single entry
> "deferred_probe_initcall".  This patch logs the times of the
> individual deferred probe calls by device name, to better help
> developers understand where the time is spent.  If this feature finds
> favor, it may also be deemed useful to update analyze_boot.py to graph
> this information.

I think updating it would be good, but for now this should be fine.
Thanks for the information.

greg k-h