Excessive latency for dev_dbg?

Excessive latency for dev_dbg?

[Alan Stern]

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?

Alan Stern

Re: Excessive latency for dev_dbg?

[Joe Perches]

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?

Re: Excessive latency for dev_dbg?

[Greg KH]

On Wed, May 23, 2012 at 01:45:03PM -0700, 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?

Joe, why ask Kay?  He didn't touch this code until 3.5-rc1, and Alan is
testing 3.4.

confused,

greg k-h

Re: Excessive latency for dev_dbg?

[Joe Perches]

On Wed, 2012-05-23 at 19:12 -0700, Greg KH wrote:
> On Wed, May 23, 2012 at 01:45:03PM -0700, Joe Perches wrote:
> > cc'ing Kay.
> > > What's going on here?  Did printk suddenly slow down a lot?  Or has the
> > > timer code gone crazy?
> Joe, why ask Kay?  He didn't touch this code until 3.5-rc1, and Alan is
> testing 3.4.

Sorry, my mistake.

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