Comments on Another Profile Creator Function

[David Roberts]

Re here.

[Gösta H. Lovgren-2]

Dave said:

The approaches differ in that Gösta's code is more string oriented and mine is more array oriented although both use Array Sort. Some procedures need to be excluded and I chose an exclusion list whereas Gösta chose to scan the Win32API.inc file which takes longer

Some clarification here. While I'm sure using a string method of handling stuff takes longer, time is not really a factor here. The Profile routine only gets called once and even with the variables included and the clumsy sort associated with them, the entire Profile only takes a second (certainly less than two) to run.

Another difference is the UDT elements are sorted as found in my case whereas with Gösta's approach the elements are effectively transferred to the primary element as that is how arrays of UDTs are sorted pre PB9/CC5. So, Gösta's code will work with pre PB9/CC5, unless Gösta is using PB9/CC5 'stuff' that I haven't spotted, whereas mine will not.

I'm not sure what you mean here, Dave. The all fields are sorted in the final output. I'm missing what pre/post PB9/CC5 has to do with it.

That said, I'm going to try your version, and if I see anything I can add to or improve my/our version, I will shamelessly and unapologetically appropriate it. {grin}

[Gösta H. Lovgren-2]

Just ran it, Dave. Changed the output name to "_ProfileDR.txt" so was able to compare the two outputs side by side in a text editor.

I see now it's easier reading the lists if the names are Lset. I had Rset them so as make it easier following across the lines. (Changes will be made).

I think the % column is easier/quicker reading/scanning without the tenth's showing. I mean in this application does 15.4% tell you any more than 15% ? I suppose there may be cases where the tenths are important to know but I prefer the less cluttered readability (IMO). Ditto for Using$("#, ", ) the longer numbers. The comma format makes the numbers stand out better/quicker.

And I think the UnCalled's are more easily readable/scanned in column form. Could do it in a couple three columns is you are concerned about document length.

Another thought. At the top if the Include, put

'ProfileReportDR.inc 
'http://www.powerbasic.com/support/pbforums/showthread.php?t=39185

Just a tad more convenient for the programmer.

[David Roberts]

Thanks for your comments, Gösta. I'll go over them one by when I have a spare moment.

In the meantime I'm trying to break the Egress concept.

I've just tried

Egress("MyThread")
Thread Create MyThread( 0 ) To hThread

and it came through in one piece.

There are some weird and wonderful ways of calling procedures so it is a case of searching through my files to see if Egress is capable of handling them all and if not what is required to make it so.

[David Roberts]

I had a look at your comments, Gösta. I won't be making any changes - the output suits me. If anyone downloads it for its intended purpose I'm sure that they will be more than capable of editing it to suit them.

[David Roberts]

Extended profiling enhanced.

ProfileReport.inc has been renamed to ProfileEx.inc and the 'Extended profiling' code has been enhanced such that the output now is effectively a list of recommendations.

[Gösta H. Lovgren-2]

Dave, you need to add an "End Function" at the bottom your code. It must have gotten lost during C&P.

Launching NotePad is a nice touch. Think I'll steal it. {grin} Probably have it as an option, though, so it doesn't pop up every time.

Note some may find it useful to create a "Profile" folder and occasionally save Profiles under a dated (Timed) name (ie. "2008-11-15 Life Profile.txt") to have for reference when working on a program. Probably put applicable notes at the top of it Profile (ie "Used Pointers here"., "Used Long Arrays instead of strings here.", etc.) before saving it.

Writing this gives me an idea. Think I'll add a date stamp to the name. That way a new file is created every day. As an Option, of course.

[David Roberts]

Dave, you need to add an "End Function" at the bottom your code. It must have gotten lost during C&P.

That was because there's more work to be done.

Thanks, Gösta.

[David Roberts]

Final version published.

NotePad is now only invoked on a short report request. A short report only includes 'Uncalled procedures', if any, an extended profile if Egress is employed with the procedure's influence sorted at the end of the report.

A full report is dumped to file but not NotePad.

[David Roberts]

Gösta has written: "...but with 60-70 procedures it's just too much work to add an Egress call to each."

I had already written: "There is no such thing as a free lunch, so they say, and that applies here too. Too get extended profiling we have to get our hands dirty."

Egress("") can be pasted many times fairly quickly. All we need do now is copy the procedure name and paste it between the inverted commas. Admittedly, not a few seconds job but not that bad.

