profiler issues: time overflows, conversion to seconds, gui/html output

[Rainer Schuetze]

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.