4GL Profiler

Posted by ChUIMonster on 28-Feb-2007 07:11

Consider the following:

Which produces this file, "prof.out":

1 02/28/2007 "Generic" 07:55:03 "tom"

.

2 "profile.p" "" 63126

.

0 0 2 1

.

0 0 1 0.000000 30.935828

2 11 1 0.000002 0.000002

2 8 1000001 4.607678 4.607678

2 9 1000000 1.719586 1.719586

2 14 1000000 1.501487 1.501487

2 12 1000001 3.013981 3.013981

2 13 1000000 3.032433 3.032433

2 16 1 0.000003 0.000003

.

.

.

.

Note the result for line 16 (the last line shown in prof.out). (The module 0, line 0 line is also curious but it isn't my focus right now.)

I can assure you that it took much longer the 0.000003 seconds for that code to execute

It would seem that source lines with multiple statements on them are not correctly accounted for.

Is this a known bug?

.

All Replies

Posted by svi on 12-Oct-2007 14:36

Tom,

I did a quick search to the bug database and could not find this. Tech Support has better tools to find known issues though. When you can please report it to them.

Thanks

Salvador

Posted by Matt Baker on 12-Oct-2007 16:09

Hi tom,

A while ago a did a ui rewrite for my own personal use on the profiler tool that ships with the full install of OE Studio. There is a copy of it somewhere on PSDN.

Calling profiler:enabled isn't an instantaneous process. I've experienced delays of a couple of seconds while it chugs away. Try stepping through with the debugger or wrapping those lines in an etime and you can see them more clearly.

The line 0 stuff is load times for the procedure. There is overhead involved in loading a .p and possibly doing a compile on it those times are associated with the line 0.

Posted by ChUIMonster on 20-Nov-2007 08:22

At the NEPUG meeting the other night someone (not me, although I heartily support the notion) brought up the point that on occasions, such as this, PSC employees really ought to take the initiative and be proactive about entering bugs and enhancement requests and such...

Posted by Tim Kuehn on 20-Nov-2007 08:24

At the NEPUG meeting the other night someone (not me,

although I heartily support the notion) brought up

the point that on occasions, such as this, PSC

employees really ought to take the initiative and be

proactive about entering bugs and enhancement

requests and such...

In one of my chats with PSC TS, the policy that was relayed to me was that they TS was being discouraged if not forbidden from doing so, in favor of the customer going to the oh-so-modern ERS and entering the request themselves.

Posted by ChUIMonster on 20-Nov-2007 08:29

Matthew,

I think you may have missed the point. I know what line 0 is all about and why it can take a bit of time. And I know that the elapsed time is wrong. I don't really care what the value itself is nor do I particularly need to see the code with the debugger.

The bug is that the profiler will only report timings for the last statement on a line rather than the sum of all statements on that line. This can lead people to miss the very performance problems that they are looking for with this tool. The sort of coding illustrated is IMHO most likely to be used when one is in a "tight coding" mindset writing small tight loops where performance adds up -- precisely the wrong sort of place for the profiler to make such a mistake.

I believe that the fix is probably pretty simple once the problem is noticed and reported.

Posted by Tim Kuehn on 20-Nov-2007 08:37

The bug is that the profiler will only report timings

for the last statement on a line rather than the sum

of all statements on that line. This can lead people

to miss the very performance problems that they are

looking for with this tool.

I believe that the fix is probably pretty simple once

the problem is noticed and reported.

I have my doubts - "last line reporting" isn't limited to the profiler too, it happens with compile processes as well, and what the compiler decides is the "current" line.

For instance, if one saves and compiles the following code:

IF YES THEN

MESSAGE "hello world" + 1

VIEW-AS ALERT-BOX INFO BUTTONS OK.

The compiler will report an error on line 1, not 3 - because the compiler defines the "IF" as the first line of the statement, not the MESSAGE statement.

On the other hand, if the statement is coded like so:

IF YES THEN

DO:

MESSAGE "hello world" + 1

VIEW-AS ALERT-BOX INFO BUTTONS OK.

END.

then the compiler reports the error on the correct line.

It would seem that the only real workaround is to refactor the existing code so the compiler - and performance tracker - will report the information one expects.

I think this issue is embedded so deeply in the existing architecture that resolving issues like is being seen with the performance tracking may be a lot harder to resolve than one might otherwise expect.

Posted by ChUIMonster on 20-Nov-2007 09:27

I'm just guessing that it isn't "hard".

I really just want it fixed.

Refactoring the code isn't a viable solution because the code being profiled is often not in the control of the one doing the profiling. As a performance consultant, for instance, I can hardly tell clients that they must first refactor their code before I start trying to find problems with it...

This thread is closed