[PATCH v2 0/2] PCI: Update quirk timing

[PATCH v2 0/2] PCI: Update quirk timing

[Bjorn Helgaas]

This is a minor update of a patch I posted earlier [1] when Paul
reported an unreasonably long time spent in PCI quirks during boot
[2].  This doesn't fix the slow quirks, but might help find them.

We previously printed the time taken by each quirk if "initcall_debug"
was specified.  With these patches, we'll print it even without
"initcall_debug" if the quirk takes longer than 10ms.

I did notice one quirk (quirk_apple_poweroff_thunderbolt()) in the
suspend path that sleeps for 300ms, so this will probably make suspend
noisier on Apple systems.

[1] https://lkml.kernel.org/r/20171228212723.GB211339@bhelgaas-glaptop.roam.corp.google.com
[2] https://lkml.kernel.org/r/44cada166e42007d27b4c3e3aa0744d7@molgen.mpg.de

---

Bjorn Helgaas (2):
      PCI: Report quirk timings with pci_info() instead of pr_debug()
      PCI: Report quirks that take more than 10ms


 drivers/pci/quirks.c |   24 ++++++++----------------
 1 file changed, 8 insertions(+), 16 deletions(-)

[PATCH v2 1/2] PCI: Report quirk timings with pci_info() instead of pr_debug()

[Bjorn Helgaas]

From: Bjorn Helgaas <bhelgaas@google.com>

With "initcall_debug", we report how long every PCI quirk took.  Previously
we used pr_debug(), which means you have to figure out how to enable debug
output.

Log these timings using pci_info() instead so it doesn't depend on DEBUG,
CONFIG_DYNAMIC_DEBUG, etc.

Also, don't log anything at all unless "initcall_debug" is specified.  This
matches what we do in do_one_initcall_debug().

Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
---
 drivers/pci/quirks.c |    7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
index ec280f2223b3..97c74e386bcc 100644
--- a/drivers/pci/quirks.c
+++ b/drivers/pci/quirks.c
@@ -3004,10 +3004,8 @@ static ktime_t fixup_debug_start(struct pci_dev *dev,
 {
 	ktime_t calltime = 0;
 
-	pci_dbg(dev, "calling %pF\n", fn);
 	if (initcall_debug) {
-		pr_debug("calling  %pF @ %i for %s\n",
-			 fn, task_pid_nr(current), dev_name(&dev->dev));
+		pci_info(dev, "calling  %pF @ %i\n", fn, task_pid_nr(current));
 		calltime = ktime_get();
 	}
 
@@ -3024,8 +3022,7 @@ static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
 		rettime = ktime_get();
 		delta = ktime_sub(rettime, calltime);
 		duration = (unsigned long long) ktime_to_ns(delta) >> 10;
-		pr_debug("pci fixup %pF returned after %lld usecs for %s\n",
-			 fn, duration, dev_name(&dev->dev));
+		pci_info(dev, "%pF took %lld usecs\n", fn, duration);
 	}
 }
 

[PATCH v2 2/2] PCI: Report quirks that take more than 10ms

[Bjorn Helgaas]

From: Bjorn Helgaas <bhelgaas@google.com>

With "initcall_debug", we report how long every PCI quirk took.

Even without "initcall_debug", report the runtime of any quirk that takes
longer than 10ms.  This is to make it easier to notice quirks that slow
down boot.

This was motivated by a report from Paul Menzel that PCI final quirks took
half a second at boot.

Link: https://lkml.kernel.org/r/44cada166e42007d27b4c3e3aa0744d7@molgen.mpg.de
Reported-by: Paul Menzel <pmenzel@molgen.mpg.de>
Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
---
 drivers/pci/quirks.c |   17 ++++++-----------
 1 file changed, 6 insertions(+), 11 deletions(-)

diff --git a/drivers/pci/quirks.c b/drivers/pci/quirks.c
index 97c74e386bcc..1466ee729e0a 100644
--- a/drivers/pci/quirks.c
+++ b/drivers/pci/quirks.c
@@ -3002,14 +3002,10 @@ DECLARE_PCI_FIXUP_HEADER(PCI_VENDOR_ID_INTEL, 0x0e0d, quirk_intel_ntb);
 static ktime_t fixup_debug_start(struct pci_dev *dev,
 				 void (*fn)(struct pci_dev *dev))
 {
-	ktime_t calltime = 0;
-
-	if (initcall_debug) {
+	if (initcall_debug)
 		pci_info(dev, "calling  %pF @ %i\n", fn, task_pid_nr(current));
-		calltime = ktime_get();
-	}
 
-	return calltime;
+	return ktime_get();
 }
 
 static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
@@ -3018,12 +3014,11 @@ static void fixup_debug_report(struct pci_dev *dev, ktime_t calltime,
 	ktime_t delta, rettime;
 	unsigned long long duration;
 
-	if (initcall_debug) {
-		rettime = ktime_get();
-		delta = ktime_sub(rettime, calltime);
-		duration = (unsigned long long) ktime_to_ns(delta) >> 10;
+	rettime = ktime_get();
+	delta = ktime_sub(rettime, calltime);
+	duration = (unsigned long long) ktime_to_ns(delta) >> 10;
+	if (initcall_debug || duration > 10000)
 		pci_info(dev, "%pF took %lld usecs\n", fn, duration);
-	}
 }
 
 /*

Re: [PATCH v2 0/2] PCI: Update quirk timing

[Bjorn Helgaas]

On Wed, Mar 14, 2018 at 08:30:26AM -0500, Bjorn Helgaas wrote:
> This is a minor update of a patch I posted earlier [1] when Paul
> reported an unreasonably long time spent in PCI quirks during boot
> [2].  This doesn't fix the slow quirks, but might help find them.
> 
> We previously printed the time taken by each quirk if "initcall_debug"
> was specified.  With these patches, we'll print it even without
> "initcall_debug" if the quirk takes longer than 10ms.
> 
> I did notice one quirk (quirk_apple_poweroff_thunderbolt()) in the
> suspend path that sleeps for 300ms, so this will probably make suspend
> noisier on Apple systems.
> 
> [1] https://lkml.kernel.org/r/20171228212723.GB211339@bhelgaas-glaptop.roam.corp.google.com
> [2] https://lkml.kernel.org/r/44cada166e42007d27b4c3e3aa0744d7@molgen.mpg.de
> 
> ---
> 
> Bjorn Helgaas (2):
>       PCI: Report quirk timings with pci_info() instead of pr_debug()
>       PCI: Report quirks that take more than 10ms
> 
> 
>  drivers/pci/quirks.c |   24 ++++++++----------------
>  1 file changed, 8 insertions(+), 16 deletions(-)

Applied to pci/misc for v4.17.