Enter/Exit function/procedure message

[440bx]

Hello,

For debugging and analysis purposes of a program, I'd like to have a message such as "entering <function/procedure name>" and "exiting <function/procedure name>" whenever a function/procedure is entered and exited.

The first question is: is there a way to tell the compiler to automatically generate code that does that ? (IOW, instrument the code.)

if the answer to the above question is "no" (which I believe is quite likely) then, suggestions as to how to accomplish this manually will be appreciated.   The "entering <function/procedure name>" is easy.  The "exiting <function/procedure name>" is more difficult/cumbersome because it has to account for every instance of an "exit" statement in the code.  Is there any way to have the "exiting" message without risking not having it due to missing an "exit" statement ?

Thank you for your help.

[dsiders]

Hello,

For debugging and analysis purposes of a program, I'd like to have a message such as "entering <function/procedure name>" and "exiting <function/procedure name>" whenever a function/procedure is entered and exited.

The first question is: is there a way to tell the compiler to automatically generate code that does that ? (IOW, instrument the code.)

if the answer to the above question is "no" (which I believe is quite likely) then, suggestions as to how to accomplish this manually will be appreciated.   The "entering <function/procedure name>" is easy.  The "exiting <function/procedure name>" is more difficult/cumbersome because it has to account for every instance of an "exit" statement in the code.  Is there any way to have the "exiting" message without risking not having it due to missing an "exit" statement ?

Thank you for your help.

This popped up on the radar  a while back: https://wiki.freepascal.org/FPProfiler... even if you're not interested in the timing aspects. I don't know much about it other than it exists.

[440bx]

This popped up on the radar  a while back: https://wiki.freepascal.org/FPProfiler... even if you're not interested in the timing aspects. I don't know much about it other than it exists.

Thank you!  This looks promising.  I'll definitely have a close look at it as it might be (or have) what I'm looking for.

[Martin_fr]

I use to "Code Templates" for that.

