Re: Excessive latency for dev_dbg?

[Alan Stern]

On Wed, 23 May 2012, Joe Perches wrote:

> cc'ing Kay.
> 
> On Wed, 2012-05-23 at 16:37 -0400, Alan Stern wrote:
> > I just tried doing some testing of 3.4.  Sequences of literally
> > adjacent dev_dbg() calls -- with local interrupts disabled -- show up
> > in the log buffer spaced at time intervals between 1 and 4
> > milliseconds!
> > 
> > This is with CONFIG_DYNAMIC_DEBUG not enabled, and CONFIG_PRINTK_TIME,
> > CONFIG_PREEMPT, CONFIG_HIGH_RES_TIMERS, and CONFIG_HPET_TIMER all set
> > to y.
> > 
> > What's going on here?  Did printk suddenly slow down a lot?  Or has the
> > timer code gone crazy?

Okay, I did a little more directed testing.  It turns out the same
thing happens with a 3.3 kernel, so I can't even call it a regression.  
And it's not directly related to dev_dbg, because the same thing 
happens with dev_info.  But it does look peculiar.

Here's the test patch:


--- usb-3.4.orig/drivers/usb/gadget/dummy_hcd.c
+++ usb-3.4/drivers/usb/gadget/dummy_hcd.c
@@ -997,6 +997,19 @@ static int dummy_udc_probe(struct platfo
 	if (rc < 0)
 		goto err_dev;
 	platform_set_drvdata(pdev, dum);
+
+	spin_lock_irq(&dum->lock);
+	dev_info(&pdev->dev, "dev_info 1\n");
+	dev_info(&pdev->dev, "dev_info 2\n");
+	dev_info(&pdev->dev, "dev_info 3\n");
+	dev_dbg(&pdev->dev, "dev_dbg 1\n");
+	dev_dbg(&pdev->dev, "dev_dbg 2\n");
+	dev_dbg(&pdev->dev, "dev_dbg 3\n");
+	printk(KERN_INFO "printk 1\n");
+	printk(KERN_INFO "printk 2\n");
+	printk(KERN_INFO "printk 3\n");
+	spin_unlock_irq(&dum->lock);
+
 	return rc;
 
 err_dev:


Here's the output under 3.3 (note: UP machine but with CONFIG_SMP 
enabled):

[  102.784488] dummy_udc dummy_udc: dev_info 1
[  102.786776] dummy_udc dummy_udc: dev_info 2
[  102.788054] dummy_udc dummy_udc: dev_info 3
[  102.788054] dummy_udc dummy_udc: dev_dbg 1
[  102.788054] dummy_udc dummy_udc: dev_dbg 2
[  102.788054] dummy_udc dummy_udc: dev_dbg 3
[  102.788054] printk 1
[  102.788054] printk 2
[  102.788054] printk 3

And here's the output under 3.4:

[  166.521453] dummy_udc dummy_udc: dev_info 1
[  166.524026] dummy_udc dummy_udc: dev_info 2
[  166.524026] dummy_udc dummy_udc: dev_info 3
[  166.524026] dummy_udc dummy_udc: dev_dbg 1
[  166.524026] dummy_udc dummy_udc: dev_dbg 2
[  166.524026] dummy_udc dummy_udc: dev_dbg 3
[  166.524026] printk 1
[  166.524026] printk 2
[  166.524026] printk 3

In fact, 3.4 looks slightly better than 3.3, in that there's no
measurable delay between the "dev_info 2" and "dev_info 3" lines.

But what's going on with the first two dev_info lines?  A 2.6 ms delay 
during which nothing happens?  Or incorrect timestamps?

.config files are available upon request.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/