www.digitalmars.com         C & C++   DMDScript  

digitalmars.D.learn - Profile Ouput

reply "Mike Parker" <aldacron gmail.com> writes:
Perhaps my googlefu has failed me, but I can find anything 
describing the output of DMD's -profile switch. I get that 
trace.def is a list of all functions called and I understand the 
table at the bottom of trace.log. What I'm not sure about is 
everything above the table in trace.log, stuff like this:

------------------
	 4000	_Dmain
_D4main6selectFZk	4000	2736	471
	 4000	_D3std6random27__T7uniformVAyaa2_5b29TkTkZ7uniformFNfkkZk
------------------

I get that it's telling me that the function main.select is 
called 4000 times and that it, in turn, calls std.random.uniform 
4000 times. What I not clear about is the 2736 and the 471. They 
match none of the times int the table below, where main.select 
has a Tree Time of 823 and a Func Time of 141. I also don't 
understand the 4000 next to _Dmain, as it's only called once. If 
anyone could clarify, or point me somewhere that explains it, I'd 
appreciate it.
Jul 14 2015
next sibling parent reply "Mike Parker" <aldacron gmail.com> writes:
On Tuesday, 14 July 2015 at 13:35:40 UTC, Mike Parker wrote:
 ------------------
 	 4000	_Dmain
 _D4main6selectFZk	4000	2736	471
 	 4000	_D3std6random27__T7uniformVAyaa2_5b29TkTkZ7uniformFNfkkZk
 ------------------
OK, I've finally realized that the top part of trace.log is an inverted (with main at the bottom) call tree. I've got everything now except that 2736 and 471 on the second line. Anyone?
Jul 15 2015
parent reply "jmh530" <john.michael.hall gmail.com> writes:
On Wednesday, 15 July 2015 at 11:47:53 UTC, Mike Parker wrote:
 On Tuesday, 14 July 2015 at 13:35:40 UTC, Mike Parker wrote:
 ------------------
 	 4000	_Dmain
 _D4main6selectFZk	4000	2736	471
 	 
 4000	_D3std6random27__T7uniformVAyaa2_5b29TkTkZ7uniformFNfkkZk
 ------------------
OK, I've finally realized that the top part of trace.log is an inverted (with main at the bottom) call tree. I've got everything now except that 2736 and 471 on the second line. Anyone?
I've been confused by this too. The only thing I can find is this http://www.digitalmars.com/ctg/trace.html I think it would be cool to write something that takes the output and puts it in a prettier format.
Jul 15 2015
parent "Mike Parker" <aldacron gmail.com> writes:
On Wednesday, 15 July 2015 at 18:02:11 UTC, jmh530 wrote:
 I've been confused by this too. The only thing I can find is 
 this
 http://www.digitalmars.com/ctg/trace.html

 I think it would be cool to write something that takes the 
 output and puts it in a prettier format.
Yeah, I eventually stumbled on to that, but it unfortunately tells me nothing I don't already know. I suppose I'll just email Walter and ask him.
Jul 15 2015
prev sibling parent "Mike Parker" <aldacron gmail.com> writes:
On Tuesday, 14 July 2015 at 13:35:40 UTC, Mike Parker wrote:

 ------------------
 	 4000	_Dmain
 _D4main6selectFZk	4000	2736	471
 	 4000	_D3std6random27__T7uniformVAyaa2_5b29TkTkZ7uniformFNfkkZk
 ------------------
Got it now. The 2736 and 471 are the call tree time and function call time, respectively, in *ticks*. They are converted to seconds then displayed as milliseconds int the table at the bottom of the file.
Jul 15 2015