With regard the 'Life' program a 50 minute run saw PBMain get a 99.8% influence rating. It was worth the effort because this tells us that the procedures had very little influence and any speed improvements were going to come from PBMain - a conclusion that normal profiling would not give since PBMain is not profiled.

Probably be better to divide the TickCount by whatever to get the actual seconds elapsed.

Profile for C:\Only_My_Programs\Life\Life_ProfileEx.txt
11-24-2008 Ran from 8:36:12 to 08:36:20 for 431,429 seconds

Looks lke you still have Timer at the head of PBMain, Gösta and restarted your system at about 08:29?

At the head of the latest version we have:

'-------------------------------------------------------
'  ProfileEx.inc for PB9 or CC5
'
'  At the top of PBMain put the following lines:
'
'  Local Profile_Start_Time As Long
'  Profile_Start_Time = GetTickCount
'  lMaxSize = 999
'  ReDim ThisProfile( 0 To lMaxSize ) As ExtendedProfile
'  Local i As Long
'  For i = 0 To lMaxSize
'    ThisProfile(i).Caller = "~"
'    Thisprofile(i).Called = "~"
'  Next
'
' At the bottom of PBMain put this line:
'
' Either
'   ProfileEx(Profile_Start_Time, 1) ' for full report
' Or
'   ProfileEx(Profile_Start_Time)    ' for short report
'-------------------------------------------------------

[Gösta H. Lovgren-2]

Gösta has written: "...but with 60-70 procedures it's just too much work to add an Egress call to each."

I had already written: "There is no such thing as a free lunch, so they say, and that applies here too. Too get extended profiling we have to get our hands dirty."

Egress("") can be pasted many times fairly quickly. All we need do now is copy the procedure name and paste it between the inverted commas. Admittedly, not a few seconds job but not that bad.

With regard the 'Life' program a 50 minute run saw PBMain get a 99.8% influence rating. It was worth the effort because this tells us that the procedures had very little influence and any speed improvements were going to come from PBMain - a conclusion that normal profiling would not give since PBMain is not profiled.

Wouldn't PBMain have a high "influence" in any program? It's where all programs stsart and end. I dob't ee any significance to that. Not saying it's not there, I don't see it.

Looks lke you still have Timer at the head of PBMain, Gösta and restarted your system at about 08:29?

At the head of the latest version we have:

'-------------------------------------------------------
'  ProfileEx.inc for PB9 or CC5
'
'  At the top of PBMain put the following lines:
'
'  Local Profile_Start_Time As Long
'  Profile_Start_Time = GetTickCount
'  lMaxSize = 999
'  ReDim ThisProfile( 0 To lMaxSize ) As ExtendedProfile
'  Local i As Long
'  For i = 0 To lMaxSize
'    ThisProfile(i).Caller = "~"
'    Thisprofile(i).Called = "~"
'  Next
'
' At the bottom of PBMain put this line:
'
' Either
'   ProfileEx(Profile_Start_Time, 1) ' for full report
' Or
'   ProfileEx(Profile_Start_Time)    ' for short report
'-------------------------------------------------------

Oh yeah, that "Follow these Directions" thing. Never have been very good at that. {sigh}. I will give it another go this evening. (Turkey time just now.)

=============================================
"How wrong it is for a woman to
expect the man to build the world she wants,
rather than to create it herself."
Anais Nin (1903-1977)
=============================================

[David Roberts]

Wouldn't PBMain have a high "influence" in any program? It's where all programs stsart and end. I dob't ee any significance to that. Not saying it's not there, I don't see it.

Function PBMain()
  Local Profile_Start_Time As Long
  Profile_Start_Time = GetTickCount
  lMaxSize = 999
  ReDim ThisProfile( 0 To lMaxSize ) As ExtendedProfile
  Local i As Long
  For i = 0 To lMaxSize
    ThisProfile(i).Caller = "~"
    Thisprofile(i).Called = "~"
  Next
 
  'Sleep 4000
 
  Egress("MySubA")
  Call MySubA
 
  ProfileEx(Profile_Start_Time)
 
End Function
 
Sub MySubA
Local i As Long
 
  For i = 1 To 100
    Egress("MySubB")
    Call MySubB
  Next
 
  Sleep 1000
 
End Sub

Sub MySubB
Local i As Long

  Sleep 100
     
End Sub

