Messages in this thread | | | Subject | cpu_clock confusion (was: printk time confusion?) | From | Johannes Berg <> | Date | Thu, 03 Apr 2008 18:34:10 +0200 |
| |
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 [unhandled content-type:application/pgp-signature] | |