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
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?
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
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.
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