As is we get:

 *** Extended profile ***
 
 Parent procedures:
 
 MYSUBA 11937 8.4% Influence
 
   MySubB       100 x 109 = 10937 [91.6%]
 
 PBMAIN 11938 0% Influence
 
   MySubA       1 x 11937 = 11937 [100%]
 
 Standalone procedures:
 
 MYSUBB 10937 91.6% Influence
 
 Sorted influences (Omitting < 5%):
 
 MYSUBB     91.6%
 MYSUBA      8.4%

PBMain's only function here is to call MySubA so there is no scope in PBMain for 'tweaking'.

Remove the comment from 'Sleep. PBMain is now doing something for 4 seconds of the total 15.938 seconds => 25%.

 *** Extended profile ***
 
 Parent procedures:
 
 MYSUBA 11937 6.3% Influence
 
   MySubB       100 x 109 = 10937 [91.6%]
 
 PBMAIN 15938 25.1% Influence
 
   MySubA       1 x 11937 = 11937 [74.9%]
 
 Standalone procedures:
 
 MYSUBB 10937 68.6% Influence
 
 Sorted influences (Omitting < 5%):
 
 MYSUBB     68.6%
 PBMAIN     25.1%
 MYSUBA      6.3%

There may be scope for tweaking PBMain if that Sleep 4000 was some 'real' code. In the latter example MySubB should still be the first port of call as it is pushing three times more influential.

[David Roberts]

In Life's PBMain I put the Graphic ReDraw, Graphic Clear pair into a function, GRedraw, and subject it to Egress. Previously PBMain had an influence of 99.8%. I didn't run Life long but the influence break down now was about 50/50 between PBMain and GRedraw.

So, half of Life's time is taken up redrawing, not surprising. There may be another area in PBMain worthy of scrutiny but I suspect that it may well be optimal. There's nothing wrong with profiling coming up with '"Looks good to me". One thing is for sure, none of the working procedures, other than PBMain, have a significant influence which must be good news.

[Gösta H. Lovgren-2]

In Life's PBMain I put the Graphic ReDraw, Graphic Clear pair into a function, GRedraw, and subject it to Egress. Previously PBMain had an influence of 99.8%. I didn't run Life long but the influence break down now was about 50/50 between PBMain and GRedraw.

So, half of Life's time is taken up redrawing, not surprising. There may be another area in PBMain worthy of scrutiny but I suspect that it may well be optimal. There's nothing wrong with profiling coming up with '"Looks good to me". One thing is for sure, none of the working procedures, other than PBMain, have a significant influence which must be good news.

Okay I get it now. In Life, PBMain has quite a bit of executing code. By moving it into procedures I could get an even better picture. Nice move putting Redraw & Clear into a function. I'll do that and run it for an hour or so.

======================================================
"Fill what's empty,
empty what's full,
and scratch where it itches."
the Duchess of Windsor,
when asked what is the secret of a long and happy life
======================================================

[David Roberts]

I'll do that and run it for an hour or so.

I let it rattle for 40 minutes. It is the best approach with Life. The redrawing is not significant.

Something must be.

Added: Actually, that does not follow. If all of our fingers are sore the thumb will not stand out. [David Roberts 2008 ]

[Gösta H. Lovgren-2]

Here's a 45 minute run for Life and it puts in perspective (I think) how good a feature Profile can be. In other words one could spend a great deal of time tweaking a procedure that, in the long(er) run has little effect on perfomance. In this example both Header functions can probably be worked on to good advantage. Not so much the other 30 or so procedures. Not to say any couldn't be more efficient, only that time would be better spent on the Header..'s.

Note also using your tip, Dave, I split Graphic Redraw & Clear statements into two functions for timing purposes. Clear takes next to no time.

I'll let it run overnight as well. (See if GetTickCount solves my midnight problem too.) and get a REALLy good test of everything.

Also it occurs to me writing this that I probably use Grahic redraw in several other places probably unnecessarily and should remove them given they use so much time. Or maybe call them via the function just to see how much they subtract (if anything). It's just so quick to add when coding I haven't paid much attention to it as a time user. Never really thought about it.

              Profile for C:\Only_My_Programs\Life\Life_Profile.txt
               Started 11-27-2008 at 19:23:01
              Finished 11-27-2008 at 20:08:03
              Ran for 0 Hours 45 Minutes 2 Seconds 
              (Note elapsed seconds may not agree exactly due to the different methods used
                to calculate each. Especially on shorter runs - say under 2 minutes)
