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
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).
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)

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.

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.

So I'm still not sure how to convert those numbers to seconds. Is
there a deterministic way? Is the multiplicative factor (300 to
1000) fixed on a given machine or what does it depend on ?

The time in ms is calculated as (time * 1000000) / freq, so
with a processor speed of 2GHz, this will overflow after about
2000s.

Why not use 64 bit integer instead of 32 bit for counter?

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

I ran it just once

- 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.

No recursive functions

Visual D lets you explore trace.log in a browse window inside
Visual Studio, but I guess this won't help you on OSX.

great! Is there a way to run it on a project build outside of
visualD? I use a makefile instead of relying on visualD's build
system. When I open the profiler window and open trace.log inside
nothing is shown. Ideally all it should do is demangle symbols
and convert to a table, so I'm assuming trace.log is
self-contained.

great! Is there a way to run it on a project build outside of
visualD? I use a makefile instead of relying on visualD's build
system. When I open the profiler window and open trace.log
inside nothing is shown. Ideally all it should do is demangle
symbols and convert to a table, so I'm assuming trace.log is
self-contained.

Oh the problem is trace.log here was built on a different
architecture (osx). Would there be any way to visualize that with
the tool still ? It should only be a matter of demangling osx
style instead of windows style, the rest being identical?

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.

So I'm still not sure how to convert those numbers to seconds. Is there
a deterministic way? Is the multiplicative factor (300 to 1000) fixed on
a given machine or what does it depend on ?

The factor should be CPU-cycles-per-second / 3579545, so my estimate was
for a CPU that runs at about 1 - 3.5 GHz.

The time in ms is calculated as (time * 1000000) / freq, so with a
processor speed of 2GHz, this will overflow after about 2000s.

Why not use 64 bit integer instead of 32 bit for counter?

The time is a long, but for current CPU-clock-speeds multiplying it with
1000000 limits the measurable time.

Visual D lets you explore trace.log in a browse window inside Visual
Studio, but I guess this won't help you on OSX.

great! Is there a way to run it on a project build outside of visualD? I
use a makefile instead of relying on visualD's build system. When I open
the profiler window and open trace.log inside nothing is shown. Ideally
all it should do is demangle symbols and convert to a table, so I'm
assuming trace.log is self-contained.

I would have guessed that it should not depend on the system the
trace.log is generated as the D name mangling should be the same. And
even if it is not, the profiler window still displays the mangled names.
If you have an example of a non-working trace.log, you can send it to
me, and I'll have a look.