sub-millisecond timings
aHeckman
javascript Date obj has left me wanting more detail. Is there any
interest in extending date to provide more fine grained (sub-
millisecond) timings for server side profiling? Anyone know how we
could accomplish something like that?
Louis Santillan
need to be exposed.
-L
> --
> You received this message because you are subscribed to the Google Groups "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/nodejs?hl=en.
>
>
Elijah Insua
Marak Squires
Morgan Allen
.......It's a sweater!
http://www.alleycatracing.com
LTABOTIIOFR! ROFL! ROFL! ROFL!
Upcoming alley cats, reviews, touring logs, and a general congregation of bike nerdity.
Aaron Heckmann
Elijah Insua
tjholowaychuk
keep express away from c++, which means ext too but
looks cool
On Mar 19, 2:31 pm, Elijah Insua <tmp...@gmail.com> wrote:
> On what os?
>
> On Fri, Mar 19, 2010 at 3:23 PM, Morgan Allen <morganral...@gmail.com>wrote:
>
>
>
> > This worked...
>
> > for(var i = 0; i < 100000; i++) {
> > var t1 = microseconds();
> > var t2 = microseconds();
> > if(t1 === t2) throw new Error("Uh OH");
> > }
>
> > On Fri, Mar 19, 2010 at 12:15 PM, Marak Squires <marak.squi...@gmail.com>wrote:
>
> >> Does this mean I can do something like
>
> >> var myUniqueID = microseconds();
> >> var myOtherUniqueID = microseconds();
>
> >> and be guaranteed that myUniqueID and myOtherUniqueID will always
> >> be different?
>
> >> On Fri, Mar 19, 2010 at 3:11 PM, Elijah Insua <tmp...@gmail.com> wrote:
>
> >>> I just had to. ~15 minutes of work and we now have
> >>>http://github.com/tmpvar/node-microseconds
>
> >>> Let me know what you think!
>
> >>> -- Elijah
>
> >>> On Fri, Mar 19, 2010 at 2:09 PM, Louis Santillan <lpsan...@gmail.com>wrote:
>
> >>>> Posix gettimeofday returns microsec (1/1000 millisec). That would
> >>>> need to be exposed.
>
> >>>> -L
>
> >>>> On Fri, Mar 19, 2010 at 11:05 AM, aHeckman <aaron.heckm...@gmail.com>
> >>>> wrote:
> >>>> > After working with request loggers and uids for Express, the
> >>>> > javascript Date obj has left me wanting more detail. Is there any
> >>>> > interest in extending date to provide more fine grained (sub-
> >>>> > millisecond) timings for server side profiling? Anyone know how we
> >>>> > could accomplish something like that?
>
> >>>> > --
> >>>> > You received this message because you are subscribed to the Google
> >>>> Groups "nodejs" group.
> >>>> > To post to this group, send email to nod...@googlegroups.com.
> >>>> > To unsubscribe from this group, send email to
> >>>> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> >>>> .
> >>>> > For more options, visit this group at
> >>>>http://groups.google.com/group/nodejs?hl=en.
>
> >>>> --
> >>>> You received this message because you are subscribed to the Google
> >>>> Groups "nodejs" group.
> >>>> To post to this group, send email to nod...@googlegroups.com.
> >>>> To unsubscribe from this group, send email to
> >>>> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> >>>> .
> >>>> For more options, visit this group at
> >>>>http://groups.google.com/group/nodejs?hl=en.
>
> >>> --
> >>> You received this message because you are subscribed to the Google Groups
> >>> "nodejs" group.
> >>> To post to this group, send email to nod...@googlegroups.com.
> >>> To unsubscribe from this group, send email to
> >>> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> >>> .
> >>> For more options, visit this group at
> >>>http://groups.google.com/group/nodejs?hl=en.
>
> >> --
> >> You received this message because you are subscribed to the Google Groups
> >> "nodejs" group.
> >> To post to this group, send email to nod...@googlegroups.com.
> >> To unsubscribe from this group, send email to
> >> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> >> .
> >> For more options, visit this group at
> >>http://groups.google.com/group/nodejs?hl=en.
>
> > --
> >http://morglog.org
> > .......It's a sweater!
>
> >http://www.alleycatracing.com
> > LTABOTIIOFR! ROFL! ROFL! ROFL!
> > Upcoming alley cats, reviews, touring logs, and a general congregation of
> > bike nerdity.
>
> > --
> > You received this message because you are subscribed to the Google Groups
> > "nodejs" group.
> > To post to this group, send email to nod...@googlegroups.com.
> > To unsubscribe from this group, send email to
> > nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
Elijah Insua
To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
Zoka
seconds, something like this:
double get_seconds(void)
{
struct timeval tv;
gettimeofday(&tv, NULL);
return (double) tv.tv_sec + (double)tv.tv_usec/100000.0;
}
Floating point operations on contemporary CPUs are very fast.
On Mar 20, 8:55 am, Elijah Insua <tmp...@gmail.com> wrote:
> I made an update to this addon:
>
> - it actually returns microseconds now ^_^ (no more decimals)
> - updated the sanity check to compare results against setTimeout (super
> scientific!)
>
> Aso:
>
> @Marak: I wouldn't trust this to give you unique ids. unfortunately there
> is a margin of error.
>
> @Morgan: I'd like to know what you mean by it works.. on my end the
> exception is thrown for 9000+ iterations (what os are you testing on, etc?)
>
> -- Elijah
>
> > <nodejs%2Bunsu...@googlegroups.com<nodejs%252Buns...@googlegroups.com>
>
> > > >>>> .
> > > >>>> > For more options, visit this group at
> > > >>>>http://groups.google.com/group/nodejs?hl=en.
>
> > > >>>> --
> > > >>>> You received this message because you are subscribed to the Google
> > > >>>> Groups "nodejs" group.
> > > >>>> To post to this group, send email to nod...@googlegroups.com.
> > > >>>> To unsubscribe from this group, send email to
> > > >>>> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> > <nodejs%2Bunsu...@googlegroups.com<nodejs%252Buns...@googlegroups.com>
>
> > > >>>> .
> > > >>>> For more options, visit this group at
> > > >>>>http://groups.google.com/group/nodejs?hl=en.
>
> > > >>> --
> > > >>> You received this message because you are subscribed to the Google
> > Groups
> > > >>> "nodejs" group.
> > > >>> To post to this group, send email to nod...@googlegroups.com.
> > > >>> To unsubscribe from this group, send email to
> > > >>> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> > <nodejs%2Bunsu...@googlegroups.com<nodejs%252Buns...@googlegroups.com>
>
> > > >>> .
> > > >>> For more options, visit this group at
> > > >>>http://groups.google.com/group/nodejs?hl=en.
>
> > > >> --
> > > >> You received this message because you are subscribed to the Google
> > Groups
> > > >> "nodejs" group.
> > > >> To post to this group, send email to nod...@googlegroups.com.
> > > >> To unsubscribe from this group, send email to
> > > >> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> > <nodejs%2Bunsu...@googlegroups.com<nodejs%252Buns...@googlegroups.com>
>
> > > >> .
> > > >> For more options, visit this group at
> > > >>http://groups.google.com/group/nodejs?hl=en.
>
> > > > --
> > > >http://morglog.org
> > > > .......It's a sweater!
>
> > > >http://www.alleycatracing.com
> > > > LTABOTIIOFR! ROFL! ROFL! ROFL!
> > > > Upcoming alley cats, reviews, touring logs, and a general congregation
> > of
> > > > bike nerdity.
>
> > > > --
> > > > You received this message because you are subscribed to the Google
> > Groups
> > > > "nodejs" group.
> > > > To post to this group, send email to nod...@googlegroups.com.
> > > > To unsubscribe from this group, send email to
> > > > nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
> > <nodejs%2Bunsu...@googlegroups.com<nodejs%252Buns...@googlegroups.com>
Morgan Allen
Elijah Insua
I meant it works as in t1 never equals t2Linux, AMD64
Ryan Dahl
> Since double is default type in JS maybe you should return just
> seconds, something like this:
>
> double get_seconds(void)
> {
> struct timeval tv;
> gettimeofday(&tv, NULL);
> return (double) tv.tv_sec + (double)tv.tv_usec/100000.0;
> }
>
> Floating point operations on contemporary CPUs are very fast.
Node uses millisecond resolution everywhere (because setTimeout is
defined to take milliseconds in the w3 spec), so that'd be best imo.
Louis Santillan
(setUTimeout(t, cb) = setTimeout( t * 1000, cb )) and many
i386s/x86-64s are more than capable of processing V8 with that kind of
resolution. From my experience with V8, my Q8400 can do ~5-10
microsec (or 1/100 of a millisec) quite easily in 10.6.2. Such
resolution could be useful for CPU-bound apps or apps that would like
thinner time slices. This is with a very naive event loop written in
JS.
-L
> --
> You received this message because you are subscribed to the Google Groups "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
Elijah Insua
Joran Greef
it makes simple things like Number.seconds, Number.hours etc.
possible: one could pass (60).seconds() as an argument to a config
function, (2).hours() for a job that needs to repeat every 2 hours
etc. With no base unit it's not possible.
Louis Santillan
you want to operate on timeval.tv_* as longs. Significant bits can
get truncated if you don't.
-L
Louis Santillan
Zoka
floating point format) are only useful for time measurement, not for
timer scheduling functions such as setTimeout().
Having such function would be nice for general Node performance
indication:
record events/second or events/minute and also measure average/min/max
event processing time over last second/minute.
On Mar 20, 9:38 am, Ryan Dahl <coldredle...@gmail.com> wrote:
Zoka
long gcc type and then it comes problematic since JS integer
precission goes only to 53 bits IRC. That is why I would prefer double
values for time measurement.
On Mar 20, 10:15 am, Louis Santillan <lpsan...@gmail.com> wrote:
> BTW, Number:New( long ) works.
>
> On Fri, Mar 19, 2010 at 4:13 PM, Louis Santillan <lpsan...@gmail.com> wrote:
> > Two things. Firstly, gettimeofday can return -1 (error). Secondly,
> > you want to operate on timeval.tv_* as longs. Significant bits can
> > get truncated if you don't.
>
> > -L
>
> > On Fri, Mar 19, 2010 at 3:54 PM, Elijah Insua <tmp...@gmail.com> wrote:
> >> Added seconds and milliseconds.
> >> Currently the sanity.js fails:
> >> Microseconds: 1269038949795161
> >> Seconds: 1269038949.795198
> >> Milliseconds: 1269038949795.215
> >> Error: bla: 2
> >> at Object.<anonymous>
> >> (/Users/tmpvar/work/c/node-microseconds/test/sanity.js:15:11)
> >> at Module._compile (node.js:719:23)
> >> at node.js:750:20
> >> at fs:51:23
> >> at node.js:811:9
> >> the exception is never thrown with i > 3 .. is there something I'm missing
> >> about the internals of v8 and its optimizations? It appears as though every
> >> call to gettimeofday() takes ~6us which does not appear to be the case in a
> >> loop. Any suggestions?
> >> -- Elijah
> >> On Fri, Mar 19, 2010 at 6:52 PM, Louis Santillan <lpsan...@gmail.com> wrote:
>
> >>> setTimeout/et. al. can easily be implemented using microsec resolution
> >>> (setUTimeout(t, cb) = setTimeout( t * 1000, cb )) and many
> >>> i386s/x86-64s are more than capable of processing V8 with that kind of
> >>> resolution. From my experience with V8, my Q8400 can do ~5-10
> >>> microsec (or 1/100 of a millisec) quite easily in 10.6.2. Such
> >>> resolution could be useful for CPU-bound apps or apps that would like
> >>> thinner time slices. This is with a very naive event loop written in
> >>> JS.
>
> >>> -L
>
> >>> On Fri, Mar 19, 2010 at 3:38 PM, Ryan Dahl <coldredle...@gmail.com> wrote:
Aaron Heckmann
The microsecond precision timing functions (either in integer of
floating point format) are only useful for time measurement, not for
timer scheduling functions such as setTimeout().
Having such function would be nice for general Node performance
indication:
record events/second or events/minute and also measure average/min/max
event processing time over last second/minute.
Elijah Insua
--
You received this message because you are subscribed to the Google Groups "nodejs" group.
To post to this group, send email to nod...@googlegroups.com.
To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
Zoka
Have look at the code and comments at http://gist.github.com/340921
To summarize, I think we only need one method for time measurement -
one that returns seconds since 1/1/1970 in double format. If one
desires millisconds then simple division with 1000.0 will be good
enough. Integer microseconds() method works by accident for intervals
up to around bit more than on hour.
In fact, this method, together with methods that measure events per
second/minute and event processing load per second/minute should be
part of the Node.js itself.
Regards
Zoka
On Mar 23, 1:44 pm, Elijah Insua <tmp...@gmail.com> wrote:
> ok, can anyone offer me some concrete suggestions about the current
> implementation?http://github.com/tmpvar/node-microseconds
>
> <http://github.com/tmpvar/node-microseconds>Preferably things I'm doing
> wrong/could be doing better.
>
> Thanks,
> -- Elijah
>
> On Fri, Mar 19, 2010 at 8:07 PM, Aaron Heckmann <aaron.heckm...@gmail.com>wrote:
>
>
>
> > The microsecond precision timing functions (either in integer of
> >> floating point format) are only useful for time measurement, not for
> >> timer scheduling functions such as setTimeout().
>
> >> Having such function would be nice for general Node performance
> >> indication:
>
> >> record events/second or events/minute and also measure average/min/max
> >> event processing time over last second/minute.
>
> > Exactly why I brought it up.
>
> > --
> > You received this message because you are subscribed to the Google Groups
> > "nodejs" group.
> > To post to this group, send email to nod...@googlegroups.com.
> > To unsubscribe from this group, send email to
> > nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
Joran Greef
in milliseconds. Milliseconds is the base unit for all other
Javascript apis that work with time.
Aaron Heckmann
+1 part of node
> --
> You received this message because you are subscribed to the Google Groups
> "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to
> nodejs+un...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/nodejs?hl=en.
>
>
--
Sent from my mobile device
Aaron
Zoka
is better choice.
Ryan Dahl
> Hi,
>
> Have look at the code and comments at http://gist.github.com/340921
>
> To summarize, I think we only need one method for time measurement -
> one that returns seconds since 1/1/1970 in double format. If one
> desires millisconds then simple division with 1000.0 will be good
> enough. Integer microseconds() method works by accident for intervals
> up to around bit more than on hour.
>
> In fact, this method, together with methods that measure events per
> second/minute and event processing load per second/minute should be
> part of the Node.js itself.
Recently I added 'process.now' which is a getter to return the seconds
since the epoch. It's a binding to ev_now(), which does not make a
system call, and is only updated once per loop.
Matthew Ranney
Recently I added 'process.now' which is a getter to return the seconds
since the epoch. It's a binding to ev_now(), which does not make a
system call, and is only updated once per loop.
Elijah Insua
--
You received this message because you are subscribed to the Google Groups "nodejs" group.
To post to this group, send email to nod...@googlegroups.com.
To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
Zoka
return same result, making your test code fail.
Try this little program:
#include <stdio.h>
#include <unistd.h>
#include <sys/time.h>
// compile: g++ -o tdiff tdiff.cc
int main() {
int i;
static int diff[100];
for (i = 0; i < 1000000; i++)
{
timeval first, second;
long long f,s;
gettimeofday(&first, NULL);
gettimeofday(&second, NULL);
f = (long long) first.tv_sec * 1000000 + first.tv_usec;
s = (long long) second.tv_sec * 1000000 + second.tv_usec;
int d = (int) (s-f);
if (d < 100)
diff[d]++;
else
printf("Huge diff: %d usec !!!\n", d);
}
printf("Consecutive gettimeofday() statistics\n");
printf("for 1000000 invocations:\n");
for (i = 0; i < 100; i++)
if (diff[i])
printf("%3d usec ... %6d times\n", i, diff[i]);
}
Program output:
Consecutive gettimeofday() statistics
for 1000000 invocations:
0 usec ... 951188 times
1 usec ... 48803 times
2 usec ... 2 times
3 usec ... 5 times
8 usec ... 1 times
12 usec ... 1 times
Regards
Zoka
On Mar 27, 7:19 pm, Elijah Insua <tmp...@gmail.com> wrote:
> So, I've removed the microseconds and seconds methods, If anyone has any
> other changes that they'd like to see please provide a patch.
>
> The following loop still fails:
>
> for (var i=0; i<1000; i++)
> {
> var m1 = microseconds.milliseconds();
> var m2 = microseconds.milliseconds();
> if (m1 === m2) {
> throw new Error("bla: " + i);
> }
>
> }
>
> On my machine it never gets past the 3rd iteration.. which makes no
> sense. I'm running out of time to deal with this, and in my opinion this
> would probably be used over a period of time rather than called multiple
> times in sequence.
>
> I am open to suggestions, and especially patches...
> -- Elijah
>
> On Tue, Mar 23, 2010 at 11:27 AM, Matthew Ranney <m...@ranney.com> wrote:
> > On Tue, Mar 23, 2010 at 8:21 AM, Ryan Dahl <coldredle...@gmail.com> wrote:
>
> >> Recently I added 'process.now' which is a getter to return the seconds
> >> since the epoch. It's a binding to ev_now(), which does not make a
> >> system call, and is only updated once per loop.
>
> > That's cool, but it makes it hard to use for profiling, which I thought was
> > the point of sub-ms timing.
>
> > --
> > You received this message because you are subscribed to the Google Groups
> > "nodejs" group.
> > To post to this group, send email to nod...@googlegroups.com.
> > To unsubscribe from this group, send email to
> > nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
Jorge
But I wonder whether it's safe to use gettimeofday() for this purpose, because :
27/03/10 00:32:49 ntpd[13] time reset -0.546761 s
27/03/10 02:42:49 ntpd[13] time reset +0.435814 s
What happens when/if the system resets the time ?
--
Jorge.
Zoka
an unspecified base (usually since power up). This means that the
returned value would have to be be used strictly for time measurement,
not to be interchangeable with JavaScript time as an absolute value. I
do not see this as a big problem since sub millisecond is meant to be
used only for elapsed time calculation.
Note that OS X does not have clock_gettime() but there is replacement
at:
http://le-depotoir.googlecode.com/svn/trunk/misc/clock_gettime_stub.c
Zoka
Zoka
Unfortunately OS X clock_gettime() replacement is horribly
inefficient, about 1000x slower:
Consecutive clock_gettime(CLOCK_MONOTONIC, ..) statistics
for 1000000 invocations:
5 usec ... 990124 times
6 usec ... 753 times
7 usec ... 1148 times
8 usec ... 2041 times
9 usec ... 2659 times
10 usec ... 3029 times
11 usec ... 41 times
12 usec ... 47 times
13 usec ... 32 times
14 usec ... 23 times
15 usec ... 14 times
16 usec ... 9 times
17 usec ... 6 times
18 usec ... 12 times
19 usec ... 5 times
20 usec ... 14 times
21 usec ... 11 times
22 usec ... 6 times
24 usec ... 2 times
25 usec ... 2 times
26 usec ... 1 times
27 usec ... 1 times
28 usec ... 2 times
29 usec ... 1 times
30 usec ... 1 times
31 usec ... 3 times
32 usec ... 1 times
33 usec ... 1 times
34 usec ... 3 times
35 usec ... 1 times
38 usec ... 1 times
39 usec ... 1 times
40 usec ... 1 times
47 usec ... 1 times
48 usec ... 1 times
63 usec ... 1 times
80 usec ... 1 times
Zoka
once the right mach system call is used:
#include <mach/mach_time.h>
#include <time.h>
#include <stdio.h>
#include <unistd.h>
// compile: g++ -o mondiff mondiff.cc
static mach_timebase_info_data_t __clock_gettime_inf;
void osx_monotonic_time(timespec* tp) {
uint64_t now,nano;
now = mach_absolute_time();
if (0 == __clock_gettime_inf.denom)
mach_timebase_info(&__clock_gettime_inf);
nano = now * __clock_gettime_inf.numer / __clock_gettime_inf.denom;
tp->tv_sec = nano * 1e-9;
tp->tv_nsec = nano - (tp->tv_sec * 1e9);
}
int main() {
int i;
static int diff[100];
timespec first, second;
long long f,s, delta;
for (i = 0; i < 1000000; i++)
{
osx_monotonic_time(&first);
osx_monotonic_time(&second);
f = (long long) first.tv_sec * 1000000000 + first.tv_nsec;
s = (long long) second.tv_sec * 1000000000 + second.tv_nsec;
int d = (int) (s-f)/1000;
if (d < 100)
diff[d]++;
else
printf("Huge diff: %d usec !!!\n", d);
}
printf("Consecutive osx_monotonic_time statistics\n");
printf("for 1000000 invocations:\n");
for (i = 0; i < 100; i++)
if (diff[i])
printf("%6d usec ... %6d times\n", i, diff[i]);
}
Output:
Consecutive osx_monotonic_time statistics
for 1000000 invocations:
0 usec ... 999893 times
1 usec ... 10 times
2 usec ... 13 times
3 usec ... 40 times
4 usec ... 8 times
5 usec ... 2 times
6 usec ... 4 times
7 usec ... 3 times
8 usec ... 13 times
9 usec ... 4 times
11 usec ... 1 times
12 usec ... 1 times
13 usec ... 3 times
15 usec ... 2 times
17 usec ... 1 times
20 usec ... 1 times
25 usec ... 1 times
Zoka
Monotonic time functions are way to go. Have look at http://gist.github.com/346357
The system call to get monotonic time usually takes less than 300 nsec
on Linux and less than 90 nsec on OS X - so the overhead is
negligible.
Also, since the result has nanosecond precision, the original
problematic test should not fail unexpectedly.
Elijah Insua
--
You received this message because you are subscribed to the Google Groups "nodejs" group.
To post to this group, send email to nod...@googlegroups.com.
To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
Aaron Heckmann
>> nodejs+un...@googlegroups.com<nodejs%2Bunsu...@googlegroups.com>
>> .
>> For more options, visit this group at
>> http://groups.google.com/group/nodejs?hl=en.
>>
>>
>
> --
> You received this message because you are subscribed to the Google Groups
> "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to
> nodejs+un...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/nodejs?hl=en.
>
>
--
Zoka
Here is the preliminary oroof of concept patch add sub-millisecond
timing to Node itself:
http://gist.github.com/346669.
Monotonic time functions were used (they have better precision and are
not susceptible to external system clock changes such as ntp or
administrator intervention). They provide fixed timing reference,
usually since OS was restarted. Better starting reference point from
Node point of view would be the application uptime - the time elapsed
since Node app started in milliseconds, returned as double floating
point format number. The Uptime() function was initially tested in
little C++ program uptime_test.cc - and then integrated into node.cc
and tested again in uptime_test.js. Note that process.uptime() is
roughly 2 times slower than pure C++ equivalent and has 4 time wider
dispersion of values (OS X).
Regards
Zoka
Jorge
Hi Zoka,
Bully !
It looks good to me. mach_absolute_time() is a discovery...
However, as the value must fit into a fp double, and the mantissa is 53 bits, an integer (double) count of ns will overflow after (2^53)/1e9/60/60/24 === 104 days.
So, maybe, it would be better to return an integer count of µs with fractional ns, so that it won't overflow until after 104000 days (284 years).
That is, ns/1e3. In this way we would just lose precision in the ns fractional part as the count grows higher, but the integer µs part would always be correct.
Or maybe just return integer µs:
return (double) ((uint64_t) (mach_absolute_time() * __clock_gettime_inf.numer / __clock_gettime_inf.denom / 1e3));
Don't you think so ?
--
Jorge.
Jorge
> (...)
> Or maybe just return integer µs:
>
> return (double) ((uint64_t) (mach_absolute_time() * __clock_gettime_inf.numer / __clock_gettime_inf.denom / 1e3));
>
#include <stdio.h>
#include <sys/time.h>
#include <mach/mach_time.h>
#include <unistd.h>
int main (int argc, const char * argv[]) {
double curr, prev;
mach_timebase_info_data_t __clock_gettime_inf;
mach_timebase_info(&__clock_gettime_inf);
while (1) {
curr= (double) ((uint64_t) (mach_absolute_time() *
__clock_gettime_inf.numer / __clock_gettime_inf.denom / 1e3));
fprintf(stdout, "%f, diff:%0.0fµs\n", curr, curr-prev);
prev= curr;
}
}
-->
2279502391826.000000, diff:0µs
2279502391830.000000, diff:4µs
2279502391833.000000, diff:3µs
2279502391837.000000, diff:4µs
2279502391841.000000, diff:4µs
2279502391844.000000, diff:3µs
2279502391848.000000, diff:4µs
2279502391851.000000, diff:3µs
2279502391855.000000, diff:4µs
2279502391858.000000, diff:3µs
.
.
.
--
Jorge.
Zoka
Floating point numbers with finite size mantissa do not overflow until
maximum size of exponent is reached - instead they just loose
precision.
After 104 days nanosecond precision will drop to 52 bits, after 208
days it will drop to 51 bit - it will gradually degrade. Have look at
the consecutive call statistics in http://gist.github.com/346669 for
uptime_test.cc that has much narrower dispersion than uptime_test.js.
This pretty ideal setup (single thread application on lightly loaded
OS X) still has about +- 3.5 nsec noise (72 to 79 nsec) for roughly
90% of samples. More realistic results for the sill very simple real
Node app uptime_test.js show even more noise - therefore it seems that
we should not be worried too much about loss of precision in real
world environment.
However - there is deficiency how startup_time is handled - it should
be kept as an 64-bit integer, so the Node app timing precision does
not depend on time elapsed between OS restart and Node app start.
Zoka
Jorge
On 28/03/2010, at 18:49, Zoka wrote:
> Hi Jorge,
>
> Floating point numbers with finite size mantissa do not overflow until
> maximum size of exponent is reached - instead they just loose
> precision.
>
> After 104 days nanosecond precision will drop to 52 bits, after 208
> days it will drop to 51 bit - it will gradually degrade. Have look at
> the consecutive call statistics in http://gist.github.com/346669
Ooops, I see now that you're already dividing the ns count by 1e6:
27 + return (double) nano * 1e-6;
I was proposing instead to divide by 1e3 to return integer µs.
> (...)
--
Jorge.
Ryan Dahl
Looks good to me!
We should put a benchmarks/ script together which outputs the mean and
variance of the uptime_test.js stats. It might expose some programs if
the mean suddenly jumped. We've got the buildbots running those
scripts on each commit to produce graphs:
http://buildbot.nodejs.org:8010/perf/dashboard/overview.html
(It might also make sense to move the startup_time to an earlier part
of the process - like the first thing in main()... Then we can measure
how fast V8 is spending.)
Aaron Heckmann
> --
> You received this message because you are subscribed to the Google Groups
> "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to
> nodejs+un...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/nodejs?hl=en.
>
>
--
Jorge
> Hi Jorge,
>
> (...)
>
> However - there is deficiency how startup_time is handled - it should
> be kept as an 64-bit integer, so the Node app timing precision does
> not depend on time elapsed between OS restart and Node app start.
I think a JS API like this would be nice:
//NodeTimer: JS / C pseudo-code:
function NodeTimer () {
//Constructor
uint64_t startUpTime= get_ns();
function get_ns () {
return (uint64_t) (mach_absolute_time() * clkInfo.numer / clkInfo.denom);
}
this.s= function () {
return (double) (uint64_t) ((get_ns()- startUpTime) / 1e9);
//returns integer elapsed seconds
}
this.ms= function () {
return (double) (uint64_t) ((get_ns- startUpTime) / 1e6);
//returns integer elapsed ms
};
this.µs= function () {
return (double) (uint64_t) ((get_ns()- startUpTime) / 1e3);
//returns integer elapsed µs
//begins to misbehave after (2^53)/1e6/60/60/24/365 ~= 285 years
};
this.ns= function () {
return (double) (get_ns()- startUpTime);
//returns integer elapsed ns
//begins to misbehave after (2^53)/1e9/60/60/24 ~= 104 days
};
this.timeSpec= function () {
var t= (uint64_t) (get_ns()- startUpTime);
return {
s: (double) (uint64_t) (t / 1e9),
ms: (double) (uint64_t) (t / 1e6),
µs: (double) (uint64_t) (t / 1e3),
ns: (double) t,
}
}
}
//JS test code
var myTimer= new NodeTimer(); //Starts a timer
do {
var now= myTimer.timeSpec();
console.log([now.s, now.ms, now.µs, now.ns]);
} while (now.s < 10);
--
Jorge.
Jorge Chamorro
> (...)
> //JS test code
>
> var myTimer= new NodeTimer(); //Starts a timer
> do {
> var now= myTimer.timeSpec();
> console.log([now.s, now.ms, now.µs, now.ns]);
> } while (now.s < 10);
s/console.log/puts/ ... :-)
--
Jorge.
Jorge
> (...)
> This pretty ideal setup (single thread application on lightly loaded
> OS X) still has about +- 3.5 nsec noise (72 to 79 nsec) for roughly
> 90% of samples. More realistic results for the sill very simple real
> Node app uptime_test.js show even more noise - therefore it seems that
> we should not be worried too much about loss of precision in real
> world environment.
I'm not sure I would call that "noise". I think it's a precise reading
of what the code is actually doing in reality: 1ns is the period of
1GHz, and in such a short time not many instructions can be executed,
and any interrupts, context switches, cpu cache misses or whatever are
just going to be reflected in hi-fi when reading a ns hardware counter
that never ever misses a count.
--
Jorge.
Ryan Dahl
Maybe we should use this:
http://le-depotoir.googlecode.com/svn/trunk/misc/clock_gettime_stub.c
And allow libev to access it, somehow. Then we could call
ev_now_update() or ev_now() to implement process.uptime().
Jorge
<quote>
* we could get the ticks by doing this
*
* __asm __volatile("mov %%ebx, %%esi\n\t"
* "cpuid\n\t"
* "xchg %%esi, %%ebx\n\t"
* "rdtsc"
* : "=a" (a),
* "=d" (d)
* );
</quote>
Are you really willing to dig so much deeper ?
And to maintain it ?
Across different cpus ?
Across different OSs ?
Don't you prefer to leave that for Linus ?
(ha ha ha, there's no need to answer :-)
http://www.google.com/search?q=rdtsc+filetype:pdf+site:intel.com
e.g.:
http://download.intel.com/support/processors/mobile/pentiumiii/sb/24530659.pdf
<quote>
15.8 TIME-STAMP COUNTER
The IA-32 architecture (beginning with the Pentium processor) defines
a time-stamp counter mechanism that can be used to monitor and
identify the relative time occurrence of processor events. The
counter’s architecture includes the following components:
R
• •
• •
TSC flag — A feature bit that indicates the availability of the time-
stamp counter. The counter is available in an IA-32 processor
implementation if the function CPUID.1:EDX.TSC[bit 4] = 1.
IA32_TIME_STAMP_COUNTER MSR (called TSC MSR in P6 family and Pentium
processors) — The MSR used as the counter.
RDTSC instruction — An instruction used to read the time-stamp
counter. TSD flag — A control register flag is used to enable or
disable the time-stamp counter (enabled
if CR4.TSD[bit 2] = 1).
The time-stamp counter (as implemented in the P6 family, Pentium,
Pentium M, Pentium 4, and Intel Xeon processors) is a 64-bit counter
that is set to 0 following a RESET of the processor. Following a
RESET, the counter will increment even when the processor is halted by
the HLT instruction or the external STPCLK# pin. Note that the
assertion of the external DPSLP# pin may cause the time-stamp counter
to stop.
Members of the processor families increment the time-stamp counter
differently:
•
•
For Pentium M processors (family [06H], models [09H, 0DH]); for
Pentium 4 processors, Intel Xeon processors (family [0FH], models
[00H, 01H, or 02H]); and for P6 family processors: the time-stamp
counter increments with every internal processor clock cycle. The
internal processor clock cycle is determined by the current core-clock
to bus-clock ratio. Intel SpeedStep® technology transitions may also
impact the processor clock.
For Pentium 4 processors, Intel Xeon processors (family [0FH], models
[03H and higher]): the time-stamp counter increments at a constant
rate. That rate may be set by the maximum core-clock to bus-clock
ratio of the processor or may be set by the frequency at which the
processor is booted. The specific processor configuration determines
the behavior. Constant TSC behavior ensures that the duration of each
clock tick is uniform and supports the use of the TSC as a wall clock
timer even if the processor core changes frequency. This is the
architectural behavior moving forward.
Mobile Intel® Pentium® III Processor and Mobile Intel® Pentium® III
Processor-M 63 Specification Update
64
NOTE
To determine average processor clock frequency, Intel recommends the
use of Performance Monitoring logic to count processor core clocks
over the period of time for which the average is required. See Section
15.10.9 and Appendix A in this manual for more information.
The RDTSC instruction reads the time-stamp counter and is guaranteed
to return a monotonically increasing unique value whenever executed,
except for a 64-bit counter wraparound. Intel guarantees that the time-
stamp counter will not wraparound within 10 years after being reset.
The period for counter wrap is longer for Pentium 4, Intel Xeon, P6
family, and Pentium processors.
Normally, the RDTSC instruction can be executed by programs and
procedures running at any privilege level and in virtual-8086 mode.
The TSD flag allows use of this instruction to be restricted to
programs and procedures running at privilege level 0. A secure
operating system would set the TSD flag during system initialization
to disable user access to the time-stamp counter. An operating system
that disables user access to the time-stamp counter should emulate the
instruction through a user- accessible programming interface.
The RDTSC instruction is not serializing or ordered with other
instructions. It does not necessarily wait until all previous
instructions have been executed before reading the counter. Similarly,
subsequent instructions may begin execution before the RDTSC
instruction operation is performed.
The RDMSR and WRMSR instructions read and write the time-stamp
counter, treating the time-stamp counter as an ordinary MSR (address
10H). In the Pentium 4, Intel Xeon, and P6 family processors, all 64-
bits of the time-stamp counter are read using RDMSR (just as with
RDTSC). When WRMSR is used to write the time-stamp counter on
processors before family [0FH], models [03H, 04H]: only the low order
32-bits of the time-stamp counter can be written (the high-order 32
bits are cleared to 0). For family [0FH], models [03H, 04H]: all 64
bits are writeable.
15.10.9 COUNTING CLOCKS
The count of cycles, also known as clockticks, forms a the basis for
measuring how long a program takes to execute. Clockticks are also
used as part of efficiency ratios like cycles per instruction (CPI).
Processor clocks may stop ticking under circumstances like the
following:
•
The processor is halted when there is nothing for the CPU to do. For
example, the processor may halt to save power while the computer is
servicing an I/O request. When Hyper-Threading Technology† is enabled,
both logical processors must be halted for performance-monitoring
counters to be powered down.
• •
Non-halted clockticks — Measures clock cycles in which the specified
logical processor is not halted and is not in any power-saving state.
When Hyper-Threading Technology is enabled, this these ticks can be
measured on a per-logical-processor basis.
Non-sleep clockticks — Measures clock cycles in which the specified
physical processor is not in a sleep mode or in a power-saving state.
These ticks cannot be measured on a logical-processor basis.
Mobile Intel® Pentium® III Processor and Mobile Intel® Pentium® III
Processor-M Specification Update
The processor is asleep as a result of being halted or because of a
power-management scheme. There are different levels of sleep. In the
some deep sleep levels, the time-stamp counter stops counting.
• There are three ways to count processor clock cycles to monitor
performance. These are:
R
R
• •
Time-stamp counter — Measures clock cycles in which the physical
processor is not in deep sleep. These ticks cannot be measured on a
logical-processor basis.
Time-stamp counter — Some processor models permit clock cycles to be
measured when the physical processor is not in deep sleep (by using
the time-stamp counter and the RDTSC instruction). Note that such
sticks cannot be measured on a per-logical-processor basis. See
Section 10.8 for detail on processor capabilities.
The first two methods use performance counters and can be set up to
cause an interrupt upon overflow (for sampling). They may also be
useful where it is easier for a tool to read a performance counter
than to use a time stamp counter (the timestamp counter is accessed
using the RDTSC instruction).
For applications with a significant amount of I/O, there are two
ratios of interest:
• Non-halted CPI — Non-halted clockticks/instructions retired measures
the CPI for phases where the CPU was being used. This ratio can be
measured on a logical-processor basis when Hyper-Threading Technology
is enabled.
• Nominal CPI — Time-stamp counter ticks/instructions retired measures
the CPI over the duration of a program, including those periods when
the machine halts while waiting for I/O.
15.10.9.3 Incrementing the Time-Stamp Counter
The time-stamp counter increments when the clock signal on the system
bus is active and when the sleep pin is not asserted. The counter
value can be read with the RDTSC instruction. The time-stamp counter
and the non-sleep clockticks count may not agree in all cases and for
all processors. See Section 10.8 for more information on counter
operation.
</quote>
:-O
--
Jorge.
Louis Santillan
wiki page for reasons why,
http://en.wikipedia.org/wiki/Time_Stamp_Counter).
-L
Ryan Dahl
>> OSX doesn't have clock_gettime(3)? Arg.
>>
>> Maybe we should use this:http://le-depotoir.googlecode.com/svn/trunk/misc/clock_gettime_stub.
>
> * we could get the ticks by doing this
> *
> * __asm __volatile("mov %%ebx, %%esi\n\t"
> * "cpuid\n\t"
> * "xchg %%esi, %%ebx\n\t"
> * "rdtsc"
> * : "=a" (a),
> * "=d" (d)
> * );
> </quote>
>
> Are you really willing to dig so much deeper ?
That is not the implementation - the implementation is outside the
commented text.
> And to maintain it ?
> Across different cpus ?
> Across different OSs ?
This is for OSX only.
> Don't you prefer to leave that for Linus ?
Uh... don't you mean Apple? I'd love if Apple actually implemented
POSIX, but apparently they don't care about that.
Jorge
> On Mon, Mar 29, 2010 at 3:20 AM, Jorge <jo...@jorgechamorro.com> wrote:
> > On Mar 29, 5:27 am, Ryan Dahl <coldredle...@gmail.com> wrote:
> >> OSX doesn't have clock_gettime(3)? Arg.
>
> >> Maybe we should use this:http://le-depotoir.googlecode.com/svn/trunk/misc/clock_gettime_stub.
>
> > <quote>
> > * we could get the ticks by doing this
> > *
> > * __asm __volatile("mov %%ebx, %%esi\n\t"
> > * "cpuid\n\t"
> > * "xchg %%esi, %%ebx\n\t"
> > * "rdtsc"
> > * : "=a" (a),
> > * "=d" (d)
> > * );
> > </quote>
>
> > Are you really willing to dig so much deeper ?
>
> That is not the implementation - the implementation is outside the
> commented text.
>
> > And to maintain it ?
> > Across different cpus ?
> > Across different OSs ?
>
> This is for OSX only.
A misunderstanding, Ryan, sorry.
> > Don't you prefer to leave that for Linus ?
>
> Uh... don't you mean Apple? I'd love if Apple actually implemented
> POSIX, but apparently they don't care about that.
But they've got that nice mach kernel call that Zoka has discovered.
Don't you like it ?
--
Jorge.
Zoka
The OS X replacement for clock_gettime() in clock_get_time_stub.c in
original form is very slow (arround 5000 ns).
Since all we need is number of nanoseconds since OS restart - the easy
way to add such functionality to node was a minimal patch to node.cc
( see http://gist.github.com/346669 ).
We could try to retrofit a stub for optimal OSX clock_gettime() with
libev, however this would probably require messing around with libev
configure and/or source.
The process.uptime() now takes only around 176 nsec for 2 consecutive
calls on O...@2.67GHz. Its return value format is double [msec] so it
is easy to combine it with JS Date.now()
Note that there is gradual loss of accuracy as OS uptime (time since
OS restart) increases:
n bits of process.uptime() result mantissa every (2**n)*104 days) -
but I do not think it is relevant for purposes process.uptime() is
intended for: measuring time intervals as low as fraction of
microsecond to as high as hours and days.
I extended uptime_test.js to be able to cut off samples that are
caused by interrupts, cache misses, etc so reasonable variance / std
deviation can be achieved (see above gist)
And then I stumbled on major inaccuracy in Node timer event firing,
that somehow depends on amount of processing done prior to calling the
test_timer_accuracy().
Very puzzling since test-timers.js seems to be OK? Actually it allows
for +/- 200 msec margin of error, and that is way it passes OK. One
reason more to stay away from libev timing code :-)
There is a separate gist http://gist.github.com/349014 that
demonstrates the timer accuracy problem.
Regards
Zoka
Zoka
of measurements caused by section of the program being measured itself
and everything else that happens on the machine program is being run
on, such as unrelated interrupts. other processes and their cache
misses. , other threads within the same process , etc.
It seems that we have to do multiple measurements (samples) and then
try to cut off the odd ones before using statistical processing of the
collected results.
Have look at http://gist.github.com/346669#file_uptime_test.js
If appropriate cutoff value (1000 ns) is used, standard deviation
seems to be reasonable:
Number of samples: 1000000
Cut off value: 1000 nanoseconds
Valid samples: 999784 Rejected: 216
Largest rejected sample: 66673 nsec
Smallest rejected sample: 1035 nsec
Unique samples: 181
Mean delta: 172.35445456218542
Variance: 325.81955612528503 Std deviation: 18.050472462661055
However if cutoff is set to 1000000 ns,
we get this:
Number of samples: 1000000
Cut off value: 1000000 nanoseconds
Valid samples: 1000000 Rejected: 0
Unique samples: 322
Mean delta: 174.531307
Variance: 210107.2199038718 Std deviation: 458.37454107298737
The above standard deviation seems to be too high.
Regards
Zoka
Ryan Dahl
> Hi Ryan,
>
> The OS X replacement for clock_gettime() in clock_get_time_stub.c in
> original form is very slow (arround 5000 ns).
> Since all we need is number of nanoseconds since OS restart - the easy
> way to add such functionality to node was a minimal patch to node.cc
> ( see http://gist.github.com/346669 ).
Oh, thanks for pointing that out.
> We could try to retrofit a stub for optimal OSX clock_gettime() with
> libev, however this would probably require messing around with libev
> configure and/or source.
It would be very cool if we could. Note that Node already replaces
libev's configure script (see deps/libev/wscript). I don't think it
would be hard.
I'm a bit concerned about implementing a monotonic clock which behaves
correctly when the computer is put to sleep.
> The process.uptime() now takes only around 176 nsec for 2 consecutive
> calls on O...@2.67GHz. Its return value format is double [msec] so it
> is easy to combine it with JS Date.now()
>
> Note that there is gradual loss of accuracy as OS uptime (time since
> OS restart) increases:
> n bits of process.uptime() result mantissa every (2**n)*104 days) -
> but I do not think it is relevant for purposes process.uptime() is
> intended for: measuring time intervals as low as fraction of
> microsecond to as high as hours and days.
>
> I extended uptime_test.js to be able to cut off samples that are
> caused by interrupts, cache misses, etc so reasonable variance / std
> deviation can be achieved (see above gist)
>
> And then I stumbled on major inaccuracy in Node timer event firing,
> that somehow depends on amount of processing done prior to calling the
> test_timer_accuracy().
>
> Very puzzling since test-timers.js seems to be OK? Actually it allows
> for +/- 200 msec margin of error, and that is way it passes OK. One
> reason more to stay away from libev timing code :-)
>
> There is a separate gist http://gist.github.com/349014 that
> demonstrates the timer accuracy problem.
I suspect the problem is that libev's clock is not getting updated. I
don't have much time to look into it at the moment though.
It's sad that "new Date()" make a system call yet does not update
libev's sense of what time it is. This could probably be fixed by
hacking deps/v8/src/platform*
Zoka
> > There is a separate gisthttp://gist.github.com/349014that
> > demonstrates the timer accuracy problem.
>
> I suspect the problem is that libev's clock is not getting updated. I
> don't have much time to look into it at the moment though.
>
> It's sad that "new Date()" make a system call yet does not update
> libev's sense of what time it is. This could probably be fixed by
> hacking deps/v8/src/platform*
When setTimeout() is called it will eventually call set
Timer::start() that will call ev_timer_start(). It looks that
ev_timer_start() does not update libev internal time reference.
Zoka
r...@tinyclouds.org
> When setTimeout() is called it will eventually call set
> Timer::start() that will call ev_timer_start(). It looks that
> ev_timer_start() does not update libev internal time reference.
Are you suggesting that we ev_now_update() when we start the timer?
(Does that fix the problem?) Generally I trust that libev makes the
right optimizations - but we might need to account for the slowness of
our programs.
Zoka
On Mar 31, 12:21 pm, r...@tinyclouds.org wrote:
Yes, this seems to fix the problem. I am still puzzled why libev goes
to great length to avoid calling gettimeofday() since this call only
takes a fraction of microsecond.
Handle<Value>
Timer::Start (const Arguments& args)
{
HandleScope scope;
Timer *timer = ObjectWrap::Unwrap<Timer>(args.Holder());
if (args.Length() != 2)
return ThrowException(String::New("Bad arguments"));
bool was_active = ev_is_active(&timer->watcher_);
ev_tstamp after = NODE_V8_UNIXTIME(args[0]);
ev_tstamp repeat = NODE_V8_UNIXTIME(args[1]);
ev_now_update(); // bug fix - update libev internal time reference
before starting the timer
ev_timer_init(&timer->watcher_, Timer::OnTimeout, after, repeat);
timer->watcher_.data = timer;
ev_timer_start(EV_DEFAULT_UC_ &timer->watcher_);
if (!was_active) timer->Ref();
return Undefined();
}
r...@tinyclouds.org
best of both. I'd be really great if we could get a hook into whatever
system call is being used... Is there a way to do that?
r...@tinyclouds.org
>
> On Mar 31, 12:21 pm, r...@tinyclouds.org wrote:
>> On Tue, Mar 30, 2010 at 6:14 PM, Zoka <ztomi...@gmail.com> wrote:
>> > When setTimeout() is called it will eventually call set
>> > Timer::start() that will call ev_timer_start(). It looks that
>> > ev_timer_start() does not update libev internal time reference.
>>
>> Are you suggesting that we ev_now_update() when we start the timer?
>> (Does that fix the problem?) Generally I trust that libev makes the
>> right optimizations - but we might need to account for the slowness of
>> our programs.
>
> Yes, this seems to fix the problem.
I changed Node in ec0266a to call ev_now_update() when starting a timer.