printk time confusion?

printk time confusion?

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 1116 bytes --]

Hi,

Not sure whether the lockdep patches or something else is causing this
as I haven't checked w/o the patches yet, but I seem to be having some
confusion of printk timestamps:

[...]
[  176.440255] iwl4965: No space for Tx
[...]
[  147.983705] ioctl32(gnome-terminal:6361): Unknown cmd fd(25) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/2
[...]
[  173.589209] BUG kmalloc-2048: Poison overwritten
[...]
[  208.385226] ioctl32(gnome-terminal:6498): Unknown cmd fd(29) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/6
[...]
[  139.026724] ioctl32(gnome-terminal:6521): Unknown cmd fd(30) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe8) on /dev/pts/7
[...]
[  155.982345] ioctl32(gnome-terminal:6543): Unknown cmd fd(31) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/8
[...]
[  218.918388] tg3: eth0: Link is down.
[...]

Yes, these entries really were printed in that order. Btw, what's with
the unknown ioctls?

Kernel version is 2.6.25-rc8-wl-04519-g6648ff7-dirty where -wl/-dirty
refers to wireless patches and the lockdep patches and otherwise it's
just -rc8.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: printk time confusion?

[Benjamin Herrenschmidt]

On Wed, 2008-04-02 at 16:23 +0200, Johannes Berg wrote:
> Hi,
> 
> Not sure whether the lockdep patches or something else is causing this
> as I haven't checked w/o the patches yet, but I seem to be having some
> confusion of printk timestamps:

Tried reverting the patches ?

> [...]
> [  176.440255] iwl4965: No space for Tx
> [...]
> [  147.983705] ioctl32(gnome-terminal:6361): Unknown cmd fd(25) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/2
> [...]
> [  173.589209] BUG kmalloc-2048: Poison overwritten
> [...]
> [  208.385226] ioctl32(gnome-terminal:6498): Unknown cmd fd(29) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/6
> [...]
> [  139.026724] ioctl32(gnome-terminal:6521): Unknown cmd fd(30) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe8) on /dev/pts/7
> [...]
> [  155.982345] ioctl32(gnome-terminal:6543): Unknown cmd fd(31) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/8
> [...]
> [  218.918388] tg3: eth0: Link is down.
> [...]
> 
> Yes, these entries really were printed in that order. Btw, what's with
> the unknown ioctls?

Proably ioctl's that lack a 32 bits conversion, you'll have to dig in
the pty stuff to find out which ones it is and if it can be a problem...

> Kernel version is 2.6.25-rc8-wl-04519-g6648ff7-dirty where -wl/-dirty
> refers to wireless patches and the lockdep patches and otherwise it's
> just -rc8.
> 
> johannes

Re: printk time confusion?

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 734 bytes --]


> > Not sure whether the lockdep patches or something else is causing this
> > as I haven't checked w/o the patches yet, but I seem to be having some
> > confusion of printk timestamps:
> 
> Tried reverting the patches ?

No, not yet, I'll do that later today.


> > [  155.982345] ioctl32(gnome-terminal:6543): Unknown cmd fd(31) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/8

> > Yes, these entries really were printed in that order. Btw, what's with
> > the unknown ioctls?
> 
> Proably ioctl's that lack a 32 bits conversion, you'll have to dig in
> the pty stuff to find out which ones it is and if it can be a problem...

Yeah, I'll have to see, I just thought Arnd might already know :)

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: printk time confusion?

[Andreas Schwab]

Benjamin Herrenschmidt <benh@ozlabs.org> writes:

> On Wed, 2008-04-02 at 16:23 +0200, Johannes Berg wrote:
>> [...]
>> [  176.440255] iwl4965: No space for Tx
>> [...]
>> [  147.983705] ioctl32(gnome-terminal:6361): Unknown cmd fd(25) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/2
>> [...]
>> [  173.589209] BUG kmalloc-2048: Poison overwritten
>> [...]
>> [  208.385226] ioctl32(gnome-terminal:6498): Unknown cmd fd(29) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/6
>> [...]
>> [  139.026724] ioctl32(gnome-terminal:6521): Unknown cmd fd(30) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe8) on /dev/pts/7
>> [...]
>> [  155.982345] ioctl32(gnome-terminal:6543): Unknown cmd fd(31) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/8
>> [...]
>> [  218.918388] tg3: eth0: Link is down.
>> [...]
>> 
>> Yes, these entries really were printed in that order. Btw, what's with
>> the unknown ioctls?
>
> Proably ioctl's that lack a 32 bits conversion, you'll have to dig in
> the pty stuff to find out which ones it is and if it can be a problem...

