* Re: Excessive latency for dev_dbg?
2012-05-23 20:45 ` Joe Perches
@ 2012-05-24 2:12 ` Greg KH
2012-05-24 2:13 ` Joe Perches
2012-05-24 17:57 ` Alan Stern
1 sibling, 1 reply; 5+ messages in thread
From: Greg KH @ 2012-05-24 2:12 UTC (permalink / raw)
To: Joe Perches
Cc: Alan Stern, Kay Sievers, Kernel development list, Jason Baron,
Thomas Gleixner
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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: Excessive latency for dev_dbg?
2012-05-23 20:45 ` Joe Perches
2012-05-24 2:12 ` Greg KH
@ 2012-05-24 17:57 ` Alan Stern
1 sibling, 0 replies; 5+ messages in thread
From: Alan Stern @ 2012-05-24 17:57 UTC (permalink / raw)
To: Joe Perches
Cc: Kay Sievers, Kernel development list, Jason Baron,
Thomas Gleixner, Greg KH
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
^ permalink raw reply [flat|nested] 5+ messages in thread