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

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.

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

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

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.