0x53xx is claimed by cdrom.h, and 0x530b is CDROMSUBCHNL.  Of course, a
tty does not implement cdrom ioctls.

Andreas.

-- 
Andreas Schwab, SuSE Labs, schwab@suse.de
SuSE Linux Products GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany
PGP key fingerprint = 58CA 54C7 6D53 942B 1756  01D3 44D5 214B 8276 4ED5
"And now for something completely different."

Re: printk time confusion?

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 529 bytes --]


> >> [  155.982345] ioctl32(gnome-terminal:6543): Unknown cmd fd(31) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/8

> > Proably ioctl's that lack a 32 bits conversion, you'll have to dig in
> > the pty stuff to find out which ones it is and if it can be a problem...
> 
> 0x53xx is claimed by cdrom.h, and 0x530b is CDROMSUBCHNL.  Of course, a
> tty does not implement cdrom ioctls.

Humm ok, then the first question is why gnome-terminal tries that, and
the second why it would printk something?

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: printk time confusion?

[Andreas Schwab]

Johannes Berg <johannes@sipsolutions.net> writes:

>> >> [  155.982345] ioctl32(gnome-terminal:6543): Unknown cmd fd(31) cmd(0000530b){t:'S';sz:0} arg(0fd7bbe0) on /dev/pts/8
>
>> > Proably ioctl's that lack a 32 bits conversion, you'll have to dig in
>> > the pty stuff to find out which ones it is and if it can be a problem...
>> 
>> 0x53xx is claimed by cdrom.h, and 0x530b is CDROMSUBCHNL.  Of course, a
>> tty does not implement cdrom ioctls.
>
> Humm ok, then the first question is why gnome-terminal tries that

Perhaps some misconfiguration, I can't reproduce that here (with
2.18.2).

> and the second why it would printk something?

To ease finding missing compat ioctl handlers.

Andreas.

-- 
Andreas Schwab, SuSE Labs, schwab@suse.de
SuSE Linux Products GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany
PGP key fingerprint = 58CA 54C7 6D53 942B 1756  01D3 44D5 214B 8276 4ED5
"And now for something completely different."

cpu_clock confusion (was: printk time confusion?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 1506 bytes --]

Hi,

> > Not sure whether the lockdep patches or something else is causing this
> > as I haven't checked w/o the patches yet, but I seem to be having some
> > confusion of printk timestamps:
> 
> Tried reverting the patches ?

That didn't help, so it's not the lockdep patches causing it. I'm still
seeing printk timestamps like this:

[    2.764009 (3/3)]
[    4.272241 (2/2)]
[    4.272322 (2/2)]
[    4.272375 (2/2)]
[    2.948002 (3/3)]

As you can see, I added printk_cpu and smp_processor_id() to the printk
timestamp output and thus it is obvious that the different times come
from different CPUs.

I have to admit that I do not understand the cpu_clock() implementation,
but I can only point out that the bug seems to be there since our
sched_clock() uses the timebase which is certainly synchronized. For the
fun of it, here's another output, with get_tb() thrown in:

[   15.285317 (0/0,1734086151)]
[   13.563845 (3/3,1757040324)]
[   13.700157 (3/3,1773150788)]
[   15.181275 (1/1,1829646200)]
[   15.181343 (1/1,1829648488)]
[   16.987944 (0/0,1829664311)]
[   16.988485 (0/0,1829682407)]
[   12.047482 (2/2,1829690681)]

As expected, the timebase is perfectly fine, it's monotonously
increasing over all the processors, but cpu_clock() doesn't seem to
notice. Not sure what to make of it. It seems just using the timebase
(in form of sched_clock()) ought to be perfectly fine and even have less
overhead than all this cpu_clock() business.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: cpu_clock confusion (was: printk time confusion?)

