(* * LANGUAGE : ANS Forth * PROJECT : Forth Environments * DESCRIPTION : Inspired by Jon Bentley's ``More Programming Pearls'' * CATEGORY : Tools * AUTHOR : Marcel Hendrix * LAST CHANGE : May 26, 1997, Marcel Hendrix general butchering for publication * LAST CHANGE : September 8, 1995, Marcel Hendrix removed ARRAY * LAST CHANGE : September 8, 1993, Marcel Hendrix redefined : * LAST CHANGE : March 8, 1993, Marcel Hendrix *) NEEDS -miscutil REVISION -lprofile "ÄÄÄ Forth Line Profiler Version 1.14 ÄÄÄ" PRIVATES DOC Line Profiler (* Profiling? ---------- Sometimes it is useful to know where a program is spending its runtime. Although schemes exist where : and ; get redefined to compile counters, there is no direct link to the source code with this solution. Editing in a special word in the source is very flexible -- it limits output to just the words and constructs you're interested in. However, sometimes the exact troublespot is unknown. Furthermore, some programmers hate it to have to modify the source code by hand after it is finished and debugged. The solution presented here is to have the profiler read in the source and write a modified version of it to a temporary file. The latter is then included. The modifications made allow one to list the original source with an execution count in the left margin. Regrettably the idea will not work on all ANS Forth systems. The main stumbling block will be the availability of the variable #LINES , counting the lines compiled. There could be problems with the use of TAB's and the IBM-PC character set but they should be easy to solve. Implementation -------------- The source file is read in line by line. Each line is prepended by the string "^ " (The caret character plus a TAB). The word '^' is immediate and does nothing in execute mode. However, when compiling it compiles code to increment a counter in the array PROBES , at the position corresponding to the line where it executes (is: compiles). The modified lines are copied to the file !!!!!!!!.$$$ , which is subsequently included (in that way executing / compiling ^ for every line). With .PROFILE the file !!!!!!!!.$$$ is read in and displayed without the prepended "^ " string. Instead of this string the contents of the corresponding counter in PROBES are displayed. This is of course only meaningful when the words in this file have been executed at least once. The counters can be reset with the word PROINIT (not automatic!). *) ENDDOC DOC Timing (* Timing individual words ----------------------- Apart from its execution frequency, the speed of execution of a word is important. The words TIMER-RESET and .ELAPSED are almost always sufficient for this task, however some (kernel) words are so fast that you will appreciate the word .TIME" string " which times with microsecond resolution. It does this by placing string in a loop and executing the result a sufficient number of times (sufficient for the wanted resolution). The words to be tested may not change any stack. This means words must be added to string to assure this. Likewise, loop overhead is not automatically subtracted out as the optimizer makes this overhead difficult to predict. You can do this yourself easily. Let's see how you would test DUP : .TIME" 4 DUP 2DROP" xxx microseconds / iteration .TIME" 4 4 2DROP" yyy microseconds / iteration Subtracting xxx and yyy gives a reasonable approximation to the DUP speed. CAREFUL! """""""" Do not time words from a file that is being profiled. Nothing will break, but the words are MUCH slower than without the profiler code, so completely wrong conclusions could be drawn. *) ENDDOC ( The profiler tool ) #1000 =: /maxwords PRIVATE \ maximum number of colon definitions in source file #2000 =: /maxlines PRIVATE \ maximum number of lines in source file /maxwords 6 * CELLS ALLOCATE ?ALLOCATE =: 'timers /maxlines CELLS ALLOCATE ?ALLOCATE =: 'probes \ [d1][d2][nfa][rsvd] d1 is accumulator, d2 is set to the current ticks value at definition start. : tick-on ( ix -- ) 3 * 1+ 'timers []DOUBLE TICKS-GET ROT 2! ;P \ update d1 unless d2 is 0, then set d2 to 0. The idea is that d1 d2 should be paired. : tick-off ( ix -- ) 3 * 'timers []DOUBLE >S TICKS-GET S 1 DOUBLE[] 2@ 2DUP D0<> IF D- S 2+! ELSE 4DROP ENDIF 0. S> 1 DOUBLE[] 2! ;P 0 VALUE t-flag? PRIVATE 0 VALUE #words PRIVATE : TIMEINIT ( -- ) 'timers /maxwords 4 * CELLS ERASE TRUE TO t-flag? ; : probes@ ( ix -- n ) CELLS 'probes + @ ;P : probes+! ( n ix -- ) CELLS 'probes + +! ;P : PROINIT ( -- ) 'probes /maxlines CELLS ERASE TIMEINIT CLEAR #words ; PROINIT : PROEXIT ( -- ) CLEAR t-flag? ; PROEXIT :NONAME ( pfa -- ) DROP 'probes FREE DROP 'timers FREE DROP ; IS-FORGET PROINIT 0 VALUE thisword PRIVATE : ton, t-flag? 0= ?EXIT STATE @ 0= ?EXIT #words /maxwords U> ABORT" ton, :: array bounds exceeded" #words POSTPONE LITERAL POSTPONE tick-on S TO thisword ; IMMEDIATE : toff, t-flag? 0= ?EXIT thisword 0= ?EXIT STATE @ 0= ?EXIT #words /maxwords U> ABORT" ton, :: array bounds exceeded" #words POSTPONE LITERAL POSTPONE tick-off thisword #words 3 * 2+ 'timers []DOUBLE ! 1 +TO #words CLEAR thisword ; IMMEDIATE : (.USED) ( minimum scale -- maximum ) 0 LOCALS| maximum scale minimum | #words 0 ?DO I 3 * 'timers []DOUBLE 2@ TICKS>US #1000 UM/MOD NIP DUP maximum UMAX TO maximum DUP minimum U> IF I 3 * 2+ 'timers []DOUBLE @ ID$ CR TYPE DROP #32 HTAB scale IF #100 scale */ 9 .R ." %" ELSE 9 .R ." ms" ENDIF ELSE DROP ENDIF LOOP maximum ;P : .USED 0 0 (.USED) DROP ; ( -- ) : .MAXIMUM -1 0 (.USED) DEC. ; ( -- ) : .MINIMUM 0 (.USED) DROP ; ( minimum -- ) : .SCALED -1 0 (.USED) DUP #100 / SWAP (.USED) DROP ; ( -- ) \ User marker: probe this line if compiling, else do nothing. \ Note that ':' must be redefined too, but let's delay that ... : ^ STATE @ 0= ?EXIT 1 POSTPONE LITERAL SOURCELINE# 1- DUP /maxlines U> ABORT" ^ :: array bounds exceeded" POSTPONE LITERAL POSTPONE probes+! ; IMMEDIATE -- The strings to type start with "^ ", which we'll throw away. : TTYPE 2 /STRING 0 LOCAL pos \ --- <> 0 ?DO C@+ DUP ^I = IF DROP 8 pos 8 MOD - DUP SPACES ELSE EMIT 1 ENDIF +TO pos pos C/L #13 - U> ?LEAVE LOOP DROP ;P CREATE "^"buf PRIVATE BL C, '^' C, ^I C, #256 ALLOT : EDIT-FILE LOCALS| hof hif | \ --- <> BEGIN "^"buf 3 + #256 hif READ-LINE ?FILE WHILE "^"buf SWAP 3 + hof WRITE-LINE ?FILE REPEAT DROP ;P \ Instead of INCLUDE name , IN name , S" name" INCLUDED etcetera : PROFILE /PARSE R/O OPEN-FILE \ ## --- <> ?FILE LOCAL handle-if S" !!!!!!!!.$$$" W/O CREATE-FILE ?FILE LOCAL handle-of handle-if handle-of ['] EDIT-FILE CATCH IF 2DROP ." oeps!" ENDIF handle-of CLOSE-FILE ?FILE handle-if CLOSE-FILE ?FILE S" !!!!!!!!.$$$" INCLUDED ; : (.PROFILE) 0 LOCALS| line# handle | \ --- <> BEGIN PAD #256 handle READ-LINE ?FILE WAIT? 0= AND WHILE CR line# probes@ DUP 0> IF 8 .R ." * " ELSE 8 SPACES ." | " DROP ENDIF PAD SWAP TTYPE 1 +TO line# REPEAT DROP ;P : .PROFILE S" !!!!!!!!.$$$" R/O \ ## --- <> OPEN-FILE ?FILE DUP LOCAL handle ['] (.PROFILE) CATCH IF DROP ." oeps!" ENDIF handle CLOSE-FILE ?FILE ; \ Doesn't yet work right? \ : EXIT #words >S POSTPONE toff, S> TO #words POSTPONE EXIT ; IMMEDIATE : ; POSTPONE toff, POSTPONE ; ; IMMEDIATE ( note t-flag? OFF ) : : : POSTPONE ^ POSTPONE ton, ; IMMEDIATE :ABOUT CR ." A file to be profiled must be loaded with PROFILE name" CR ." Execute PROINIT and the main word, then type .PROFILE for a listing." CR CR ." Instead of .PROFILE, try .USED | .MAXIMUM | .MINIMUM | .SCALED" CR ." To use only the timers do PROINIT, load the file, execute the main word." CR ." (Using PROINIT after loading erases the monitored words list)." CR CR .~ Also try: `` .TICKS" string " '' to time ~ CR CR ." Note that may NOT have any lasting stack effects!" CR .~ Example: .TICKS" 9e FSQRT fdrop "~ CR .~ .TICKS" 9 SQRT drop "~ ; .ABOUT -lprofile CR DEPRIVE (* End of Source *)