cpu_clock confusion (was: printk time confusion?)

[Johannes Berg <johannes@sipsolutions.net>]

[-- 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 --]