IDE Profiling

bridged with qnx.development_tools
Robert Muil

Re: IDE Profiling

Post by Robert Muil » Tue Nov 23, 2004 3:34 am

Steve,

I have added -gdwarf-2 to CCFLAGS and LDFLAGS in Makefile.

It makes no difference - the line references all place me (and the coloured
bars) 1 code line below the actual line.

Is there supposed to be a GUI option to modify these settings, or have I
done it correctly?

Does the binary parser option in project settings have anything to do with
this?

Robert.

"Steve Reid" <stever@sreid.ott.qnx.com> wrote in message
news:cntb34$bk7$1@inn.qnx.com...
David Gibbs <dagibbs@qnx.com> wrote:
Robert Muil <r.muil@crcmining.com.au> wrote:
There are a couple problems, though. The placement of the code
information
lines seems to be off by one. (Existing PR.) And, I think you mentioned
you were Neutrino-hosted. There are a bunch of focus and redraw problems
in Neutrino-hosted that make it such that hover-help often doesn't work,
making this data hard to view. (The redraw and focus problems are
supposed
to be fixed for service pack 1, I'm not sure about the finding the right
line problem.)

The problem with line numbers hasn't been fixed yet, but there is a
partial workaround (this is from the SP1 release notes):

Line numbers in the Memory Analysis, Application Profiler, and Code
Coverage tools are incorrect on SH and MIPS targets. On x86, PowerPC and
ARM targets, the line numbers are off by 1 if you use the stabs
debugging format. (Ref# 21198, 21412)

Workaround: For x86, PowerPC and ARM targets, use the DWARF debugging
format, by adding -gdwarf-2 option to the compile flags.

------------------------------------------
Steve Reid stever@qnx.com
TechPubs (Technical Publications)
QNX Software Systems
------------------------------------------

Colin Burgess

Re: IDE Profiling

Post by Colin Burgess » Tue Nov 23, 2004 2:12 pm

I don't want to get into the functionality of the profiler too much, but
the test program in your source is going to spend 99.9% of it's time in
libc functions usleep (which will end up being a TimerTimeout ) and
printf (all sorts of libc functions).

Since libc isn't profiled, this will cause varying and unclear results.

Robert Muil wrote:
David,

I hope this screenshot is viewable. It should show how complicated a process
it is to profile even a stupidly simple program.

To determine how much time is spent in do_loop (), and where that is spent,
I first must find out what resolve_rels(), lookup(), hash(),
ConnectAttach(), static_strcmp(), __SysCpupageGet(), _dladdr() functions
are. Most are not even mentioned in the documentation (although this is hard
to be certain of because there is no index).

I must then work out where they are being called from.

I must then work out how much time they are using, presumably by guessing
percentage CPU from the %Time Usage bar or and calculating time in functions
as an percentage of the overall program run time (which would need to be
determined, I suppose, with a separate tool).

I hope that I am wrong about this. If so, please tell me how I can use the
information shown in the Profiler perspective to tell how much time has been
used by the do_loop() function, and where that time was spent).

Also note the coloured bars in the c editor. What is this supposed to
suggest, beyond that QNX likes the sound of its own name and has coloured in
the margin to highlight it?

Robert.


"David Gibbs" <dagibbs@qnx.com> wrote in message
news:cnl3nr$5n4$1@inn.qnx.com...

Robert Muil <r.muil@crcmining.com.au> wrote:

David,

I am unable to determine how long a program spends, cumulatively, in a
function.

Total time directly in a function would be given by the total time in
Sampling information view.

Or, do you mean for a function, and all sub-functions, cumulated to that
function?


It does not help me to know that 5% of my time was in ldiv() or .plt()
(whatever they are). I want to know that 100% was in main(), then 90% of
that was in do_loop(), etc.

Sounds like that's what you want. That can't be done. Well, in theory
it can be done, but the data collection to provide that would be enormous.
What the profiler does is collect 2 types of information -- it annotates
any code compiled with profiling to get function call counts (basically
call pairs), and it samples the execution of the program from the timer
interrupt, storing the current IP, and active thread at that point. Then,
the time useage is "estimated" based on the sampling -- but it doesn't
know what the call path to get to the function is. To get the cumulative
sub-function useage your asking for, at every sample point a full stack
backtrace would have to be collected and stored -- the overhead to collect
that information, and store that information, would be quite impressive,
and heavily impact whatever you were trying to profile. Also, the tool
chain (GCC) doesn't supply tools to do that.

