www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - profiler issues: time overflows, conversion to seconds, gui/html

reply "timotheecour" <thelastmammoth gmail.com> writes:
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)
Aug 22 2012
parent reply Rainer Schuetze <r.sagitario gmx.de> writes:
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.
Aug 23 2012
parent reply "timotheecour" <thelastmammoth gmail.com> writes:
Thanks,


 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.
Aug 24 2012
next sibling parent "timotheecour" <thelastmammoth gmail.com> writes:
 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?
Aug 24 2012
prev sibling parent Rainer Schuetze <r.sagitario gmx.de> writes:
On 24.08.2012 19:35, timotheecour wrote:

 Thanks,


 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.
Aug 24 2012