On 23.08.2012 05:52, timotheecour wrote:
I'm not sure how to interpret trace.log from running dmd with -profile
(on osx at least).
I inserted a stopwatch inside main, which gave 35.8 seconds.
1) How to convert times in trace.log to seconds? Eg, how to get 35.8
seconds using the numbers below?
here's the first last line for times:
======== Timer Is 3579545 Ticks/Sec, Times are in Microsecs ========
Num Tree Func Per
Calls Time Time Call
here's the last line:
1 16317420002 -43499161 -43499161 _Dmain
The trace code is in druntime/rt/trace.d. There you can see that the
ticks/sec is just set to the shown constant value for anything but
Windows, but RDTSC is used to read the processor cycles. So the values
are probably off by a factor of 300 to 1000.
2) Why are there negative numbers? (seems like an overflow problem, but
the total time is quite small so it seems the scale is wrong).
The time in ms is calculated as (time * 1000000) / freq, so with a
processor speed of 2GHz, this will overflow after about 2000s. This
doesn't seem to explain negative values in your run, so some random hints:
- if you rerun the program, results will accumulate in trace.log
- if you are calling recursive functions from inside main, there might
be some issues with the timings of these functions (from my own
experience from writing a profiler, it can get quite tricky to measure
the execution time of recursive functions), and these are used to
calculate the FuncTime of main.
3) are there any tools to visualize trace.log (eg gui, html or otherwise)?
The only ones I found were outdated (ptrace.d for tango and profiled.d
for D1)
Visual D lets you explore trace.log in a browse window inside Visual
Studio, but I guess this won't help you on OSX.