Why would full backtrace be neede?
Consider the following:

int func1() { /* use lots of CPU */}
int funca() { func1(); }
int funcb() { func1(); }
int main() { while (1) { funca(); funcb(); } }

Now, is CPU time spent in func1() attributed to funca() or funcb()?
Without
a stack backtrace, you can't know.


Also, it does not seem to correctly read the symbol table. I have a very
simple program to test, which just loops and does a few printfs. When I
profile it, the calling information only displays call information for
the
source I compiled. For example, it does not tell me that do_loop() called
printf().

Nope, it doesn't. printf() is in our library -- so it's not instrumented.
If I understand it properly, the call information is put in the prefix
of the called function -- so any of your functions that get called should
have call count information -- but if you call functions from our library,
from source files not compiled -p, from your libraries not compiled -p,
etc, you won't get call count information for those.


The sampling information is all over the place. If I reduce the
iterations
in do_loop(), the sampling information doesn't even mention printf(). It
never mentions usleep(). With a higher number of iterations (like 99999),
I
get a couple of little coloured bars in the text editor, but they don't
correspond to where the program would have run. I only see 1 green and 1
blue bar - no breakdown at all. With 999 iterations, I don't get any
coloured bars.

I ran it, I got coloured bars with 999 iterations. But, I ran it on
a pretty slow CPU target. (A VMWare session, in fact.) I got a little
bit of CPU attributed to the loop in do_loop(), but looking at the
Sampling information, most of the CPU was attributed to some unknown
function -- I'm going to have to check with a developper as to what
is going on for that. I'm pretty sure that would be the printf().
(And, you won't see the time in a function attributed to the function
call line in the editor.)

Your usleep() is 1000 usec, which is 1 ms -- with a sampling rate of
1ms, I wouldn't expect much attributed to usleep(). It might be another
of the "unknown" functions I'm seeing.


I have attached a screenshot of the editor after a profile. This is about
as
much useful information as I can get out of it.

I tried to view the screenshot, but got a garbled image. :(


There is no way to look at the profiling data statistically. No logs, or
textual data, such as the actual numbers that the %Time Usage bars are
drawn
from. For CPU usage, all I can get are little coloured bars, and then
only
if I am perseverent and lucky.

Are you just looking at the editor for the sampling data, or are you
actually using the QNX Application Profiler perspective, which includes
the Sampling Information and Call Information views which both provide
statistics summaries?

When you launched with profiling, did you click the "Switch to this
Tool's Perspective on Launch" choice to open it automatically?


This is not a tool worthy of the advertising hype that populates the help
documentation. If the documents spent as much time telling me *how* to
use
their brilliant, time-saving, modular, single, consistent, integrated
environment as they spent placing adjectives in front of their products,
I
may have less to complain about. Unfortunately it seems the deficiencies
are
in the product also - not only the documentation. This is especially true
of
the profiling and update/installation perspectives.

The update/installation perspective is core Eclipse, and should be
documented in the Eclipse docs, through the Help->Help Contents
menu, in particular I think this is talked about in the Workbench
Users Guide -> Tasks -> Updating Features with the update manager.

The IDE docs seem to be task-oriented, rather than reference oriented.


Just try to save a source file to My Documents quickly - or open an
external
c file in an existing editor.

That is an Eclipse paradigm, it works within a subset of the directory
structure, the workspace, and expects everything to be there.
(I think this is not uncommon with IDEs -- they import/export stuff,
but only really deal with stuff that is in their more limitted
view/working
area.)

I found it frustrating, too, though.

Hope some of this helps.

-David
--
David Gibbs
QNX Training Services
dagibbs@qnx.com


--
cburgess@qnx.com

David Gibbs

Re: IDE Profiling

Post by David Gibbs » Tue Nov 23, 2004 3:11 pm

Robert Muil <r.muil@crcmining.com.au> wrote:
I don't know about Visual Studio. I do know that gprof lies. (Well, it
makes naive assumptions and reports them as fact.)

Consider:

expensive_func( int COUNT )
{
/* do something time consuming COUNT times */
}

funca() { expensive_func( 10 ); }
funcb() { expensive_func( 1000 ); }
int main() {
while(1) {
funca();
funcb();
}
}