[Ingo Molnar]

* Johannes Berg <johannes@sipsolutions.net> wrote:

> Hi,
> 
> > > Not sure whether the lockdep patches or something else is causing this
> > > as I haven't checked w/o the patches yet, but I seem to be having some
> > > confusion of printk timestamps:
> > 
> > Tried reverting the patches ?
> 
> That didn't help, so it's not the lockdep patches causing it. I'm still
> seeing printk timestamps like this:
> 
> [    2.764009 (3/3)]
> [    4.272241 (2/2)]
> [    4.272322 (2/2)]
> [    4.272375 (2/2)]
> [    2.948002 (3/3)]
> 
> As you can see, I added printk_cpu and smp_processor_id() to the 
> printk timestamp output and thus it is obvious that the different 
> times come from different CPUs.

the fixes are queued for v2.6.26. You can pick them up from 
sched-devel/latest as well:

  http://people.redhat.com/mingo/sched-devel.git/README

	Ingo

Re: cpu_clock confusion (was: printk time confusion?)

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 714 bytes --]


> > [    2.764009 (3/3)]
> > [    4.272241 (2/2)]
> > [    4.272322 (2/2)]
> > [    4.272375 (2/2)]
> > [    2.948002 (3/3)]
> > 
> > As you can see, I added printk_cpu and smp_processor_id() to the 
> > printk timestamp output and thus it is obvious that the different 
> > times come from different CPUs.
> 
> the fixes are queued for v2.6.26. You can pick them up from 
> sched-devel/latest as well:
> 
>   http://people.redhat.com/mingo/sched-devel.git/README

Hmm. Why is that whole cpu_clock stuff in place anyway? powerpc has
perfectly synchronised time across processors with dirt cheap access to
it as well, so why build all this code that only messes it up on top of
it?

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: cpu_clock confusion

[David Miller]

From: Johannes Berg <johannes@sipsolutions.net>
Date: Thu, 24 Apr 2008 11:21:52 +0200

> Hmm. Why is that whole cpu_clock stuff in place anyway? powerpc has
> perfectly synchronised time across processors with dirt cheap access to
> it as well, so why build all this code that only messes it up on top of
> it?

Same on sparc64.  These changes add more bugs than they fix.

Re: cpu_clock confusion

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 790 bytes --]

On Thu, 2008-04-24 at 02:24 -0700, David Miller wrote:
> From: Johannes Berg <johannes@sipsolutions.net>
> Date: Thu, 24 Apr 2008 11:21:52 +0200
> 
> > Hmm. Why is that whole cpu_clock stuff in place anyway? powerpc has
> > perfectly synchronised time across processors with dirt cheap access to
> > it as well, so why build all this code that only messes it up on top of
> > it?
> 
> Same on sparc64.  These changes add more bugs than they fix.

I tend to think all this clock business should be done local to those
arches that aren't capable of providing cheap, useful synchronised and
accurate clocks themselves. Or be a lib that they can link in if needed.
As it stands, it seems to me that it all just penalises those
architectures that have decent clocks.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: cpu_clock confusion

[Gabriel Paubert]

On Thu, Apr 24, 2008 at 11:27:37AM +0200, Johannes Berg wrote:
> On Thu, 2008-04-24 at 02:24 -0700, David Miller wrote:
> > From: Johannes Berg <johannes@sipsolutions.net>
> > Date: Thu, 24 Apr 2008 11:21:52 +0200
> > 
> > > Hmm. Why is that whole cpu_clock stuff in place anyway? powerpc has
> > > perfectly synchronised time across processors with dirt cheap access to
> > > it as well, so why build all this code that only messes it up on top of
> > > it?
> > 
> > Same on sparc64.  These changes add more bugs than they fix.
> 
> I tend to think all this clock business should be done local to those
> arches that aren't capable of providing cheap, useful synchronised and
> accurate clocks themselves. Or be a lib that they can link in if needed.
> As it stands, it seems to me that it all just penalises those
> architectures that have decent clocks.

100% agreed. 

	Gabriel