...snip
*****************************************************************************************************
 *** Time Used ***                            Calls         Tot ms  ms/call    % of time
  1) Update_Gary ____________________________47,488______1,383,165_____29.1__41%
  2) Header_Set _____________________________47,489________619,823_____13.1__19%
  3) Header_Print ___________________________47,500________619,682_____13.0__19%
  4) Screen_Redraw __________________________47,488________607,302_____12.8__18%
...snip
 30) Screen_Clear ___________________________47,488______________0______0.0___0%
...snip

=============================================
"You can get more with a kind word and a gun
than you can with a kind word alone."
Al Capone (1899-1947)
=============================================

[David Roberts]

In this example both Header functions can probably be worked on to good advantage.

It has been mentioned that PBMain has an influence in excess of 99%.

Suppose it had an influence of 95% and another procedure had the balance of 5%. If we could get that other procedure to run at the speed of light then the application would either terminate 5% earlier or be 5% faster depending upon how we look at it. However, if the best we could do was to get the other procedure to run twice as fast then the application would only benefit by 2½%.

With an influence in excess of 99% we are wasting our time looking at anything other than PBMain.

Now, if a procedure is not giving up it secrets one course of action is to totally break it down into sections, not just one or two, in such a way that it has zero influence. With PB's Profile all we get is the total time spent by each procedure - we do not get who calls it, how many procedures calls it and what percentage time it takes of it's, perhaps various, parent(s). Egress gives us all of that.

Whilst deciding how to break PBMain up I spotted something.

Sleep 10.

10 milliseconds is a long time on my machine - it can crunch 300,000 RNDs in that time. So, without further ado I put that 'Sleep 10' into a function, FnSleep.

After a 12 minute run I got this:

Sorted influences (Omitting < 5%):
 
 FNSLEEP                      90.6%
 HEADER_PRINT                  8.3%

and PBMain was

PBMAIN 725469 0% Influence
 
  Background_Change              21028 x 0 = 0 [0%]
  Default_Settings               1 x 5437 = 5437 [.7%]
  FnSleep                        42057 x 15 = 657052 [90.6%]
  GRedraw                        42057 x 0 = 1624 [.2%]
  Gen_Total_Set                  42058 x 0 = 0 [0%]
  Get_Inkey                      42058 x 0 = 33 [0%]
  Header_Set                     3823 x 15 = 59949 [8.3%]
  Mouse_Click_Check              42058 x 0 = 0 [0%]
  Pixel_Color_Set                42058 x 0 = 0 [0%]
  Population_Unchanged           42058 x 0 = 0 [0%]
  Stasis_Check                   42058 x 0 = 0 [0%]
  Update_With_All_Pointers       42057 x 0 = 1295 [.2%]
  Var_Ptrs_Set                   1 x 0 = 0 [0%]
  Wrap_Horizontally              42057 x 0 = 32 [0%]

The total within [] adds to 100% - the code not put into procedures was, obviously, too small to have an impact and PBmain has effectively no influence. The GRedraw is the Graphic ReDraw/Clear combo.

Look at FnSleep!!!

PBMain, and thus Life, is sparked out most of the time.

We are told 15ms/call. I suppose the function overhead is starting to show at this level.

One way to get a procedure to run at the speed of light is to remove it, so FnSleep was relegated to Uncalled procedure status.

After a 13 minute run I got:

Sorted influences (Omitting < 5%):
 
 UPDATE_WITH_ALL_POINTERS     73.0%
 HEADER_PRINT                 12.3%
 GEN_TOTAL_SET                 6.3%
 WRAP_HORIZONTALLY             6.0%

PBMain's influence was 0.7%.

So, all the while that we have been profiling an application it's PBMain has been throttled back.

Is that 'Sleep 10' a left over from development or is there a reason for its being there now? There is no comment next to it.

It would seem to be a good idea to keep Sleep out of the picture when profiling and introduce it, or them, at running tests if they are needed for display reasons. It shouldn't matter if a profile run is jerky or whatever. I see that Sleep is used in other places as well.

If you comment then all out then there may be plenty of influences which would otherwise not show themselves and may be 'tweakable'.

I shall leave you to it, Gösta, I don't want to get into analysing the Life program.

[Michael Mattias]

