digitalmars.D - 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
Jan 25 2008
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
Lutger schrieb: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 ? BjoernI 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 28 2008
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
Bjoern <nanali nospam-wanadoo.fr> 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/PtraceUtilitySorry 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.
Jan 31 2008