I cannot get stats for this, with gprof. I compile it with 'cc -g -p
main.c', then run it with ./a.out to generate the gmon.out. When I run
gprof, it tells me the call counts, but contains no times at all.
Wasn't intended to be a compilable example -- I'll include at the end
the actual sample code I used, and the gprof output.

The relevant bits are:
-----------------------------------------------
0.00 0.47 23/23 main [1]
[5] 50.7 0.00 0.47 23 afunc [5]
0.01 0.46 23/45 dofuncs [3]
-----------------------------------------------
0.00 0.45 22/22 main [1]
[6] 48.6 0.00 0.45 22 bfunc [6]
0.01 0.44 22/45 dofuncs [3]

Note that the CPU% attributed to afunc vs bfunc is, basically,
the number of times they've called dofuncs, over total times
dofuncs() is called. (23/45 = 51.1%, 22/45 = 48.9%).

Also, to get time data, you need to run the program as root --
the profiling code attaches an interrupt handler to the timer
interrupt to get the sampling data, if it can't attach the
interrupt, all it can get is the call count.

Yes, and we work to fix bugs in the Eclipse core, and to get features
or extensions we want/need into the core.
I think the editiability of functions outside the workspace is supposed
to be much better with the next generation of the core Eclipse tools.

That's good to hear. Will this be available for 6.2.1 or just >6.3.0?
I think it is added to the core with Eclipse 3.0. It will definitely
be post 6.3.0.
Also, I have read all that documentation, and it is not very helpful.

And, the update tools is one that is not needed for useage as a QNX
development environment -- unless you're adding someone else's tools
to the IDE. We try to enhance documentation as needed for core pieces
that are used for QNX development, as well as documenting the non-core
pieces that are QNX specific.

I appreciate that people like yourself do, and QNX's development is
admirable. But please, less marketing hype. Aim the documentation at
technicians and engineers, not other marketing departments.
Wish I could control the marketing hype. But, apparently, the marketing
people think that generating hype is their job.
I can add a huge list of other complaints, at the top of which would be:
+ my workbench layou is "failed to load" almost every time I run the IDE

Does it generate a .log file when it fails? Check in workspace/.metadata
for a file called ".log". Each time the IDE has an error, it is supposed
to generate a log to that file. Posting the .log file with a description
of the error may allow the problem to be resolved.

I have looked through this log and am none the wiser, but I will post it
when the error occurs again (the whole log file is formidably large atm).
You don't generally need to post the whole log -- each entry (which
is multiple lines long) is dated at the start of the entry. Also,
if the IDE is not running, you can just delete the .log file, to start
from a clean log.

(Each entry in the log will start with the key string "!ENTRY".)

+ javaw.exe locks on 100% CPU nearly every 2nd time I run the IDE

Can you describe what you do to trigger this fault?

So far, the only common trigger is running the IDE. It is usually associated
with a debugging or system information session, but it is intermittent.
Is it also associated with a loss of connectivity to the client? Either
through client restart, qconn crash, or other such thing? If debugging,
do you find a nto_gdb* process running using lots of CPU? If so, does
killing that process off help recover?

-David

Flat profile:

Each sample counts as 0.001 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
68.06 0.63 0.63 44 14386.36 14386.36 func2
29.46 0.91 0.27 45 6088.89 6088.89 func1
1.61 0.92 0.01 45 333.33 20488.89 dofuncs
0.75 0.93 0.01 1 7000.00 930000.00 main
0.11 0.93 0.00 22 45.45 20534.34 bfunc
0.00 0.93 0.00 23 0.00 20488.89 afunc
0.00 0.93 0.00 1 0.00 0.00 options

% the percentage of the total running time of the
time program used by this function.

cumulative a running sum of the number of seconds accounted
seconds for by this function and those listed above it.

self the number of seconds accounted for by this
seconds function alone. This is the major sort for this
listing.

calls the number of times this function was invoked, if
this function is profiled, else blank.

self the average number of milliseconds spent in this
ms/call function per call, if this function is profiled,
else blank.

total the average number of milliseconds spent in this
ms/call function and its descendents per call, if this
function is profiled, else blank.

name the name of the function. This is the minor sort
for this listing. The index shows the location of
the function in the gprof listing. If the index is
in parenthesis it shows where it would appear in
the gprof listing if it were to be printed.

Call graph (explanation follows)


granularity: each sample hit covers 4 byte(s) for 0.11% of 0.93 seconds

