I decided to dig deeper, with the help of a totally contrived C
program [6] that uses mach_absolute_time to measure elapsed time. It's
the same method used by DTrace on Mac OSX, I believe.
My conclusion is that elapsed time has to be taken in the context of
the startup time that DOES include dtrace overhead, not in the context
that excludes it.
My pipeline consists of a driver shell script that allows me to put
several dtrace scripts together (d) [1] and the following dtrace
scripts:
b.d : times C function b [2]
main.d : times main [3]
trace.d : times all functions using function entry/return probes [4]
sigcont.d : sends SIGCONT to $target [5]
I compile foo.c using 'gcc foo.c -std=c99 -O0 -o foo' and run dtrace
and foo in different windows, starting foo after dtrace.
Without dtrace
---
./foo
elapsed time in b: 2468196181ns
elapsed time in main 2961539846ns
---
Timing both main() and b() using 2 scripts
---
elapsed time in b: 2499433877ns
elapsed time in main 2998021720ns
./d foo b.d main.d
dtrace -Zqw -x dynvarsize=64m -x evaltime=postinit -p 37583 -s b.d -s
main.d -s sigcont.d
b: elapsed: 2491.8609689ms
b: cpu : 2457.9077335ms
b: count : 20 times
main: 2998.110291ms
---
vs timing just main() using dtrace
---
elapsed time in b: 2471918169ns
elapsed time in main 2967909333ns
./d foo main.d
dtrace -Zqw -x dynvarsize=64m -x evaltime=postinit -p 37592 -s main.d
-s sigcont.d
main: 2967.973019ms
---
Times are very comparable so there's not a lot of overhead in main.d
and b.d.
Now the same but with a VERY expensive trace.d which causes a kernel
trap for every user function
---
elapsed time in b: 4048801437ns
elapsed time in main 4861803951ns
./d foo main.d b.d trace.d
dtrace -Zqw -x dynvarsize=64m -x evaltime=postinit -p 37622 -s main.d
-s b.d -s trace.d -s sigcont.d
b: elapsed: 4037.12010634ms
b: cpu : 3064.10182894ms
b: count : 20 times
main: 4863.032899ms
---
Elapsed time is proportionally increased both in the app (foo) and in
the output from dtrace scripts. This tells me that you should always
view the timings in the context of the same dtrace run (b.d + main.d),
not in some other context.
Is this conclusive proof? Let me know!
Thanks, Joel
---
[1] d
#!/bin/bash
progname=$1
shift
scripts=""
for i in $*; do scripts="$scripts -s $i"; done
scripts="$scripts -s sigcont.d"
opts="-Zqw -x dynvarsize=64m -x evaltime=postinit"
dtrace='
inline string progname="'$progname'";
inline string scripts="'$scripts'";
inline string opts="'$opts'";
proc:::exec-success
/execname == progname/
{
stop();
printf("dtrace %s -p %d %s\n", opts, pid, scripts);
system("dtrace %s -p %d %s\n", opts, pid, scripts);
exit(0);
}
'
sync && purge && dtrace $opts -n "$dtrace"
[2] b.d
BEGIN
{
self->t = 0;
self->vt = 0;
}
pid$target::b:entry
{
self->t = timestamp;
self->vt = vtimestamp;
}
pid$target::b:return
/self->t/
{
this->t = timestamp - self->t;
this->vt = vtimestamp - self->vt;
@tsint = sum(this->t / 1000000);
@tsfrac = sum(this->t % 1000000);
@vtsint = sum(this->vt / 1000000);
@vtsfrac = sum(this->vt % 1000000);
@n = count();
self->t = 0;
self->vt = 0;
}
END
{
t = timestamp;
printa("b: elapsed: %...@u.%@06ums\n", @tsint, @tsfrac);
printa("b: cpu : %...@u.%@06ums\n", @vtsint, @vtsfrac);
printa("b: count : %...@u times\n", @n);
}
[3] main.d
pid$target::main:entry
{
start = timestamp;
}
pid$target::main:return
{
this->total = timestamp - start;
printf("main: %u.%06ums\n", this->total / 1000000, this->total %
1000000);
exit(0);
}
[4] trace.d
BEGIN
{
trace_start = timestamp;
}
pid$target:::entry
{
self->trace_ts = timestamp;
}
pid$target:::return
/self->trace_ts/
{
this->trace_delta = timestamp - self->trace_ts;
@trace_elapsed1[probefunc] = sum(this->trace_delta / 1000000);
@trace_elapsed2[probefunc] = sum(this->trace_delta % 1000000);
@trace_total1 = sum(this->trace_delta / 1000000);
@trace_total2 = sum(this->trace_delta % 1000000);
@trace_count[probefunc] = count();
self->trace_ts = 0;
}
END
{
this->trace_t = timestamp;
trunc(@trace_elapsed1, 25);
trunc(@trace_elapsed2, 25);
trunc(@trace_count, 25);
this->trace_total = this->trace_t - trace_start;
printf("Top user functions by elapsed time:\n");
printa("%@ 10...@06ums for %s\n", @trace_elapsed1, @trace_elapsed2);
printf("---------------\n");
printa("= %...@u.%@06ums\n", @trace_total1, @trace_total2);
printf("Total: %u.%06ums\n", this->trace_total / 1000000, this-
>trace_total % 1000000);
}
[5] sigcont.d
BEGIN
{
system("kill -CONT %d &\n", $target);
}
[6] foo.c
#include <stdio.h>
#include <stdlib.h>
#include <stdarg.h>
#include <mach/mach.h>
#include <mach/mach_time.h>
#include <unistd.h>
uint64_t nanoseconds(uint64_t elapsed) {
mach_timebase_info_data_t info;
mach_timebase_info(&info);
uint64_t nanoSeconds = elapsed * info.numer / info.denom;
return nanoSeconds;
}
uint64_t a(int y) {
FILE* fp;
uint32_t x;
if((fp = fopen("/dev/urandom", "r")) == NULL) {
printf("bummer!\n");
exit(1);
}
for (int i = 0; i < 512; i++)
fread(&x, sizeof(uint32_t), 1, fp);
fclose(fp);
return x * x * x * y;
}
uint64_t b() {
uint64_t start = mach_absolute_time();
for(int i = 0; i < 20; i++)
a(i);
uint64_t end = mach_absolute_time();
return end - start;
}
void c() {
for(int i = 0; i < 40; i++)
a(i);
}
int main()
{
uint64_t elapsed = 0;
uint64_t start = mach_absolute_time();
c();
for (int i = 0; i < 20; i++)
elapsed += b();
c();
//and here where we take the 2nd time measurement...
uint64_t end = mach_absolute_time();
printf ("elapsed time in b: %lldns\n", nanoseconds(elapsed));
printf ("elapsed time in main %lldns\n", nanoseconds(end - start));
return 0;
}
---
fastest mac firefox!
http://wagerlabs.com
_______________________________________________
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org
