www.digitalmars.com         C & C++   DMDScript  

digitalmars.D.learn - Still can't understand -profile numbers

reply Ary Manzana <ary esperanto.org.ar> writes:
Take a look at this trace.log file:

------------------
	    1	foo
	    6	foo2
bar	7	199	49
	    4	someMethod
------------------
	    1	main
foo	1	50	9
	    1	bar
------------------
	    5	foo3
	    1	main
foo2	6	212	54
	    6	bar
------------------
	    5	someMethod
foo3	5	209	45
	    5	foo2
------------------
	    4	bar
	    1	main
someMethod	5	254	45
	    5	foo3
------------------
main	0	230	28
	    1	foo
	    1	foo2
	    1	someMethod

======== Timer Is 3579545 Ticks/Sec, Times are in Microsecs ========

   Num          Tree        Func        Per
   Calls        Time        Time        Call

       6          59          15           2     foo2
       7          55          13           1     bar
       5          70          12           2     someMethod
       5          58          12           2     foo3
       1          64           7           7     main
       1          13           2           2     foo
---

I can't understand why main has a tree time of 64 and someMethod, which 
is invoked by main, has 70. An invoked method can't spend more time in 
total than the function that invoked it. Or yes?

Well, maybe looking at the tree ticks... main has 230, but then again, 
someMethod has 254.
Aug 11 2007
parent reply Lutger <lutger.blijdestijn gmail.com> writes:
Ary Manzana wrote:
...
 
 I can't understand why main has a tree time of 64 and someMethod, which 
 is invoked by main, has 70. An invoked method can't spend more time in 
 total than the function that invoked it. Or yes?
 
 Well, maybe looking at the tree ticks... main has 230, but then again, 
 someMethod has 254.

My guess is that is because the timings are very short. In general I have noticed some irregular behavior, it is a good idea to profile multiple times. There are some limitations and reasons for irregular timings written under the 'notes' section on digitalmars: http://www.digitalmars.com/ctg/trace.html Finally, on some machines, the windows high performance api can have bugs (I have such a machine, motherboard issue).
Aug 11 2007
parent Bill Baxter <dnewsgroup billbaxter.com> writes:
Lutger wrote:
 Ary Manzana wrote:
 ...
 I can't understand why main has a tree time of 64 and someMethod, 
 which is invoked by main, has 70. An invoked method can't spend more 
 time in total than the function that invoked it. Or yes?

 Well, maybe looking at the tree ticks... main has 230, but then again, 
 someMethod has 254.

My guess is that is because the timings are very short. In general I have noticed some irregular behavior, it is a good idea to profile multiple times. There are some limitations and reasons for irregular timings written under the 'notes' section on digitalmars: http://www.digitalmars.com/ctg/trace.html Finally, on some machines, the windows high performance api can have bugs (I have such a machine, motherboard issue).

I was thinking it was just some sort of rounding. I see things like Per Call = 0, with Func Time = <not zero> very often. So I was just assuming the numbers were rounded to the nearest unit, whatever the unit is. --bb
Aug 12 2007