index % time self children called name
0.01 0.92 1/1 _start [2]
[1] 100.0 0.01 0.92 1 main [1]
0.00 0.47 23/23 afunc [5]
0.00 0.45 22/22 bfunc [6]
0.00 0.00 1/1 options [8]
-----------------------------------------------
<spontaneous>
[2] 100.0 0.00 0.93 _start [2]
0.01 0.92 1/1 main [1]
-----------------------------------------------
0.01 0.44 22/45 bfunc [6]
0.01 0.46 23/45 afunc [5]
[3] 99.1 0.01 0.91 45 dofuncs [3]
0.63 0.00 44/44 func2 [4]
0.27 0.00 45/45 func1 [7]
-----------------------------------------------
0.63 0.00 44/44 dofuncs [3]
[4] 68.1 0.63 0.00 44 func2 [4]
-----------------------------------------------
0.00 0.47 23/23 main [1]
[5] 50.7 0.00 0.47 23 afunc [5]
0.01 0.46 23/45 dofuncs [3]
-----------------------------------------------
0.00 0.45 22/22 main [1]
[6] 48.6 0.00 0.45 22 bfunc [6]
0.01 0.44 22/45 dofuncs [3]
-----------------------------------------------
0.27 0.00 45/45 dofuncs [3]
[7] 29.5 0.27 0.00 45 func1 [7]
-----------------------------------------------
0.00 0.00 1/1 main [1]
[8] 0.0 0.00 0.00 1 options [8]
-----------------------------------------------

This table describes the call tree of the program, and was sorted by
the total amount of time spent in each function and its children.

Each entry in this table consists of several lines. The line with the
index number at the left hand margin lists the current function.
The lines above it list the functions that called this function,
and the lines below it list the functions this one called.
This line lists:
index A unique number given to each element of the table.
Index numbers are sorted numerically.
The index number is printed next to every function name so
it is easier to look up where the function in the table.

% time This is the percentage of the `total' time that was spent
in this function and its children. Note that due to
different viewpoints, functions excluded by options, etc,
these numbers will NOT add up to 100%.

self This is the total amount of time spent in this function.

children This is the total amount of time propagated into this
function by its children.

called This is the number of times the function was called.
If the function called itself recursively, the number
only includes non-recursive calls, and is followed by
a `+' and the number of recursive calls.

name The name of the current function. The index number is
printed after it. If the function is a member of a
cycle, the cycle number is printed between the
function's name and the index number.


For the function's parents, the fields have the following meanings:

self This is the amount of time that was propagated directly
from the function into this parent.

children This is the amount of time that was propagated from
the function's children into this parent.

called This is the number of times this parent called the
function `/' the total number of times the function
was called. Recursive calls to the function are not
included in the number after the `/'.

name This is the name of the parent. The parent's index
number is printed after it. If the parent is a
member of a cycle, the cycle number is printed between
the name and the index number.

If the parents of the function cannot be determined, the word
`<spontaneous>' is printed in the `name' field, and all the other
fields are blank.

For the function's children, the fields have the following meanings:

self This is the amount of time that was propagated directly
from the child into the function.

children This is the amount of time that was propagated from the
child's children to the function.

called This is the number of times the function called
this child `/' the total number of times the child
was called. Recursive calls by the child are not
listed in the number after the `/'.

name This is the name of the child. The child's index
number is printed after it. If the child is a
member of a cycle, the cycle number is printed
between the name and the index number.

