View mode: basic / threaded / horizontal-split · Log in · Help
January 25, 2008
Profiler, profiling DLLs, trace.log
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
January 27, 2008
Re: Profiler, profiling DLLs, trace.log
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.
January 28, 2008
Re: Profiler, profiling DLLs, trace.log
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.
> 
> 
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
January 29, 2008
Re: Profiler, profiling DLLs, trace.log
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
January 31, 2008
Re: Profiler, profiling DLLs, trace.log
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
> 
> 
Sorry for the delay. Had an accident and one of my feets are pretty 
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.
Top | Discussion index | About this forum | D home