We are told 15ms/call. I suppose the function overhead is starting to show at this level.

You don't mean 15 ms overhead for CALL {procedure} versus inline, do you?

I refuse to believe that. For one thing it must be processor-dependent since everything comes back to 'clocks' meaning there can be no 'time' standard for this, only a 'clocks' standard. And 15 ms is like, FOREVER in today's terms. I 'might' have believed 15 ms on my first personal computer but I'm guessing there aren't a lot of computers in service running at 4.77 Mhz (6 Mhz if you hit the orange button) any more.

Who is doing this telling?

[Gösta H. Lovgren-2]

It has been mentioned that PBMain has an influence in excess of 99%.

Suppose it had an influence of 95% and another procedure had the balance of 5%. If we could get that other procedure to run at the speed of light then the application would either terminate 5% earlier or be 5% faster depending upon how we look at it. However, if the best we could do was to get the other procedure to run twice as fast then the application would only benefit by 2½%.

With an influence in excess of 99% we are wasting our time looking at anything other than PBMain.

Now, if a procedure is not giving up it secrets one course of action is to totally break it down into sections, not just one or two, in such a way that it has zero influence. With PB's Profile all we get is the total time spent by each procedure - we do not get who calls it, how many procedures calls it and what percentage time it takes of it's, perhaps various, parent(s). Egress gives us all of that.
...

PBMain's influence was 0.7%.

So, all the while that we have been profiling an application it's PBMain has been throttled back.

I guess I'm just not getting what you mean by "influence".

And I don't understand the advantage of "Egress". It seems to me the same info is gotten out of Profile without the programmer overhead of adding "Egress(something)" to every procedure. (In Life's case, 60 or 70 times).

Is that 'Sleep 10' a left over from development or is there a reason for its being there now? There is no comment next to it.

It's not in the version of Life I'm currently using, which is certainly different from yours. I only load updates to the Forum when there are major changes.. In the meantime I'm constantly fiddling with it.

It would seem to be a good idea to keep Sleep out of the picture when profiling and introduce it, or them, at running tests if they are needed for display reasons. It shouldn't matter if a profile run is jerky or whatever. I see that Sleep is used in other places as well.

If you comment then all out then there may be plenty of influences which would otherwise not show themselves and may be 'tweakable'.

Again I'm not getting the concept of "influence". Are you using it to indicate a slice or % of time? As far as Sleep goes (for example), if the programmer see a high % of time taken by a particular procedure, surely he's going to take the Sleep factor into account.

I shall leave you to it, Gösta, I don't want to get into analysing the Life program.

No, of course not. It's just that Life is a good example to test the Profile concept on. By the way, just by Proceduring Graphic Redraw, the results show that really there isn't much to improve on as far as speed goes (NOte Header stuff in this run is only called about 1/4 as much, which really doesn't affect visual display much at all as it was called 10-50 times a second otherwise)

95% of the time is spent either updating (UpDate_Gary - which is about as fast is it can get) and redrawing (Graphic Redraw - a PB command the programmer cannot control and is probably already optimized to the nth)

              Profile for C:\Only_My_Programs\Life\Life_Profile.txt
               Started 11-27-2008 at 21:42:04
              Finished 11-28-2008 at 08:28:45
              Ran for 10 Hours 46 Minutes 41 Seconds 
              (Note elapsed seconds may not agree exactly due to the different methods used
                to calculate each. Especially on shorter runs - say under 2 minutes)
 
*****************************************************************************************************
*****************************************************************************************************
 *** Time Used ***                            Calls         Tot ms  ms/call    % of time
  1) Update_Gary ___________________________619,993_____27,184,106_____43.8__69%
  2) Screen_Redraw _________________________619,993______9,729,485_____15.7__25%
  3) Mat_Arrays ____________________________619,993________951,783______1.5___2%
  4) Header_Print ___________________________43,813________685,054_____15.6___2%
  5) Header_Set ____________________________206,665________684,976______3.3___2%

[Michael Mattias]

I changed my mind... I could believe 15 ms if either TRACE or PROFILE is enabled... those functions require extra overhead when a procedure is called, eg collecting statistics and/or writing to disk file.

ie, I think this means the rule of thumb has to be "Due to extra overhead, PROFILE and TRACE (others? CALLSTK? ) do not produce any useful information vis-a-vis the differences between executing code 'in-line' versus isolating code in separate procedures."


MCM