www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - Profiler, profiling DLLs, trace.log

reply Bjoern <nanali nospam-wanadoo.fr> writes:
Hi,
First of all you'll have a lot of fun when you profile a DLL which is 
used to call /dmd -profile /  via process like :

export extern(Windows)
void ExecuteProcess(DisplayCallBack cb, char* _dir, char* _command, 
char* _args)
{
/// bla, bla
Process p = new Process(command, null);
p.workDir = dir;		
msg = Text.layout(buffer, "Executing %0 ", p.toString);

p.execute(); // call dmd -profile etc...
----------------------------------------

But that's another story ;)

I wonder where are the relevant information within trace.log.

PART I

I have modified the contents a bit but it starts f.i.

<TAB>    2<TAB>_ExecuteProcess 16
_D5tango4text4Util13__T6layoutTaZ6layoutFAaAAaXAa<TAB>2<TAB>25<TAB>25

<TAB>   84<TAB>_ExecuteProcess 16
_D5tango4text4Util14__T7indexOfTaZ7indexOfFPaakZk<TAB>84<TAB>140<TAB>140

etc.

PART II

At the bottom of the log file you'll find something like this :

   Num          Tree        Func        Per
   Calls        Time        Time        Call

       2      278961      278952      139476 
_D5tango4text6stream14StreamIterator22__T14StreamIteratorTaZ14StreamIterator7consumeMFZb
       1      288585        9347        9347     _ExecuteProcess 16
       1        1570        1570        1570     _DllMain 12
       2         112         112          56 
_D5tango4text6stream14StreamIterator22__T14StreamIteratorTaZ14StreamIterator3setMFC5tango2io5model8IConduit11InputStreamZC5tango4text6stream14StreamIterator22__T14StreamIteratorTaZ14StreamIterator

I guess the numeric data at the bottom part are relevant. And each of 
them is calulated based on PART I.

How ? NONSENSE ?

Last Q for the moment. What is PART I good for ? Or in other words, Can 
I use this information somehow ?

And yes I know about pTrace from Lutger, but I prefer to understand the 
log file contents instead of simply to pluggin a piece of software :)
Many thanks in advance Bjoern
Jan 25 2008
parent reply Lutger <lutger.blijdestijn gmail.com> writes:
Bjoern wrote:

...
 I guess the numeric data at the bottom part are relevant. And each of
 them is calulated based on PART I.
 
 How ? NONSENSE ?

iirc, the timings in part one are in ticks, not microseconds, while the timings in the summary are calculated to be in microseconds. This is a bit confusing. In the table of the second part the frequency is stated which can be used to calculate from ticks to microseconds.
 Last Q for the moment. What is PART I good for ? Or in other words, Can
 I use this information somehow ?

Call graphs. For each function, it tells you by which functions it is called and which functions it calls, along with timing information. This can give useful hints when looking for performance bottlenecks.
Jan 27 2008
parent reply Bjoern <nanali nospam-wanadoo.fr> writes:
Lutger schrieb:
 Bjoern wrote:
 
 ...
 I guess the numeric data at the bottom part are relevant. And each of
 them is calulated based on PART I.

 How ? NONSENSE ?

iirc, the timings in part one are in ticks, not microseconds, while the timings in the summary are calculated to be in microseconds. This is a bit confusing. In the table of the second part the frequency is stated which can be used to calculate from ticks to microseconds.
 Last Q for the moment. What is PART I good for ? Or in other words, Can
 I use this information somehow ?

Call graphs. For each function, it tells you by which functions it is called and which functions it calls, along with timing information. This can give useful hints when looking for performance bottlenecks.

pTrace actually just supports the summary table, right ? Call graphs. I wonder how a graphical representation should look like. Perheps: called from \ / F / \ /0.012ms/ calls Ideas ? Bjoern
Jan 28 2008
parent reply Lutger <lutger.blijdestijn gmail.com> writes:
Bjoern wrote:

...
 Thanks Lutger.
 pTrace actually just supports the summary table, right ?
 
 Call graphs.
 I wonder how a graphical representation should look like.
 Perheps:
 
 called from
 
 \ /
   F
 / \
      /0.012ms/
 calls
 
 
 Ideas ?
 Bjoern

Hi, ptrace supports call graphs and also converts ticks to microseconds. I have added an example of how it looks to the wiki* It's basically a table where functions calls are seperated by a blank line and the timed function is in bold, layout is similar to the trace.log file. I hope it'll speak for itself, it includes a header. I did once added support for generating images with graphviz for callgraphs, but I found it to be quite some work to make it look good and get useful images. iirc it can be done with ptrace by only redefining the ddoc macros, but the function identifiers are way too long atm, including the whole type. I think making a complete call graph out of a trace.log file will look too cluttered. Ideally you'll have some way to view the call graph of a single function and click through it's callers and callees. Perhaps with an option to set the depth of the call tree from that function. However, to make this work nicely I think it's necessary to reduce the fully qualified names to a single function name. From an IDE perspective, speaking personally, it would be more useful if the relevant information integrates with the rest of the IDE. For example, after making a profile the timing information is remembered and easily accessed through the code symbol browser or from right-clicking on the source. Along with timing there would be a small list of the callers and callees. Things like that (ideally speaking). I'm curious what you're going to do with it, profiling is very important and it's a very good idea to make this more accessable within the IDE, imho. It will encourage people to actually gather empirical evidence about their code. Regards, Lutger * http://www.dsource.org/projects/scrapple/wiki/PtraceUtility
Jan 29 2008
parent Bjoern <nanali nospam-wanadoo.fr> writes:
Lutger schrieb:

 I'm curious what you're going to do with it, profiling is very important and
 it's a very good idea to make this more accessable within the IDE, imho. It
 will encourage people to actually gather empirical evidence about their
 code. 
 
 Regards,
 
 Lutger
 
 * http://www.dsource.org/projects/scrapple/wiki/PtraceUtility
 
 

green and blue... actually green dominates :) What I am going to do : Finally something similar to this : http://www.netbeans.org/images/v6/features/profiler-java.png I guess the GUI part should not take more than 3 hours. So no problem here. Problem is that I need a better understanding regarding profiler results. For instance : The screenshot shows Time in ms and a percent value. Percent of what ? CPU usage ? Well the shot is showing Java profiler results, it seems this profiler offers additional information. like Used Heap / Heap Size. However, You see, the Netbeans folks are using a Tree-List widget. I like it, so I will create a similar GUI adapted to use pTrace output. ( still wondering how they deal recursive functions ) Once done, I hope you'll lend me a hand to fill the treelist with Ptrace data. As said I have to modify Ptrace 'cause I need a DLL. Further: return values have to be char* and instead of having several single values, a comma, whitespace, whatever delimited *list is preferable. No rocket science :), Building the call graph is an other story. * 193,43885,32456,168,ptrace.Words.opApply,int function(int delegate(inout char[], void*), void*) Regards, Bjoern But first things first. D source to database mapping has to be done.
Jan 31 2008