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

Message-Id: <20170725233159.89543-1-toddpoynor@google.com>
Date:   Tue, 25 Jul 2017 16:31:59 -0700
From:   Todd Poynor <toddpoynor@...gle.com>
To:     Greg Kroah-Hartman <gregkh@...uxfoundation.org>
Cc:     linux-kernel@...r.kernel.org, android-kernel@...gle.com,
        Todd Poynor <toddpoynor@...gle.com>
Subject: [PATCH] initcall_debug: add deferred probe times

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

Signed-off-by: Todd Poynor <toddpoynor@...gle.com>
---
 drivers/base/dd.c | 28 +++++++++++++++++++++++++++-
 1 file changed, 27 insertions(+), 1 deletion(-)

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 4882f06d12df..6831cb48e9dd 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -20,6 +20,7 @@
 #include <linux/device.h>
 #include <linux/delay.h>
 #include <linux/dma-mapping.h>
+#include <linux/init.h>
 #include <linux/module.h>
 #include <linux/kthread.h>
 #include <linux/wait.h>
@@ -53,6 +54,7 @@ static DEFINE_MUTEX(deferred_probe_mutex);
 static LIST_HEAD(deferred_probe_pending_list);
 static LIST_HEAD(deferred_probe_active_list);
 static atomic_t deferred_trigger_count = ATOMIC_INIT(0);
+static bool initcalls_done;
 
 /*
  * In some cases, like suspend to RAM or hibernation, It might be reasonable
@@ -61,6 +63,26 @@ static atomic_t deferred_trigger_count = ATOMIC_INIT(0);
  */
 static bool defer_all_probes;
 
+/*
+ * For initcall_debug, show the deferred probes executed in late_initcall
+ * processing.
+ */
+static void deferred_probe_debug(struct device *dev)
+{
+	ktime_t calltime, delta, rettime;
+	unsigned long long duration;
+
+	printk(KERN_DEBUG "deferred probe %s @ %i\n", dev_name(dev),
+	       task_pid_nr(current));
+	calltime = ktime_get();
+	bus_probe_device(dev);
+	rettime = ktime_get();
+	delta = ktime_sub(rettime, calltime);
+	duration = (unsigned long long) ktime_to_ns(delta) >> 10;
+	printk(KERN_DEBUG "deferred probe %s returned after %lld usecs\n",
+	       dev_name(dev), duration);
+}
+
 /*
  * deferred_probe_work_func() - Retry probing devices in the active list.
  */
@@ -106,7 +128,10 @@ static void deferred_probe_work_func(struct work_struct *work)
 		device_pm_unlock();
 
 		dev_dbg(dev, "Retrying from deferred list\n");
-		bus_probe_device(dev);
+		if (initcall_debug && !initcalls_done)
+			deferred_probe_debug(dev);
+		else
+			bus_probe_device(dev);
 
 		mutex_lock(&deferred_probe_mutex);
 
@@ -215,6 +240,7 @@ static int deferred_probe_initcall(void)
 	driver_deferred_probe_trigger();
 	/* Sort as many dependencies as possible before exiting initcalls */
 	flush_work(&deferred_probe_work);
+	initcalls_done = true;
 	return 0;
 }
 late_initcall(deferred_probe_initcall);
-- 
2.14.0.rc0.400.g1c36432dff-goog