People - we are doing some performance tests on Firefox startup times and getting a little weirdness on the time differences reported looking at timestamp and walltimestamp deltas. Can anyone shed any light on this? JR P.s. The end point I choose might not work for you depending on your Firefox setup, you can always end on the history.dat access or bookmarks.html. -------------- next part -------------- An embedded message was scrubbed... From: John Rice <John.Rice at Sun.COM> Subject: Firefox DTrace Timing strangeness Date: Wed, 07 Dec 2005 09:41:09 +0000 Size: 24818 URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20051207/38ae426d/attachment.nws>
Bryan Cantrill
2005-Dec-07 19:24 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
On Wed, Dec 07, 2005 at 04:57:57PM +0000, John Rice wrote:> People - we are doing some performance tests on Firefox startup times > and getting a little weirdness on the time differences reported looking > at timestamp and walltimestamp deltas. > > Can anyone shed any light on this?This is odd. One would expect deltas in walltimestamp and timestamp to (1) not be identical and (2) to drift a bit, but this kind of difference is unexpected. Your script is a bit odd, and in particular it doesn''t predicate on the thread-local variables (if _anyone_ opens necko_cache.xpt it will report the deltas, even if the thread that opened it isn''t the thread that exec''d firefox, or isn''t firefox at all). Still, if this were your problem you would expect numbers that are wildly wrong, not just drifting. Just for sanity''s sake, run this script on the machine: ---8<--- deltas.d ---8<--- #pragma D option quiet BEGIN { ts = timestamp; wall = walltimestamp; } tick-1sec { this->dts = timestamp - ts; this->dwall = walltimestamp - wall; printf("Difference in deltas : %10d nanoseconds.\n", (int64_t)this->dts - (int64_t)this->dwall); } ---8<--- deltas.d ---8<--- If this script shows huge or wildly diverging deltas, there might be something busted in either the hardware and/or the TOD chip. (When I run the above on a few test machines, I see the expected output: smallish and roughly constant numbers.) - Bryan -------------------------------------------------------------------------- Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
Sean McGrath - Sun Microsystems Ireland
2005-Dec-07 19:52 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
on a ferrari 4000 (where I''m seeing similar things to John):
bash-3.00# ./deltas.d
Difference in deltas : -443369462 nanoseconds.
Difference in deltas : -1043369843 nanoseconds.
Difference in deltas : -1643369337 nanoseconds.
Difference in deltas : -2243369600 nanoseconds.
Difference in deltas : -2843369852 nanoseconds.
Difference in deltas : -3443369833 nanoseconds.
Difference in deltas : -4043369692 nanoseconds.
Difference in deltas : -4643369664 nanoseconds.
Difference in deltas : -5243369322 nanoseconds.
Difference in deltas : -5843369488 nanoseconds.
Difference in deltas : -6443369887 nanoseconds.
Difference in deltas : -7043368713 nanoseconds.
Difference in deltas : -7643369908 nanoseconds.
Difference in deltas : -8243370203 nanoseconds.
Difference in deltas : -8843368998 nanoseconds.
Difference in deltas : -9443369210 nanoseconds.
Difference in deltas : -10043369668 nanoseconds.
Difference in deltas : -10643369511 nanoseconds.
Difference in deltas : -11243369762 nanoseconds.
^C
and keeps growing...
This a side affect of being on a single cpu box ? Or cause its a
laptop ?
Sean.
.
Bryan Cantrill stated:
< On Wed, Dec 07, 2005 at 04:57:57PM +0000, John Rice wrote:
< > People - we are doing some performance tests on Firefox startup times
< > and getting a little weirdness on the time differences reported
looking
< > at timestamp and walltimestamp deltas.
< >
< > Can anyone shed any light on this?
<
< This is odd. One would expect deltas in walltimestamp and timestamp
< to (1) not be identical and (2) to drift a bit, but this kind of
< difference is unexpected. Your script is a bit odd, and in particular
< it doesn''t predicate on the thread-local variables (if _anyone_
opens
< necko_cache.xpt it will report the deltas, even if the thread that opened
< it isn''t the thread that exec''d firefox, or
isn''t firefox at all). Still,
< if this were your problem you would expect numbers that are wildly
< wrong, not just drifting. Just for sanity''s sake, run this script
< on the machine:
<
< ---8<--- deltas.d ---8<---
<
< #pragma D option quiet
<
< BEGIN
< {
< ts = timestamp;
< wall = walltimestamp;
< }
<
< tick-1sec
< {
< this->dts = timestamp - ts;
< this->dwall = walltimestamp - wall;
<
< printf("Difference in deltas : %10d nanoseconds.\n",
< (int64_t)this->dts - (int64_t)this->dwall);
< }
<
< ---8<--- deltas.d ---8<---
<
< If this script shows huge or wildly diverging deltas, there might be
< something busted in either the hardware and/or the TOD chip. (When I run
< the above on a few test machines, I see the expected output: smallish and
< roughly constant numbers.)
<
< - Bryan
<
< --------------------------------------------------------------------------
< Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
< _______________________________________________
< dtrace-discuss mailing list
< dtrace-discuss at opensolaris.org
Sean McGrath - Sun Microsystems Ireland
2005-Dec-07 20:02 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
btw, also ran the script on multi-cpu sparc - no growing,
on a single cpu dell x86 box - no growing..
Seems to be laptop related.
I''ve seen dtraced boottimes on a laptop showing an uptime of
523099 seconds, when I only hit the power button 70 secs beforehand.
Sean.
.
Sean McGrath - Sun Microsystems Ireland stated:
<
<
< on a ferrari 4000 (where I''m seeing similar things to John):
<
< bash-3.00# ./deltas.d
< Difference in deltas : -443369462 nanoseconds.
< Difference in deltas : -1043369843 nanoseconds.
< Difference in deltas : -1643369337 nanoseconds.
< Difference in deltas : -2243369600 nanoseconds.
< Difference in deltas : -2843369852 nanoseconds.
< Difference in deltas : -3443369833 nanoseconds.
< Difference in deltas : -4043369692 nanoseconds.
< Difference in deltas : -4643369664 nanoseconds.
< Difference in deltas : -5243369322 nanoseconds.
< Difference in deltas : -5843369488 nanoseconds.
< Difference in deltas : -6443369887 nanoseconds.
< Difference in deltas : -7043368713 nanoseconds.
< Difference in deltas : -7643369908 nanoseconds.
< Difference in deltas : -8243370203 nanoseconds.
< Difference in deltas : -8843368998 nanoseconds.
< Difference in deltas : -9443369210 nanoseconds.
< Difference in deltas : -10043369668 nanoseconds.
< Difference in deltas : -10643369511 nanoseconds.
< Difference in deltas : -11243369762 nanoseconds.
< ^C
<
< and keeps growing...
<
< This a side affect of being on a single cpu box ? Or cause its a
< laptop ?
<
< Sean.
< .
< Bryan Cantrill stated:
< < On Wed, Dec 07, 2005 at 04:57:57PM +0000, John Rice wrote:
< < > People - we are doing some performance tests on Firefox startup
times
< < > and getting a little weirdness on the time differences reported
looking
< < > at timestamp and walltimestamp deltas.
< < >
< < > Can anyone shed any light on this?
< <
< < This is odd. One would expect deltas in walltimestamp and timestamp
< < to (1) not be identical and (2) to drift a bit, but this kind of
< < difference is unexpected. Your script is a bit odd, and in particular
< < it doesn''t predicate on the thread-local variables (if
_anyone_ opens
< < necko_cache.xpt it will report the deltas, even if the thread that
opened
< < it isn''t the thread that exec''d firefox, or
isn''t firefox at all). Still,
< < if this were your problem you would expect numbers that are wildly
< < wrong, not just drifting. Just for sanity''s sake, run this
script
< < on the machine:
< <
< < ---8<--- deltas.d ---8<---
< <
< < #pragma D option quiet
< <
< < BEGIN
< < {
< < ts = timestamp;
< < wall = walltimestamp;
< < }
< <
< < tick-1sec
< < {
< < this->dts = timestamp - ts;
< < this->dwall = walltimestamp - wall;
< <
< < printf("Difference in deltas : %10d nanoseconds.\n",
< < (int64_t)this->dts - (int64_t)this->dwall);
< < }
< <
< < ---8<--- deltas.d ---8<---
< <
< < If this script shows huge or wildly diverging deltas, there might be
< < something busted in either the hardware and/or the TOD chip. (When I
run
< < the above on a few test machines, I see the expected output: smallish
and
< < roughly constant numbers.)
< <
< < - Bryan
< <
< <
--------------------------------------------------------------------------
< < Bryan Cantrill, Solaris Kernel Development.
http://blogs.sun.com/bmc
< < _______________________________________________
< < dtrace-discuss mailing list
< < dtrace-discuss at opensolaris.org
<
< _______________________________________________
< dtrace-discuss mailing list
< dtrace-discuss at opensolaris.org
Bryan Cantrill
2005-Dec-07 20:10 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
> on a ferrari 4000 (where I''m seeing similar things to John): > > bash-3.00# ./deltas.d > Difference in deltas : -443369462 nanoseconds. > Difference in deltas : -1043369843 nanoseconds. > Difference in deltas : -1643369337 nanoseconds. > Difference in deltas : -2243369600 nanoseconds. > Difference in deltas : -2843369852 nanoseconds. > Difference in deltas : -3443369833 nanoseconds. > Difference in deltas : -4043369692 nanoseconds. > Difference in deltas : -4643369664 nanoseconds. > Difference in deltas : -5243369322 nanoseconds. > Difference in deltas : -5843369488 nanoseconds. > Difference in deltas : -6443369887 nanoseconds. > Difference in deltas : -7043368713 nanoseconds. > Difference in deltas : -7643369908 nanoseconds. > Difference in deltas : -8243370203 nanoseconds. > Difference in deltas : -8843368998 nanoseconds. > Difference in deltas : -9443369210 nanoseconds. > Difference in deltas : -10043369668 nanoseconds. > Difference in deltas : -10643369511 nanoseconds. > Difference in deltas : -11243369762 nanoseconds. > ^C > > and keeps growing... > > This a side affect of being on a single cpu box ? Or cause its a > laptop ?It''s (apparently) because high-resolution time on that platform seems to be busted -- it looks like gethrtime() isn''t moving forward. Try this: % cat hr.c #include <sys/time.h> void main() { hrtime_t start; for (start = gethrtime();;) { sleep(1); printf("%lld nanoseconds\n", gethrtime() - start); } } % gcc -o hr hr.c hr.c: In function `main'': hr.c:5: warning: return type of ''main'' is not `int'' % Running this, you should see output like this (from my Ferrari 3400): 1008399151 nanoseconds 2018369679 nanoseconds 3028365931 nanoseconds 4038392484 nanoseconds 5048369385 nanoseconds 6058367998 nanoseconds 7068392922 nanoseconds 8078366154 nanoseconds That is, the deltas should be ~one billion nanoseconds +/- the clock interval (ten milliseconds by default). If there not, we know that this is a generic high-resolution time problem on the Ferrari 4000, and not a DTrace problem per se. John: is the data that you originally sent out from a Ferrari 4000 as well? - Bryan -------------------------------------------------------------------------- Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
Sean McGrath - Sun Microsystems Ireland
2005-Dec-07 20:15 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
Bryan Cantrill stated:
<
< > on a ferrari 4000 (where I''m seeing similar things to
John):
< >
< > bash-3.00# ./deltas.d
< > Difference in deltas : -443369462 nanoseconds.
< > Difference in deltas : -1043369843 nanoseconds.
< > Difference in deltas : -1643369337 nanoseconds.
< > Difference in deltas : -2243369600 nanoseconds.
< > Difference in deltas : -2843369852 nanoseconds.
< > Difference in deltas : -3443369833 nanoseconds.
< > Difference in deltas : -4043369692 nanoseconds.
< > Difference in deltas : -4643369664 nanoseconds.
< > Difference in deltas : -5243369322 nanoseconds.
< > Difference in deltas : -5843369488 nanoseconds.
< > Difference in deltas : -6443369887 nanoseconds.
< > Difference in deltas : -7043368713 nanoseconds.
< > Difference in deltas : -7643369908 nanoseconds.
< > Difference in deltas : -8243370203 nanoseconds.
< > Difference in deltas : -8843368998 nanoseconds.
< > Difference in deltas : -9443369210 nanoseconds.
< > Difference in deltas : -10043369668 nanoseconds.
< > Difference in deltas : -10643369511 nanoseconds.
< > Difference in deltas : -11243369762 nanoseconds.
< > ^C
< >
< > and keeps growing...
< >
< > This a side affect of being on a single cpu box ? Or cause its a
< > laptop ?
<
< It''s (apparently) because high-resolution time on that platform
seems to
< be busted -- it looks like gethrtime() isn''t moving forward. Try
this:
<
< % cat hr.c
< #include <sys/time.h>
<
< void
< main()
< {
< hrtime_t start;
<
< for (start = gethrtime();;) {
< sleep(1);
< printf("%lld nanoseconds\n", gethrtime() - start);
< }
< }
< % gcc -o hr hr.c
< hr.c: In function `main'':
< hr.c:5: warning: return type of ''main'' is not
`int''
< %
<
< Running this, you should see output like this (from my Ferrari 3400):
<
< 1008399151 nanoseconds
< 2018369679 nanoseconds
< 3028365931 nanoseconds
< 4038392484 nanoseconds
< 5048369385 nanoseconds
< 6058367998 nanoseconds
< 7068392922 nanoseconds
< 8078366154 nanoseconds
Getting similar:
kashyyyk:~/langs/c$ ./hr
1005641410 nanoseconds
2015600062 nanoseconds
3015650538 nanoseconds
4025609963 nanoseconds
5035611191 nanoseconds
6045649572 nanoseconds
7055610006 nanoseconds
8055655973 nanoseconds
9065621642 nanoseconds
^C
kashyyyk:~/langs/c$
<
< That is, the deltas should be ~one billion nanoseconds +/- the clock
< interval (ten milliseconds by default). If there not, we know that this
< is a generic high-resolution time problem on the Ferrari 4000, and not
< a DTrace problem per se. John: is the data that you originally sent out
< from a Ferrari 4000 as well?
Johns got a 3400
Sean.
.
<
< - Bryan
<
< --------------------------------------------------------------------------
< Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
--
Sean.
.
sean DoT mcgrath At sun.com http://blogs.sun.com/smg
http://www.sun.com/software/solaris
Bryan Cantrill
2005-Dec-07 20:21 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
> Getting similar: > kashyyyk:~/langs/c$ ./hr > 1005641410 nanoseconds > 2015600062 nanoseconds > 3015650538 nanoseconds > 4025609963 nanoseconds > 5035611191 nanoseconds > 6045649572 nanoseconds > 7055610006 nanoseconds > 8055655973 nanoseconds > 9065621642 nanoseconds > ^C > kashyyyk:~/langs/c$Odd; on my 3400, the D script that I sent gives the expected output. What build are you running? (I''ve booted S10 GA at the moment.) And are you running frkit? - Bryan -------------------------------------------------------------------------- Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
Sean McGrath - Sun Microsystems Ireland
2005-Dec-07 20:25 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
Bryan Cantrill stated: < < > Getting similar: < > kashyyyk:~/langs/c$ ./hr < > 1005641410 nanoseconds < > 2015600062 nanoseconds < > 3015650538 nanoseconds < > 4025609963 nanoseconds < > 5035611191 nanoseconds < > 6045649572 nanoseconds < > 7055610006 nanoseconds < > 8055655973 nanoseconds < > 9065621642 nanoseconds < > ^C < > kashyyyk:~/langs/c$ < < Odd; on my 3400, the D script that I sent gives the expected output. < What build are you running? (I''ve booted S10 GA at the moment.) And < are you running frkit? snv_28 and yes, running the frkit. John has 27a, I don''t know off hand if hes got the frkit on it. Sean. . < < - Bryan < < -------------------------------------------------------------------------- < Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
Sean McGrath - Sun Microsystems Ireland
2005-Dec-07 20:44 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
Thanks Seth, You got something there. I rem_drv''d the powernow driver, disabled the service, rebooted and now Byran''s deltas.d script is nice and neat: bash-3.00# ./deltas.d Difference in deltas : -928950 nanoseconds. Difference in deltas : -928375 nanoseconds. Difference in deltas : -928340 nanoseconds. Difference in deltas : -928658 nanoseconds. Difference in deltas : -927988 nanoseconds. Difference in deltas : -928414 nanoseconds. Difference in deltas : -928726 nanoseconds. Difference in deltas : -928112 nanoseconds. Difference in deltas : -928451 nanoseconds. Difference in deltas : -928160 nanoseconds. Difference in deltas : -928157 nanoseconds. Seth Goldberg stated: < < Try disabling the frkit''s cpu power component (preventing it from < switching frequencies). It may very well be that the timestamp counter in < the processor is changing tick rates when the core frequency is changing. < < --S < < On Wed, 7 Dec 2005, Sean McGrath - Sun Microsystems Ireland wrote: < < }Bryan Cantrill stated: < }< < }< > Getting similar: < }< > kashyyyk:~/langs/c$ ./hr < }< > 1005641410 nanoseconds < }< > 2015600062 nanoseconds < }< > 3015650538 nanoseconds < }< > 4025609963 nanoseconds < }< > 5035611191 nanoseconds < }< > 6045649572 nanoseconds < }< > 7055610006 nanoseconds < }< > 8055655973 nanoseconds < }< > 9065621642 nanoseconds < }< > ^C < }< > kashyyyk:~/langs/c$ < }< < }< Odd; on my 3400, the D script that I sent gives the expected output. < }< What build are you running? (I''ve booted S10 GA at the moment.) And < }< are you running frkit? < } < } snv_28 and yes, running the frkit. John has 27a, I don''t know off hand < } if hes got the frkit on it. < } < }Sean. < }. < }< < }< - Bryan < }< < }< -------------------------------------------------------------------------- < }< Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc < }_______________________________________________ < }dtrace-discuss mailing list < }dtrace-discuss at opensolaris.org < } -- Sean. . sean DoT mcgrath At sun.com http://blogs.sun.com/smg http://www.sun.com/software/solaris
Thanks Bryan, Sean and all,
I ran this test script from Charles LeBrac [similar to your own] to
confirm the issue. The high res timer is broken when powernow is enabled
on the Ferrari 3400 [nevada b27a]. You can see the difference below when
I change the powernow cpu stepper to be manual/ automatic.
Set to manual, no problems, small constant delta of 0.004 sec.
Set to automatic get a drift of up to 0.6 sec per sec.
JR
P.s. Yep I know I should have predicated on the necko_cache.xpt with
firefox-bin, but it''s a firefox specific XPCOM type library file
required by the Gecko engine, so safe enough though a little sloppy, par
+1 ;)
# powernowadm
State MHz Watts Volts
0 2000 35.0 1.350 (current)
1 1800 26.0 1.250
2 1600 21.0 1.200
3 800 9.0 0.975
Powernow mode: manual
# dtrace -s tick.d
855783450 859354220 -3570770
1855783486 1859354206 -3570720
2855783797 2859354324 -3570527
3855783558 3859354183 -3570625
4855783324 4859354290 -3570966
5855783713 5859354131 -3570418
6855783689 6859354228 -3570539
7855783725 7859354245 -3570520
8855783725 8859354135 -3570410
9855783396 9859354295 -3570899
10855783564 10859354118 -3570554
11855783803 11859354318 -3570515
12855783791 12859354117 -3570326
13855783498 13859354256 -3570758
14855783976 14859354344 -3570368
15855783623 15859354189 -3570566
16855783803 16859354360 -3570557
17855781169 17859354214 -3573045
18855783755 18859354279 -3570524
^C
# powernowadm automatic
# powernowadm
State MHz Watts Volts
0 2000 35.0 1.350
1 1800 26.0 1.250
2 1600 21.0 1.200
3 800 9.0 0.975 (current)
Powernow mode: automatic
# dtrace -s tick.d
475642618 909072670 -433430052
875642249 1909072326 -1033430077
1275642610 2909072710 -1633430100
1675642714 3909073366 -2233430652
2075642605 4909072378 -2833429773
2475642245 5909072612 -3433430367
2875642574 6909072636 -4033430062
3275642350 7909072524 -4633430174
3675642590 8909072750 -5233430160
4075642434 9909072779 -5833430345
4475642441 10909072362 -6433429921
4875642500 11909072693 -7033430193
5275642546 12909072566 -7633430020
5675642384 13909072356 -8233429972
6075642311 14909072840 -8833430529
6475642714 15909072828 -9433430114
6875642525 16909072407 -10033429882
7275642250 17909072661 -10633430411
7675396885 18909072633 -11233675748
8075642205 19909072409 -11833430204
8475642281 20909072842 -12433430561
8875642411 21909072881 -13033430470
9275642071 22909072632 -13633430561
9675642568 23909072433 -14233429865
^C
# cat tick.d
#!/usr/sbin/dtrace -s
#pragma D option quiet
BEGIN
{
ts = timestamp;
wts = walltimestamp;
}
tick-1s
{
this->dts = timestamp - ts;
this->dwts = walltimestamp - wts;
printf("%15d %15d %15d\n", this->dts, this->dwts,
(long) (this->dts - this->dwts));
}
Bryan Cantrill wrote:
>On Wed, Dec 07, 2005 at 04:57:57PM +0000, John Rice wrote:
>
>
>>People - we are doing some performance tests on Firefox startup times
>>and getting a little weirdness on the time differences reported looking
>>at timestamp and walltimestamp deltas.
>>
>>Can anyone shed any light on this?
>>
>>
>
>This is odd. One would expect deltas in walltimestamp and timestamp
>to (1) not be identical and (2) to drift a bit, but this kind of
>difference is unexpected. Your script is a bit odd, and in particular
>it doesn''t predicate on the thread-local variables (if _anyone_
opens
>necko_cache.xpt it will report the deltas, even if the thread that opened
>it isn''t the thread that exec''d firefox, or isn''t
firefox at all). Still,
>if this were your problem you would expect numbers that are wildly
>wrong, not just drifting. Just for sanity''s sake, run this script
>on the machine:
>
>---8<--- deltas.d ---8<---
>
>#pragma D option quiet
>
>BEGIN
>{
> ts = timestamp;
> wall = walltimestamp;
>}
>
>tick-1sec
>{
> this->dts = timestamp - ts;
> this->dwall = walltimestamp - wall;
>
> printf("Difference in deltas : %10d nanoseconds.\n",
> (int64_t)this->dts - (int64_t)this->dwall);
>}
>
>---8<--- deltas.d ---8<---
>
>If this script shows huge or wildly diverging deltas, there might be
>something busted in either the hardware and/or the TOD chip. (When I run
>the above on a few test machines, I see the expected output: smallish and
>roughly constant numbers.)
>
> - Bryan
>
>--------------------------------------------------------------------------
>Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc
>_______________________________________________
>dtrace-discuss mailing list
>dtrace-discuss at opensolaris.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20051208/6c73d9e6/attachment.html>
John Rice wrote:> Thanks Bryan, Sean and all, > > I ran this test script from Charles LeBrac [similar to your own] to > confirm the issue. The high res timer is broken when powernow is enabled > on the Ferrari 3400 [nevada b27a].(hindsight: of course it is. powernow isn''t yet a part of Solaris. You get what you QA for.)
Keith Cantrell
2005-Dec-08 15:14 UTC
[dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]
All, I forwarded this Email to the creator of powernow and below was his response. Regards, Keith ----------------------------------------------------------------- Keith Cantrell Sun Microsystems Solution Architect/OS Ambassador Dallas, TX Email: Keith.cantrell at sun.com Phone: 972-392-5014 ----------------------------------------------------------------- -------- Original Message -------- Subject: Re: [Fwd: Re: [dtrace-discuss] [Fwd: Firefox DTrace Timing strangeness]] Date: Thu, 08 Dec 2005 15:56:11 +0100 From: Casper To: Keith Cantrell <Keith.Cantrell at Sun.COM> > > Not sure if you saw this, but apparently setting powernowd into automatic mode > breaks the high res timer. See the below Email thread for more detail. It breaks the dtrace highres timer because it cannot be interposed. It does not break the other highres timers (not that badly, anyway) Casper John Rice wrote:> Thanks Bryan, Sean and all, > > I ran this test script from Charles LeBrac [similar to your own] to > confirm the issue. The high res timer is broken when powernow is enabled > on the Ferrari 3400 [nevada b27a]. You can see the difference below when > I change the powernow cpu stepper to be manual/ automatic. > > Set to manual, no problems, small constant delta of 0.004 sec. > Set to automatic get a drift of up to 0.6 sec per sec. > > JR > > P.s. Yep I know I should have predicated on the necko_cache.xpt with > firefox-bin, but it''s a firefox specific XPCOM type library file > required by the Gecko engine, so safe enough though a little sloppy, par > +1 ;) > > # powernowadm > State MHz Watts Volts > 0 2000 35.0 1.350 (current) > 1 1800 26.0 1.250 > 2 1600 21.0 1.200 > 3 800 9.0 0.975 > > Powernow mode: manual > # dtrace -s tick.d > 855783450 859354220 -3570770 > 1855783486 1859354206 -3570720 > 2855783797 2859354324 -3570527 > 3855783558 3859354183 -3570625 > 4855783324 4859354290 -3570966 > 5855783713 5859354131 -3570418 > 6855783689 6859354228 -3570539 > 7855783725 7859354245 -3570520 > 8855783725 8859354135 -3570410 > 9855783396 9859354295 -3570899 > 10855783564 10859354118 -3570554 > 11855783803 11859354318 -3570515 > 12855783791 12859354117 -3570326 > 13855783498 13859354256 -3570758 > 14855783976 14859354344 -3570368 > 15855783623 15859354189 -3570566 > 16855783803 16859354360 -3570557 > 17855781169 17859354214 -3573045 > 18855783755 18859354279 -3570524 > ^C > > # powernowadm automatic > # powernowadm > State MHz Watts Volts > 0 2000 35.0 1.350 > 1 1800 26.0 1.250 > 2 1600 21.0 1.200 > 3 800 9.0 0.975 (current) > > Powernow mode: automatic > # dtrace -s tick.d > 475642618 909072670 -433430052 > 875642249 1909072326 -1033430077 > 1275642610 2909072710 -1633430100 > 1675642714 3909073366 -2233430652 > 2075642605 4909072378 -2833429773 > 2475642245 5909072612 -3433430367 > 2875642574 6909072636 -4033430062 > 3275642350 7909072524 -4633430174 > 3675642590 8909072750 -5233430160 > 4075642434 9909072779 -5833430345 > 4475642441 10909072362 -6433429921 > 4875642500 11909072693 -7033430193 > 5275642546 12909072566 -7633430020 > 5675642384 13909072356 -8233429972 > 6075642311 14909072840 -8833430529 > 6475642714 15909072828 -9433430114 > 6875642525 16909072407 -10033429882 > 7275642250 17909072661 -10633430411 > 7675396885 18909072633 -11233675748 > 8075642205 19909072409 -11833430204 > 8475642281 20909072842 -12433430561 > 8875642411 21909072881 -13033430470 > 9275642071 22909072632 -13633430561 > 9675642568 23909072433 -14233429865 > ^C > > # cat tick.d > #!/usr/sbin/dtrace -s > > #pragma D option quiet > > BEGIN > { > ts = timestamp; > wts = walltimestamp; > } > > tick-1s > { > this->dts = timestamp - ts; > this->dwts = walltimestamp - wts; > printf("%15d %15d %15d\n", this->dts, this->dwts, > (long) (this->dts - this->dwts)); > } > > > Bryan Cantrill wrote: > >>On Wed, Dec 07, 2005 at 04:57:57PM +0000, John Rice wrote: >> >> >>>People - we are doing some performance tests on Firefox startup times >>>and getting a little weirdness on the time differences reported looking >>>at timestamp and walltimestamp deltas. >>> >>>Can anyone shed any light on this? >>> >>> >> >>This is odd. One would expect deltas in walltimestamp and timestamp >>to (1) not be identical and (2) to drift a bit, but this kind of >>difference is unexpected. Your script is a bit odd, and in particular >>it doesn''t predicate on the thread-local variables (if _anyone_ opens >>necko_cache.xpt it will report the deltas, even if the thread that opened >>it isn''t the thread that exec''d firefox, or isn''t firefox at all). Still, >>if this were your problem you would expect numbers that are wildly >>wrong, not just drifting. Just for sanity''s sake, run this script >>on the machine: >> >>---8<--- deltas.d ---8<--- >> >>#pragma D option quiet >> >>BEGIN >>{ >> ts = timestamp; >> wall = walltimestamp; >>} >> >>tick-1sec >>{ >> this->dts = timestamp - ts; >> this->dwall = walltimestamp - wall; >> >> printf("Difference in deltas : %10d nanoseconds.\n", >> (int64_t)this->dts - (int64_t)this->dwall); >>} >> >>---8<--- deltas.d ---8<--- >> >>If this script shows huge or wildly diverging deltas, there might be >>something busted in either the hardware and/or the TOD chip. (When I run >>the above on a few test machines, I see the expected output: smallish and >>roughly constant numbers.) >> >> - Bryan >> >>-------------------------------------------------------------------------- >>Bryan Cantrill, Solaris Kernel Development. http://blogs.sun.com/bmc >>_______________________________________________ >>dtrace-discuss mailing list >>dtrace-discuss at opensolaris.org >> >> > > > ------------------------------------------------------------------------ > > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org