5.3.2 The backtrace logging facility

5.3.2.1 Using the Backtrace Logging Facility

To use the Backtrace Logging Facility, follow these steps:

: 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.

You cannot use the Backtrace Logging Facility at the same time that you are using the Performance Monitor. See the section "The Performance Monitor" for information about monitoring functions.

The filebinomial.lisp contains a program for computing the list of coefficients that are obtained when the expression(x + 1)nis 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 time to produce some initial performance estimates; the results of the test run are written to the filebinomial.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) 

NIL

With 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 NIL

These 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) 

NIL

This 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