If there are any cycles (circles) in the call graph, there is an
entry for the cycle-as-a-whole. This entry shows who called the
cycle (as parents) and the members of the cycle (as children.)
The `+' recursive calls entry shows the number of function calls that
were internal to the cycle, and the calls entry for each member shows,
for that member, how many times it was called from other members of
the cycle.


Index by function name

[5] afunc [7] func1 [8] options
[6] bfunc [4] func2
[3] dofuncs [1] main

/*
* appprofile_looper
*
* This is a sample for demonstrating the use of the application profiler
* tool. It is a very phoney but effective sample (i.e. it does nothing
* practical but is useful for demonstrating profiling).
*
* If you run it with no command line arguments then it will loop forever.
* On SIGINT or SIGTERM it will exit and write a gmon.out file.
*
*
*/

#include <stdlib.h>
#include <stdio.h>
#include <inttypes.h>
#include <sched.h>
#include <unistd.h>
#include <pthread.h>

void *other_thread (void *arg);
void dofuncs (uint64_t count);
uint64_t func1 (uint64_t n);
uint64_t func2 (uint64_t n);
void options (int argc, char **argv);

int loop_once; /* -o to have it loop only once */
int optv; /* -v for verbose operation */
char *progname;
int tid;

void sig_exit( int signo )
{
pthread_cancel(tid );
printf("exit from sig exit\n");
exit(EXIT_SUCCESS );
}
void afunc()
{
dofuncs (1000000);
}

void bfunc()
{
dofuncs (100000);
}

int
main (int argc, char *argv[])
{
progname = argv[0];
setvbuf(stdout, NULL, _IOLBF, BUFSIZ );
printf ("%s: starting...\n", progname);
options (argc, argv);

signal( SIGTERM, sig_exit );
signal( SIGINT, sig_exit );

setprio (0, 5); /* run at low priority, 5, so we don't hog CPU */

//pthread_create (&tid, NULL, other_thread, NULL);

while (1) {
afunc();
bfunc();
}
printf ("%s: exiting...\n", progname);

return EXIT_SUCCESS;
}

void *
other_thread (void *arg)
{
while (1) {
dofuncs (100000);
if (loop_once)
break;
delay (1); /* put a minimal delay so that this thread will run less */
}
return NULL;
}

void
dofuncs (uint64_t count) /* dofuncs() is an excuse to have more call layers */
{
//uint64_t count = 1000000; /* larger is better */

func1 (count);
func2 (count);
}

uint64_t
func1 (uint64_t n) /* 33.3% of total run time */
{
volatile uint64_t a, b, c;

if (optv)
printf ("%s: Now in func1()\n", progname);
for (a = 0; a < 2*n; a++) {} /* 50% of func1() time */
for (b = 0; b < n; b++) {} /* 25% of func1() time */
for (c = 0; c < n; c++) {} /* 25% of func1() time */
return 1;
}

uint64_t
func2 (uint64_t n) /* 66.7% of total run time */
{
volatile uint64_t d, e;

if (optv)
printf ("%s: Now in func2()\n", progname);
for (d = 0; d < n; d++) {} /* 12.5% of func2() time */
for (e = 0; e < 7*n; e++) {} /* 87.5% of func2() time */
return 1;
}

/*
* options
*
* This routine handles the command line options.
* We support:
* -o loop only once
* -v verbose operation
*/

void
options (int argc, char **argv)
{
int opt;

optv = 0;
loop_once = 0;

while ((opt = getopt (argc, argv, "ov")) != -1) {
switch (opt) {
case 'o':
loop_once = 1;
break;
case 'v':
optv = 1;
break;
}
}
}
--
David Gibbs
QNX Training Services
dagibbs@qnx.com

David Gibbs

Re: IDE Profiling

Post by David Gibbs » Tue Nov 23, 2004 3:11 pm

John Garvey <jgarvey@qnx.com> wrote:
Robert Muil wrote:
I cannot get stats for this, with gprof. I compile it with 'cc -g -p
main.c', then run it with ./a.out to generate the gmon.out. When I run
gprof, it tells me the call counts, but contains no times at all.

What happens if you run the profiled a.out as root? I found that gprof
did not give me times (call counts only) when I was non-root, then
repeating the run after doing a "su" I got non-0 timing figures:
Yeah, it attaches an interrupt handler to the timer to do the sampling.
No interrupt handler, no samples.

-David
--
David Gibbs
QNX Training Services
dagibbs@qnx.com

David Gibbs

Re: IDE Profiling

Post by David Gibbs » Tue Nov 23, 2004 3:56 pm

Robert Muil <r.muil@crcmining.com.au> wrote:
Steve,

I have added -gdwarf-2 to CCFLAGS and LDFLAGS in Makefile.
CFLAGS or CCFLAGS?

(I thought CFLAGS was for C code, CCFLAGS for C++ code, but I could
be wrong.)
It makes no difference - the line references all place me (and the coloured
bars) 1 code line below the actual line.

Is there supposed to be a GUI option to modify these settings, or have I
done it correctly?
Is it a QNX C project, or a Standard Make project?

If a QNX C project, you probably need to do it through the GUI, you're
not supposed to edit the Makefile. (In fact, I don't know what editing
the Makefile does.)

I don't have a 6.2.1 IDE around anymore to check exactly how to do it with
6.2.1.
Does the binary parser option in project settings have anything to do with
this?
For a QNX project, it should be set properly automatically.

For 6.2.1, I don't remember for sure, but for a Standard Make project,
it should probably be set to QNX Binary parser. I don't think it will
make a difference, but I'm not sure.

-David
--
David Gibbs
QNX Training Services
dagibbs@qnx.com

David Gibbs

Re: IDE Profiling

Post by David Gibbs » Tue Nov 23, 2004 4:02 pm

Robert Muil <r.muil@crcmining.com.au> wrote:
I copied the source, profiled it, and got completely different results,
though. (And, I got the results I expected, too.)

I don't understand that. Are you using 6.2.1 IDE? Why would I get completely
different results?
I'm using a 6.3.0 IDE. I don't have a 6.2.1 installation around.
I do not think you can get this information. I do not think the data
needed to answer this question is generated. (That is, I don't think
gprof could tell you this either.)

I do not understand how the profiler can be used, therefore, to give useful
information. This seems to me to be so fundamental as to erode the purpose
of the profiler. It is akin to measuring the pressure on soldiers' feet to
determine the movement an army.
For an application that is 99% library code, 1% user code it doesn't help
much. For an application that is 10% library code, and 90% user code,
the tool can help a lot more.

-David
--
David Gibbs
QNX Training Services
dagibbs@qnx.com

Chris Herborth

Re: IDE Profiling

Post by Chris Herborth » Tue Nov 23, 2004 6:24 pm

David Gibbs wrote:
I have added -gdwarf-2 to CCFLAGS and LDFLAGS in Makefile.

CFLAGS or CCFLAGS?

(I thought CFLAGS was for C code, CCFLAGS for C++ code, but I could
be wrong.)
David is correct, CFLAGS for C code, CCFLAGS for C++ code.

--
Chris Herborth (cherborth@qnx.com)
Never send a monster to do the work of an evil scientist.

Chris Herborth

Re: IDE Profiling

Post by Chris Herborth » Tue Nov 23, 2004 6:27 pm

Robert Muil wrote:
I appreciate that people like yourself do, and QNX's development is
admirable. But please, less marketing hype. Aim the documentation at
technicians and engineers, not other marketing departments.
The IDE User's Guide has had quite a number of changes for SP1, but
we're always interested in specific feedback about the docs...

--
Chris Herborth (cherborth@qnx.com)
Never send a monster to do the work of an evil scientist.

Chris Herborth

Re: IDE Profiling

Post by Chris Herborth » Tue Nov 23, 2004 6:35 pm

David Gibbs wrote:
[... need to run as root to get times in profiling data ...]
Yeah, it attaches an interrupt handler to the timer to do the sampling.
No interrupt handler, no samples.
The IDE docs don't mention this, so I'll file a PR.

--
Chris Herborth (cherborth@qnx.com)
Never send a monster to do the work of an evil scientist.

David Gibbs

Re: IDE Profiling

Post by David Gibbs » Tue Nov 23, 2004 7:25 pm

Chris Herborth <cherborth@qnx.com> wrote:
David Gibbs wrote:
[... need to run as root to get times in profiling data ...]
Yeah, it attaches an interrupt handler to the timer to do the sampling.
No interrupt handler, no samples.

The IDE docs don't mention this, so I'll file a PR.
Not sure the IDE docs need to mention it -- the IDE launches everything
through qconn, which runs as root.

This only matters if you are trying to do profiling by running from the
commandline.

-David
--
David Gibbs
QNX Training Services
dagibbs@qnx.com

Chris Herborth

Re: IDE Profiling

Post by Chris Herborth » Tue Nov 23, 2004 8:30 pm

David Gibbs wrote:
This only matters if you are trying to do profiling by running from the
commandline.
And since we support loading profiler output generated by running from
the command-line, people should know how to do it... ;-)

--
Chris Herborth (cherborth@qnx.com)
Never send a monster to do the work of an evil scientist.

Robert Muil

Re: IDE Profiling

Post by Robert Muil » Wed Nov 24, 2004 4:55 am

Wasn't intended to be a compilable example -- I'll include at the end
the actual sample code I used, and the gprof output.
:)

I didn't try to compile what you posted. I added relevant code. Run as root,
I get similar results to you. I see that your point is valid - and very
surprising. gprof is blatantly fabricating information.

Word up to Microsoft for their profiler.
I think it is added to the core with Eclipse 3.0. It will definitely
be post 6.3.0.
So support and development for 6.2.1 is over?

Robert Muil

Re: IDE Profiling

Post by Robert Muil » Wed Nov 24, 2004 4:58 am

I'm using a 6.3.0 IDE. I don't have a 6.2.1 installation around.
So would I be, if it wasn't completely incompatible with 6.2.1 targets.
I do not understand how the profiler can be used, therefore, to give
useful
information. This seems to me to be so fundamental as to erode the
purpose
of the profiler. It is akin to measuring the pressure on soldiers' feet
to
determine the movement an army.

For an application that is 99% library code, 1% user code it doesn't help
much. For an application that is 10% library code, and 90% user code,
the tool can help a lot more.
Not if the bottleneck is the 1% of user code that calls 90% of the library
code.

Robert Muil

Re: IDE Profiling

Post by Robert Muil » Wed Nov 24, 2004 5:03 am

Agreed, and I have played with samples that just spin etc, but I was trying
to work out how to look at cumulative times.

Robert.

"Colin Burgess" <cburgess@qnx.com> wrote in message
news:cnvg2p$23e$1@inn.qnx.com...
I don't want to get into the functionality of the profiler too much, but
the test program in your source is going to spend 99.9% of it's time in
libc functions usleep (which will end up being a TimerTimeout ) and printf
(all sorts of libc functions).

Since libc isn't profiled, this will cause varying and unclear results.

Robert Muil wrote:
David,

I hope this screenshot is viewable. It should show how complicated a
process it is to profile even a stupidly simple program.

To determine how much time is spent in do_loop (), and where that is
spent, I first must find out what resolve_rels(), lookup(), hash(),
ConnectAttach(), static_strcmp(), __SysCpupageGet(), _dladdr() functions
are. Most are not even mentioned in the documentation (although this is
hard to be certain of because there is no index).

I must then work out where they are being called from.

I must then work out how much time they are using, presumably by guessing
percentage CPU from the %Time Usage bar or and calculating time in
functions as an percentage of the overall program run time (which would
need to be determined, I suppose, with a separate tool).

I hope that I am wrong about this. If so, please tell me how I can use
the information shown in the Profiler perspective to tell how much time
has been used by the do_loop() function, and where that time was spent).

Also note the coloured bars in the c editor. What is this supposed to
suggest, beyond that QNX likes the sound of its own name and has coloured
in the margin to highlight it?

Robert.


"David Gibbs" <dagibbs@qnx.com> wrote in message
news:cnl3nr$5n4$1@inn.qnx.com...

Robert Muil <r.muil@crcmining.com.au> wrote:

David,

I am unable to determine how long a program spends, cumulatively, in a
function.

Total time directly in a function would be given by the total time in
Sampling information view.

Or, do you mean for a function, and all sub-functions, cumulated to that
function?


It does not help me to know that 5% of my time was in ldiv() or .plt()
(whatever they are). I want to know that 100% was in main(), then 90% of
that was in do_loop(), etc.

Sounds like that's what you want. That can't be done. Well, in theory
it can be done, but the data collection to provide that would be
enormous.
What the profiler does is collect 2 types of information -- it annotates
any code compiled with profiling to get function call counts (basically
call pairs), and it samples the execution of the program from the timer
interrupt, storing the current IP, and active thread at that point.
Then,
the time useage is "estimated" based on the sampling -- but it doesn't
know what the call path to get to the function is. To get the cumulative
sub-function useage your asking for, at every sample point a full stack
backtrace would have to be collected and stored -- the overhead to
collect
that information, and store that information, would be quite impressive,
and heavily impact whatever you were trying to profile. Also, the tool
chain (GCC) doesn't supply tools to do that.

Why would full backtrace be neede?
Consider the following:

int func1() { /* use lots of CPU */}
int funca() { func1(); }
int funcb() { func1(); }
int main() { while (1) { funca(); funcb(); } }

Now, is CPU time spent in func1() attributed to funca() or funcb()?
Without
a stack backtrace, you can't know.


Also, it does not seem to correctly read the symbol table. I have a very
simple program to test, which just loops and does a few printfs. When I
profile it, the calling information only displays call information for
the
source I compiled. For example, it does not tell me that do_loop()
called
printf().

Nope, it doesn't. printf() is in our library -- so it's not
instrumented.
If I understand it properly, the call information is put in the prefix
of the called function -- so any of your functions that get called should
have call count information -- but if you call functions from our
library,
from source files not compiled -p, from your libraries not compiled -p,
etc, you won't get call count information for those.


The sampling information is all over the place. If I reduce the
iterations
in do_loop(), the sampling information doesn't even mention printf(). It
never mentions usleep(). With a higher number of iterations (like
99999), I
get a couple of little coloured bars in the text editor, but they don't
correspond to where the program would have run. I only see 1 green and 1
blue bar - no breakdown at all. With 999 iterations, I don't get any
coloured bars.

I ran it, I got coloured bars with 999 iterations. But, I ran it on
a pretty slow CPU target. (A VMWare session, in fact.) I got a little
bit of CPU attributed to the loop in do_loop(), but looking at the
Sampling information, most of the CPU was attributed to some unknown
function -- I'm going to have to check with a developper as to what
is going on for that. I'm pretty sure that would be the printf().
(And, you won't see the time in a function attributed to the function
call line in the editor.)

Your usleep() is 1000 usec, which is 1 ms -- with a sampling rate of
1ms, I wouldn't expect much attributed to usleep(). It might be another
of the "unknown" functions I'm seeing.


I have attached a screenshot of the editor after a profile. This is
about as
much useful information as I can get out of it.

I tried to view the screenshot, but got a garbled image. :(


There is no way to look at the profiling data statistically. No logs, or
textual data, such as the actual numbers that the %Time Usage bars are
drawn
from. For CPU usage, all I can get are little coloured bars, and then
only
if I am perseverent and lucky.

Are you just looking at the editor for the sampling data, or are you
actually using the QNX Application Profiler perspective, which includes
the Sampling Information and Call Information views which both provide
statistics summaries?

When you launched with profiling, did you click the "Switch to this
Tool's Perspective on Launch" choice to open it automatically?


This is not a tool worthy of the advertising hype that populates the
help
documentation. If the documents spent as much time telling me *how* to
use
their brilliant, time-saving, modular, single, consistent, integrated
environment as they spent placing adjectives in front of their products,
I
may have less to complain about. Unfortunately it seems the deficiencies
are
in the product also - not only the documentation. This is especially
true of
the profiling and update/installation perspectives.

The update/installation perspective is core Eclipse, and should be
documented in the Eclipse docs, through the Help->Help Contents
menu, in particular I think this is talked about in the Workbench
Users Guide -> Tasks -> Updating Features with the update manager.

The IDE docs seem to be task-oriented, rather than reference oriented.


Just try to save a source file to My Documents quickly - or open an
external
c file in an existing editor.

That is an Eclipse paradigm, it works within a subset of the directory
structure, the workspace, and expects everything to be there.
(I think this is not uncommon with IDEs -- they import/export stuff,
but only really deal with stuff that is in their more limitted
view/working
area.)

I found it frustrating, too, though.

Hope some of this helps.

-David
--
David Gibbs
QNX Training Services
dagibbs@qnx.com




--
cburgess@qnx.com

Robert Muil

Re: IDE Profiling

Post by Robert Muil » Wed Nov 24, 2004 5:19 am

I have added -gdwarf-2 to CCFLAGS and LDFLAGS in Makefile.

CFLAGS or CCFLAGS?

(I thought CFLAGS was for C code, CCFLAGS for C++ code, but I could
be wrong.)
CFLAGS is completely ignored.
Is there supposed to be a GUI option to modify these settings, or have I
done it correctly?

Is it a QNX C project, or a Standard Make project?
A QNX C project.
If a QNX C project, you probably need to do it through the GUI, you're
not supposed to edit the Makefile. (In fact, I don't know what editing
the Makefile does.)
There is no way to modify the command line in the 6.2.1 IDE.
Does the binary parser option in project settings have anything to do
with
this?
For a QNX project, it should be set properly automatically.
It is not set by default: the 2 radio buttons are both blank.
For 6.2.1, I don't remember for sure, but for a Standard Make project,
it should probably be set to QNX Binary parser. I don't think it will
make a difference, but I'm not sure.
There is no 'QNX binary parser'. It is either 'Elf Parser' or 'PE Windows
Parser'. The distinction eludes me.

Post Reply

Return to “qnx.development_tools”