The first (that I insert on top of each method is

Code: Pascal  [Select][+][-]

1. debuglnEnter(['> $ProcedureName() ',dbgsName(Self),dbgs(self),' '| ]); try

And at the bottom

Code: Pascal  [Select][+][-]

1. finally debuglnExit(['< $ProcedureName() '| ]); end;

Of course the could also be ifdefed, if you prefer that.

And while I haven't done myself, it should be possible to record a macro.
Something like ("det" and "fdx" are the names of my templates)

Code: Pascal  [Select][+][-]

1. begin
2. ecChar('d');
3. ecChar('e');
4. ecChar('t');
5. ecAutoCompletion;
6. ecFindBlockStart;
7. ecFindBlockStart;
8. ecFindBlockOtherEnd;
9. ecLineBreak;
10. ecUp;
11. ecChar('f');
12. ecChar('d');
13. ecChar('x');
14. ecAutoCompletion;
15. ecDown;
16. ecLineStart;
17. ecFindBlockOtherEnd;
18. end.

Inserts code at both ends, if started at an empty line below the initial "begin".

[440bx]

@Martin,

That looks like a really good solution.  I hadn't thought about using a "finally" to ensure the output of the "exiting" message.

I haven't played with templates but, it looks simple enough.  I'll definitely give your suggestion a try.

Thank you, that looks like it might be the simplest way to go.

[440bx]

I figured I'd share my solution to outputting function/procedure enter/exit messages.

First, an example of how the solution is used:

Code: Pascal  [Select][+][-]

1. {$APPTYPE CONSOLE}
2.  
3. {$MODESWITCH ADVANCEDRECORDS}
4.  
5.  
6. program _EnterExitNames;
7.  
8. uses
9.   CallTracing
10.   ;
11.  
12.  
13. {$include CallTracing.macros.inc}
14.  
15.  
16. procedure A();
17. begin
18.   _ENTER;
19.  
20.  
21.  
22.   writeln(_INDENT, 'this message should appear indented (if tracing is active)');
23.  
24.  
25.   exit;
26.   writeln('this should NOT be written');
27.  
28.  
29.   _EXIT;
30. end;
31.  
32. procedure B();
33. begin
34.   _ENTER;
35.  
36.   exit;
37.   writeln('this should NOT be written');
38.  
39.   _EXIT;
40. end;
41.  
42. procedure C();
43. begin
44.   _ENTER;
45.  
46.   exit;
47.   writeln('this should NOT be written');
48.  
49.   _EXIT;
50. end;
51.  
52. procedure D();
53. begin
54.   _ENTER;
55.  
56.   exit;
57.   writeln('this should NOT be written');
58.  
59.   _EXIT;
60. end;
61.  
62.  
63. procedure F();
64.   { example procedure with call level indented writeln output                 }
65. begin
66.   _ENTER;
67.  
68.   writeln(_INDENT, 'this message should appear indented (if tracing is active)');
69.  
70.   exit;
71.   writeln('this should NOT be written');
72.  
73.  
74.   _EXIT;
75. end;
76.  
77. procedure G();
78. begin
79.   _ENTER;
80.  
81.   F();
82.  
83.   exit;
84.   writeln('this should NOT be written');
85.  
86.   _EXIT;
87. end;
88.  
89. procedure H();
90. begin
91.   _ENTER;
92.  
93.   G();
94.  
95.   exit;
96.   writeln('this should NOT be written');
97.  
98.   _EXIT;
99. end;
100.  
101.  
102. procedure I();
103. begin
104.   _ENTER;
105.  
106.  
107.   writeln(_INDENT, 'this message should appear indented (if tracing is active)');
108.  
109.   H();
110.  
111.   _EXIT;
112. end;
113.  
114. procedure J();
115. begin
116.   _ENTER;
117.  
118.   I();
119.  
120.   exit;
121.   writeln('this should NOT be written');
122.  
123.   _EXIT;
124. end;
125.  
126. procedure K();
127. begin
128.   _ENTER;
129.  
130.   J();
131.  
132.   exit;
133.   writeln('this should NOT be written');
134.  
135.   _EXIT;
136. end;
137.  
138. procedure L();
139. begin
140.   _ENTER;
141.  
142.   K();
143.  
144.   exit;
145.   writeln('this should NOT be written');
146.  
147.   _EXIT;
148. end;
149.  
150. procedure E();
151. begin
152.   _ENTER;
153.  
154.   A();
155.   B();
156.   C();
157.   D();
158.  
159.   L();
160.  
161.   exit;
162.   writeln('this should NOT be written');
163.  
164.   _EXIT;
165. end;
166.  
167.  
168. begin
169.   { "main" program                                                            }
170.  
171.   _ENTER;
172.  
173.      A();
174.      B();
175.      C();
176.      D();
177.      E();  { calls functions that in turn call other functions                }
178.  
179.      readln;
180.  
181.      exit;
182.      writeln('this should NOT be written');
183.  
184.   _EXIT;
185. end.
186.  
187.  
188. //
189. //  end of file
190. // ----------------------------------------------------------------------------

The first requirement is to use the unit "CallTracing" which provides the tracing functions.  The second requirement is to include the file "CallTracing.macros.inc" which, as its name implies, provides macros to use the tracing functions in CallTracing.

All that's needed to trace the entry and exit of a function is to put the "_ENTER" macro at the beginning and the "_EXIT" macro at the end.

The call tracing unit is very simple:

Code: Pascal  [Select][+][-]

1. {$MODESWITCH ADVANCEDRECORDS}
2.  
3.  
4. unit CallTracing;
5.  
6. { --------------------------------------------------------------------------- }
7. INTERFACE
8. { --------------------------------------------------------------------------- }
9.  
10.  
11. type
12.   TROUTINE_LEVEL_RANGE = 0..511;                   { max call nesting         }
13.  
14.   TROUTINE_NAMES = record                          { prefix rn_               }
15.     strict private
16.       rn_index       : int32;                      { also indent level        }
17.       rn_name        : array[TROUTINE_LEVEL_RANGE] of pchar;
18.  
19.     public
20.       procedure rn_push(InProcName : pchar);
21.       procedure rn_pop();
22.       function  rn_indent() : pchar;
23.   end;
24.  
25. { --------------------------------------------------------------------------- }
26.  
27. var
28.   { the variable name must be named CallStack because of the macros.  it is   }
29.   { possible to hide that fact by creating a macro to declare the variable    }
30.  
31.   CallStack : TROUTINE_NAMES;  { !! global variable                           }
32.  
33.  
34.  
35. { --------------------------------------------------------------------------- }
36. IMPLEMENTATION
37. { --------------------------------------------------------------------------- }
38.  
39.  
40. const
41.   CALL_LEVEL_INDENT   = 3;
42.  
43. type
44.   TSPACES_RANGE       = low(TROUTINE_LEVEL_RANGE)..
45.                         CALL_LEVEL_INDENT * high(TROUTINE_LEVEL_RANGE);
46.  
47.  
48. {$WRITEABLECONST ON}
49. const
50.   { NOTE: the NULL field is to guarantee the array of spaces is always null   }
51.   {       terminated                                                          }
52.  
53.   NTSPACES : record
54.     SPACES     : array[TSPACES_RANGE] of char;
55.     NULL       : DWORD;
56.   end = (SPACES:' '; NULL:0);
57. {$WRITEABLECONST OFF}
58.  
59.  
60. { --------------------------------------------------------------------------- }
61.  
62. procedure IndentLevel(InLevel : int32);
63. begin
64.   { use the array of spaces to output the indent                              }
65.  
66.   if InLevel * CALL_LEVEL_INDENT < high(NTSPACES.SPACES) then
67.   begin
68.     NTSPACES.SPACES[InLevel * CALL_LEVEL_INDENT] := #0;
69.     write(NTSPACES.SPACES);
70.     NTSPACES.SPACES[InLevel * CALL_LEVEL_INDENT] := ' ';
71.  
72.     exit;
73.   end;
74.  
75.   { the indent level exceeds the maximum the code can handle, output tha      }
76.   { maximum number of spaces (which is the most we can do)                    }
77.  
78.   write(NTSPACES.SPACES);
79. end;
80.  
81. { --------------------------------------------------------------------------- }
82.  
83. procedure TROUTINE_NAMES.rn_push(InProcName : pchar);
84. begin
85.   rn_name[rn_index] := InProcName;
86.  
87.   writeln;
88.   IndentLevel(rn_index);
89.   writeln(rn_index:1, '  >> ', InProcName);
90.  
91.   inc(rn_index);                            { index of next available entry   }
92. end;
93.  
94. { --------------------------------------------------------------------------- }
95.  
96. function TROUTINE_NAMES.rn_indent() : pchar;
97. begin
98.   IndentLevel(rn_index - 1);
99.  
100.   result := pchar(@NTSPACES.NULL);
101. end;
102.  
103. { --------------------------------------------------------------------------- }
104.  
105. procedure TROUTINE_NAMES.rn_pop();
106. begin
107.   dec(rn_index);
108.  
109.   if rn_index < low(TROUTINE_LEVEL_RANGE) then exit;
110.  
111.   IndentLevel(rn_index);
112.   writeln(rn_index:1, '  << ', rn_name[rn_index]);
113.   writeln;
114. end;
115.  
116. { --------------------------------------------------------------------------- }
117.  
118. procedure Init();
119. var
120.   i       : int32;
121. begin
122.   { one time initialization                                                   }
123.  
124.   if NTSPACES.SPACES[high(NTSPACES.SPACES)] <> ' ' then
125.   begin
126.     for i := low(NTSPACES.SPACES) to high(NTSPACES.SPACES) do
127.     begin
128.       NTSPACES.SPACES[i] := ' ';
129.     end;
130.   end;
131. end;
132.  
133. { --------------------------------------------------------------------------- }
134.  
135. initialization
136.  
137.   Init();
138. end.
139.  
140. //
141. // end of file
142. // ----------------------------------------------------------------------------

Code that uses the unit does NOT need to be aware of any of the functions provided by the unit because those are hidden by the macros.

The macros file is as follows:

Code: Pascal  [Select][+][-]

1.  
2. { the following macro definitions are convenient to have in units where       }
3. { tracing is desired                                                          }
4.  
5.  
6. {$MACRO ON}
7.  
8. {$define CALLTRACING}
9.  
10. {$if defined(CALLTRACING)}
11.   {$define _ENTER:=Try CallStack.rn_push({$I %CURRENTROUTINE})}
12.   {$define _EXIT:=Finally CallStack.rn_pop(); end}
13.   {$define _INDENT:=CallStack.rn_indent()}
14. {$else}
15.   {$define _ENTER:=}
16.   {$define _EXIT:=}
17.   {$define _INDENT:=''}
18. {$endif}
19.  
20.  
21. //
22. // end of file
23. // ----------------------------------------------------------------------------
24.  
25.  
26.  

defining/undefining "CallTracing" controls outputting trace messages without having to make changes in the code that uses the tracing facility.

One potentially very important limitation to be aware of is that the tracing mechanism is inherently single threaded since it relies on a global variable.   A possible enhancement would be to have that variable be a thread variable (left as an exercise for those who need that improvement.)

Attached is a screenshot of the example's output.

ETA:

added the 7zip file attachment that has all the code (Jeez... I'm really getting old !!)

[440bx]

I forgot to mention a couple of things about the code that are important.

the output width of rn_index is currently one (1) (see the writeln statements in the CallTracing unit where rn_index is used), that's the value I was using for testing.  It should probably be set to somewhere around 4 to ensure the level number stays aligned when the call depth exceeds 9.

the number of elements in the names stack is currently set to 512 (see the range 0..511) and the code does _not_ check for not overflowing the stack (this is on purpose.)  For some unusually complex programs, it might be necessary to change the range to end in a larger value (for most programs 511 should be enough - a call nesting depth of 511 is fortunately quite rare - usually caused by recursive calls.)

HTH.