SPY Larry Masinter 17 October 1984 SPY is a tool to help you make programs run faster. It gives you a picture of where the program is spending its time. SPY has two parts: a 'sampler' which you run while running your program, which monitors what the program is doing, and a 'displayer' which displays the data gathered by the sampler. The 'sampler' periodically interrupts the running program to account the functions in the current call stack. This allows SPY to remember not only (proportionally) how long is spent in each individual function, but also how long each function seen on the call stack. The sampler data structures were designed to minimize interference with the normal running of the program -- there is little noticable performance degradation. Because SPY doesn't log every call and return, you can run it even over long computations, unlike DOSTATS. The 'displayer' uses the GRAPHER package to display the data gathered by the sampler. In the graph, the height of each node is adjusted to be proportional to the amount of time. Just as Masterscope and Browser give an interactive picture of the static structure of the program, SPY gives an interactive picture of the dynamic structure. The displayer is interactive as well as graphical. That is, you can look at the data in a variety of ways, since it seems there is no one picture that says it all. Since the displayer knows the whole call graph, it can show the entire tree structure (with separate calls to a function accounted separately) or merging separate calls to the same functions. Since the sampler records the entire calling stack when it samples, it can account for both individual and cumulative time. When the sampler runs, if a function is on the top of the stack, it adds to its individual total; if the function is on the stack at all, the sampler adds to the cumulative total. When there are several calls to the same function within the graph, the displayer can either 'merge' the nodes (show the total time for the function in one node) or not. If a node is merged, then one of the boxes in the graph will have all of the time for that function accounted to it, and the rest will be left as 'ghost' boxes. SPY has a variety of ways of controlling which nodes will be merged. How to Use SPY (SPY.BUTTON) [Function] This function puts up a little menu with the single button "SPY" on it. Pushing it once will turn on sampling (SPY.START). Pushing it again will turn off sampling (SPY.END) and display the results (SPY.TREE 10). This is the simplest way of spying on operations. Note that you can't turn off sampling if the mouse process is locked out. Alternatively, you can turn SPYing on and off by using the following functions: (SPY.START) [Function] Reinitializes the internal SPY data structures, and turns on sampling. (SPY.END) [Function] Turns off sampling, and cleans up the data structures. (WITH.SPY form) [Macro] Calls (SPY.START), evaluates form, calls (SPY.END), and then returns the value of form. For example, (WITH.SPY (LOAD 'FOO)) is basically (PROGN (SPY.START) (PROG1 (LOAD 'FOO) (SPY.END] To display the results, call the function SPY.TREE: (SPY.TREE threshold individualp mergetype depthlimit) [Function] SPY.TREE displays the results of the last 'spy' in a grapher window. There are a number of parameters that control the display, which you can either set when you call SPY.TREE, or set interactively with the menu. I normally just use (SPY.TREE) and use the menus. "threshold" is a number (defaults to 0), "individualp" is either NIL or T, "mergetype" is one of (NONE, ALL, DEFAULT), and "depthlimit" is a number (defaults to NIL = arbitrary depth; not completely debugged for other values.) You will get a prompt to lay down a window, and then a graph will appear in it, something like this: DDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD@DDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD@Ooq@O;vm@m[oWmXOiۻ@Oǫ?qreKo@wO@L@L@L@``L`!G8y`@L̐ Bn)BR`@B~(B` BW9(qLBV)(@B`@LĐBFD%)BR`@`GGD$y``L`@L`@L @L@@@L@L@L@L`@``L`@L`@ ` `L@`!I8y`@L@Ґ!JP)BR`x@J(Bg YI9(qxL YHP)(@Bg@L А JPD%)BR`x@`1D$y` `L@`@L`@``L `@L `@@ @L@L@L0@L@@ĀLc#D93c`=3`!g"@L̔FdmT%)J!)JR!@ĵF%}X%)B!)JP րG&UX9Cf9Kͪ*LĔF$W!IB!JJ ~*@LĔF$F2!)J!)JR F3@cFsF1!&3c`=)2L`Gd303L 3@L3@303L 3@L3@`!2L%.c<3@0Ґ!%JR)3L@ %CR!3@L `C83@Ȑ /’i !3А (Ri")3L`Ȳ.."c<3@L3@33L3@L3@33L3@L@3@@3 L @L@L@L@L@L@@L@@L @ L@L@ !qc0L` HHI#@L HHA#@ NH#A3 HHC!#L HHH!#@LpOq13@L@L@L@L@L@L@L@L@L@O@DDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD@DDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD@ In this display, 100% of the time was spent under the top 4 frames that a process normally has, T, \MAKE.PROCESS0, ERRORSET, \EVALFORM. (SPY should probably eliminate those from the display, but it doesn't right now.). That time was then divided up among 4 processes: \TIMER.PROCESS, \MOUSE.PROCESS, \BACKGROUND.PROCESS, \TEDIT2. The numbers to the left of the label are the percentages. The height of the box is proportinal to the percentage, (except that it is always made big enough to hold the label.) The width isn't significant -- it is just wide enough to hold the name of the function. If you left button any node, the window title will change to show the function name, and the individual and cumulative percentages; the first number individual total and the second is the cumulative. If you middle button the node, you will get a menu, with two items: SubTree Create another spy window which includes data only from this node and its descendents. Lets suppose that I was only interested in the actions that I had invoked via the mouse: I can middle-button \MOUSE.PROCESS and select the SubTree option. I then get a picture like this: """""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""" / / oq;pǏ;vm۷ooo_w/m[n۹oϟ /WmXu[۾woo iۻ[۷ooo_wǫ?qreKo/ ```ipԥ"@@k"@,@"@,i"@wwwwwww`i0"@f>8,`,`` ,@,,,?*UUUT?UUUUj0` *UUUT,0` UUUUj,0`@(00`P 00a(,0$c<03\dAI.CbP ,Hܥ(R)04RAJPBd(XR!00ҔAJBhP h874 ҕAYICp(,H( !02$ ҕAYHPiBhP ,H(")04$җJPDiBd(0"c<07:\b1D.{bP 00a(,00`P ,00`@(0` P 0`(,0`P ,?(?P (,P ,@( P (,P ,(P (,UUUUUUUUUUTUUUUUU@P ,* (@UUUUUUUUUUTUUUUUU@P * (,P@P ,(( (QgIg0d1@Q&}ޗ*@ JPH( H%*H*R%),R JHX% Y@RV%) ,@ YIaN+h% h%)R@ YHP>HH% I@RR%) *@ JP"H( H%)H*R%),Qw1a"O0gȱ@Qޑ ,(( (P@P (( (,UUUUUUUUUUTUUUUUU@P ,* (UUUUUUUUUUTUUUUUU@P * (,P ,(P (,P ,(P (,P ,(P (,P ,(P (,P ,(P (,P ,(P (,P ,(P UUUUUUUUT,*,UUUUUUUUT*,/"""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""" """""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""" Which shows that 80% of the total time under \MOUSE.PROCESS was spent inside the function IQUOTIENT. (Whew, something going on wrong there... why isn't it getting the microcoded version of divide?). One thing to watch out for: when you switch between Individual and Cumulative modes, the "threshold" stays the same. (Sometimes the threshold for Individual needs to be higher; otherwise, functions will tend to disappear in the Individual tree.) Also, switching to Individual also changes to "MergeAll", while switching to "Cumulative" changes you to "MergeDefault". (SPY.LEGEND) [function] If you forget what all of the different shadings and borders mean, this function brings up a window which shows what they mean. Internal controls: SPY.FREQUENCY [variable] How many times per second to sample? Initially set to 10. (Maximum 60). SPY.NOMERGEFNS [variable] Functions on this list won't get merged under MergeDefault. Includes (ERRORSET \EVAL EVALFORM APPLY EVAL). You may need to add more. SPY.TREE [variable] This variable (same name as the function) is used to hold the data from the last sampling. You can save it away and restore it using UGLYVARS. SPY.BORDERS [variable] Used to control the border display on a tree. This is a list of (nodetype description borderwidth texture interiortexture) (SPY.LEGEND) [function] Brings up a window which shows the interpretation of SPY.BORDERS. SPY.FRAGMENTS [variable] If NIL, SPY will not include 'ghost' boxes. Initially T. SPY.SHOWCOUNTS [variable] If NIL, SPY will not display the percentage in the node-box unless the node-box has been made higher to accomodate the text in the node. Initially T. SPY.FONT [variable] Font used to display node labels. Initially (GACHA 10). SPY.MAXLINES [variable] Maximum height of a node in the graph, measured in multiples of the font height of SPY.FONT. KNOWN PROBLEMS WITH THIS VERSION OF SPY The Dolphin and Dorado have a bug which will cause incorrectly large amounts of time to be accumulated to the routines which get and send packets to the 3MB Ethernet. It will show up as samples under \3MBGETPACKET (or whatever). The rest of the data in the SPY display is relatively accurate, and you may need to 'delete' that node. SPY doesn't know anything about the interpreter or the internal workings of Interlisp-D. Internal functions which are not "realframep" and don't normally show up on BT backtraces (but do on BT!) will be shown in spy. This includes things like \INTERPRETER1 which will appear underneath any interpreted function call. Finally, a number of enhancements and extentions are planned; suggestions and requests are welcome. NILNILMODERN!MODERN NILNIL,MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL>MODERN MODERN MODERN MODERN MODERN MODERN HMODERN MODERN MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL!MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL MODERN NILNILGMODERN NILNILMODERN NILNILMODERN NILNIL7MODERN NILNILMODERN NILNIL!MODERN NILNILMODERN NILNILMODERN NILNIL4MODERN NILNILMODERN NILNILEMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILeMODERN NILNILMODERN NILNILMODERN (B BMOBJ.GETFN2MODERN NILNILMODERN NILNILSMODERN NILNILMODERN NILNIL MODERN NILNILMODERN HNILNILMODERN NILNILMODERN NILNIL MODERN " BMOBJ.GETFN2MODERN NILNILMODERN HNILNILMODERN NILNILMODERN NILNILMODERN # BMOBJ.GETFN2MODERN NILNILMODERN NILNILMODERN NILNILMODERN HNILNILMODERN NILNILMODERN HNILNILMODERN HNILNILMODERN HNILNILVMODERN HNILNILMODERN HNILNILMODERN HNILNILMODERN MODERN HNILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN J BMOBJ.GETFN2MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN  BMOBJ.GETFN2MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN J BMOBJ.GETFN2MODERN NILNIL*MODERN NILNILMODERN NILNILMODERN : BMOBJ.GETFN2MODERN NILNILMODERN NILNILCMODERN NILNILMODERN NILNILMODERN T BMOBJ.GETFN2MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL$MODERN NILNIL=MODERN NILNILMODERN NILNIL^MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL&  BMOBJ.GETFN2MODERN MODERN NILNILMODERN NILNIL7MODERN NILNILMODERN NILNILMODERN NILNIL"MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL#MODERN NILNILIMODERN NILNILMODERN NILNIL#MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL!MODERN NILNIL{MODERN NILNILMODERN NILNIL"MODERN NILNILBMODERN NILNILMODERN NILNIL"MODERN NILNIL9MODERN NILNILMODERN NILNIL#MODERN NILNILMODERN NILNILMODERN NILNILMODERN NILNIL8MODERN NILNILMODERN NILNIL!MODERN NILNIL]MODERN NILNILMODERN NILNIL*MODERN NILNILMODERN NILNILMMODERN NILNILMODERN NILNIL=MODERN NILNILMODERN NILNILdMODERN Ɖ)z