5.3.2 The backtrace logging facility

- 1. As with any of the performance monitoring tools, before using the Backtrace Logging Facility, you should compile the file of interest in the production mode of the Compiler. You can invoke the production mode of the Compiler with the following form:

(proclaim '(optimize (speed 3) (safety 1)(compilation-speed 0)))

- If your file contains code that uses tail calls, you should disable tail merging by using a
*speed*setting of 2 or lower. When tail merging is on, the caller of the tail-called function might not appear on the stack; thus, information that is important to the trace can be lost. Disabling tail calls makes the results of the Backtrace Logging Facility easier to understand. - 2. Invoke the function
*start-backtrace-logging*to enable the facility and then run a test of the code. - 3. When the test is complete, invoke the function
*stop-backtrace-logging*. - 4. Finally, invoke the function
*summarize-backtrace-logging*to see the results of the test.

The file`binomial.lisp`

contains a program for computing the list of coefficients that are obtained when the expression`(x + 1)n`

is expanded. The program consists of the following function definitions:

(in-package "USER") ;;; FACT is the factorial function n!. (defun fact (n) (if (< n 2) 1 (* n (fact (1- n))))) ;;; PERM is the permutation function P(n,k) = n!/(n-k)!. (defun perm (n k) (/ (fact n) (fact (- n k)))) ;;; CHOOSE returns the binomial coefficient C(n,k) = P(n,k)/k!. ;;; This is the coefficient of x^k in the expansion of (x+1)^n. (defun choose (n k) (/ (perm n k) (fact k))) ;;; BINOMIAL-COEFFICIENTS returns a list of the binomial ;;; coefficients for the nth order equation. (defun binomial-coefficients (n) (let ((result nil)) (dotimes (k (1+ n) result) (push (choose n k) result))))To see how efficiently this program executes, you can examine it with the Backtrace Logging Facility. In this example, the test is run inside a call to the Common Lisp function

`binomial.log`

.;; Invoke the production mode of the Compiler and disable tail ;; merging. > (proclaim '(optimize (speed 2) (safety 1) (compilation-speed 0))) T > (load (compile-file "binomial")) ;;; You are using the compiler in PRODUCTION mode (compilation-speed = 0) ;;; If you want shorter compile time at the expense of reduced optimization, ;;; you should use the development mode of the compiler, which can be obtained ;;; by evaluating (proclaim '(optimize (compilation-speed 3))) ;;; Generation of argument count checking code is enabled (safety = 1) ;;; Optimization of tail calls is disabled (speed = 2) ;;; Reading source file "binomial.lisp" ;;; Writing binary file "binomial.sbin" ;;; Loading binary file "binomial.sbin" #P"/monitor/binomial.sbin" ;; This setting is for convenience only. > (setq *print-length* 8) 8 ;; Enable the Backtrace Logging Facility and run the test. > (start-backtrace-logging "binomial.log") NIL > (time (binomial-coefficients 200)) Elapsed Real Time = 7.32 seconds Total Run Time = 6.48 seconds User Run Time = 6.44 seconds System Run Time = 0.04 seconds Process Page Faults = 25 Dynamic Bytes Consed = 0 Ephemeral Bytes Consed = 5,279,408 There were 10 ephemeral GCs (1 200 19900 1313400 64684950 2535650040 82408626300 2283896214600 ...) ;; Disable the Backtrace Logging Facility. > (stop-backtrace-logging) NILWith this information, you can generate a summary. In this example, the root of the summary is the function binomial-coefficients, and the summary extends to a maximum depth of six function calls:

> (summarize-backtrace-logging "binomial.log" :root 'binomial-coefficients :max-backtrace-depth 6)Call-tree information obtained from a backtrace log. The numbers at each node represent the % of backtraces that include this node. There are 647 backtraces total.

1: BINOMIAL-COEFFICIENTS 100.000 2: CHOOSE 99.845 3: FACT 12.828 4: FACT 12.674 5: FACT 12.674 6: FACT 12.365 3: LIQUID-RUNTIME-SUPPORT:GENERIC-INTEGER-CONVERSION 5.255 4: (:INTERNAL LIQUID-RUNTIME-SUPPORT:GENERIC-INTEGER-CONVERSION LIQUID::PUNT) 5.100 5: LIQUID::BIGNUM-BIGNUM-DIVIDE 5.100 3: / 7.110 4: GCD 6.955 5: LIQUID::INTEGER-BINARY-GCD 6.955 6: LIQUID::IBG-BIG-BIG-REDUCTION 4.482 3: PERM 74.652 4: LIQUID-RUNTIME-SUPPORT:GENERIC-INTEGER-CONVERSION 11.128 5: (:INTERNAL LIQUID-RUNTIME-SUPPORT:GENERIC-INTEGER-CONVERSION LIQUID::PUNT) 11.128 6: LIQUID::BIGNUM-BIGNUM-DIVIDE 11.128 4: / 10.355 5: GCD 10.046 6: LIQUID::INTEGER-BINARY-GCD 10.046 4: FACT 53.168 5: FACT 52.396 6: FACT 51.932 Procedures by % exclusive time -- 647 samples taken 1 - LIQUID::FIXNUM-BIGNUM-*-OPEN 38.640 2 - LIQUID::BIGNUM-BIGNUM-DIVIDE 23.184 3 - FACT 16.692 4 - LIQUID::BIGNUM-REPLACE 7.728 5 - LIQUID:%ZERO-REGION 4.637 6 - * 2.473 NILThese results show that the function perm runs about 70% of the time at level 3; thus, by optimizing the function perm, the overall program performance could be improved. The following revision of perm computes (n - k + 1)* (n - k + 2)*...*n instead of the equivalent n!/(n - k)!, which reduces the overall number of computations:

(defun perm (n k) (if (<= 0 k n) (do* ((i (- n k) (1+ i)) (x 1 (* x i))) ((>= i n) x)) 0))Replacing this new definition in the file "binomial2.lisp" dramatically improves the run-time performance of the program, as the results of the call to time show:

> (load (compile-file "binomial2"))

;;; Reading source file "binomial2.lisp" ;;; Writing binary file "binomial2.sbin" ;;; Loading binary file "binomial2.sbin" > (start-backtrace-logging "binomial2.log") NIL > (time (binomial-coefficients 200)) Elapsed Real Time = 2.41 seconds Total Run Time = 2.41 seconds User Run Time = 2.40 seconds System Run Time = 0.01 seconds Process Page Faults = 0 Dynamic Bytes Consed = 0 Ephemeral Bytes Consed = 2,313,848 There were 5 ephemeral GCs (1 200 19900 1313400 64684950 2535650040 82408626300 2283896214600 ...) > (stop-backtrace-logging) NIL;; Reading source file "binomial2.lisp" ;;; Writing binary file "binomial2.sbin" ;;; Loading binary file "binomial2.sbin" > (start-backtrace-logging "binomial2.log") NIL > (time (binomial-coefficients 200)) Elapsed Real Time = 2.41 seconds Total Run Time = 2.41 seconds User Run Time = 2.40 seconds System Run Time = 0.01 seconds Process Page Faults = 0 Dynamic Bytes Consed = 0 Ephemeral Bytes Consed = 2,313,848 There were 5 ephemeral GCs (1 200 19900 1313400 64684950 2535650040 82408626300 2283896214600 ...) > (stop-backtrace-logging) NILThis version runs about 2.5 times faster than the original example and has half as many garbage collections. The backtrace logging summary shows that the time spent in perm has also been reduced by about half and that the execution time is more evenly split between fact and perm at level 3. The number of backtraces required to produce the summary has dropped from 647 to 241, which is proportional to the improvement in run-time for the root function, binomial-coefficients:

> (summarize-backtrace-logging "binomial2.log"

:root 'binomial-coefficients :max-backtrace-depth 6 :print-exclusive-time nil)Call-tree information obtained from a backtrace log. The numbers at each node represent the % of backtraces that include this node. There are 241 backtraces total.

1: BINOMIAL-COEFFICIENTS 100.000 2: CHOOSE 100.000 3: FACT 37.344 4: FACT 36.100 5: FACT 35.685 6: FACT 34.025 3: PERM 33.195 4: LIQUID::FIXNUM-BIGNUM-*-OPEN 31.120 5: #<Dynamic Closure> 5.394 6: SYSTEM:GC-INTERNAL 5.394 3: LIQUID-RUNTIME-SUPPORT:GENERIC-INTEGER-CONVERSION 14.108 4: (:INTERNAL LIQUID-RUNTIME-SUPPORT:GENERIC-INTEGER-CONVERSION LIQUID::PUNT) 13.693 5: LIQUID::BIGNUM-BIGNUM-DIVIDE 13.693 3: / 14.938 4: GCD 14.938 5: LIQUID::INTEGER-BINARY-GCD 14.938 6: LIQUID::IBG-BIG-BIG-REDUCTION 12.033 NIL

Liquid Common Lisp 5.0 Release and Installation Notes - 9 JUN 1997

Generated with Harlequin WebMaker