5.3.3 The performance monitor

5.3.3.2 Understanding performance monitoring output

Assume that you have loaded the following function definitions, and you would like to monitor their performance:

;; The function MAKE-EXAMPLE-LIST creates a list of numbers in 
(defun make-example-list (count) 
	(let (example-list) 
	(dotimes (i count example-list) 
	(push i example-list)))) 

;;; The function EXAMPLE-FUNCTION constructs a palindromic list 
;;; of numbers the length of the specified argument. It does not 
;;; use an efficient algorithm for its computation. 
(defun example-function (count) 
	(let ((list (make-example-list count))) 
	(dotimes (i (length list)) 
	(let ((obj (nth i list))) 
	(when (example-test-p i obj) 
	(setf (nth i list) i)))))) 
;;; The function EXAMPLE-FUNCTION-2 constructs a palindromic list ;;; of numbers the length of the specified argument. 
(defun example-function-2 (count) 
	(do* ((list (make-example-list count) (cdr list)) 
	(i 0 (1+ i)) 
	(obj (car list) (car list))) 
	((null list) nil) 
	(when (example-test-p i obj) 
	(setf (car list) i)))) 

;;; The function EXAMPLE-TEST-P compares two numbers. 
(defun example-test-p (index object) 
	(< index object))

The results returned by the Performance Monitor show that example-function is much less efficient than example-function-2; the algorithm for example-function has a computing time that is on the order of (n2), where n is the size of its argument:

> (monitor example-function example-function-2) 
(EXAMPLE-FUNCTION EXAMPLE-FUNCTION-2) 
> (start-monitoring) 
T 
> (example-function 1000) 
NIL 
> (example-function-2 1000) 
NIL 
> (stop-monitoring) 
NIL 
> (print-monitor 'example-function)
 Monitor information for EXAMPLE-FUNCTION 
Number of calls 	: 1 
Inclusive Time (secs) 	: 0.398 
Exclusive Time (secs) 	: 0.398 
Inclusive Consing (words) 	: 2004 
Exclusive Consing (words) 	: 2004 

NIL 

> (print-monitor 'example-function-2)
 Monitor information for EXAMPLE-FUNCTION-2 
Number of calls 	: 1 
Inclusive Time (secs) 	: 0.019 
Exclusive Time (secs) 	: 0.019 
Inclusive Consing (words) 	: 2000 
Exclusive Consing (words) 	: 2000 
NIL

The Performance Monitor returns the following information:

the name of the function being monitored
the cumulative number of times the function was called by all other functions
the inclusive time, which is the number of seconds spent in this function and in the functions that it calls
the exclusive time, which is the number of seconds spent exclusively in this function
the inclusive consing, which is the number of words of storage allocated for this function and for all the functions that it calls
the exclusive consing, which is the number of words of storage allocated exclusively for this function

To summarize the monitoring activity of all monitored functions, you can invoke the function summarize-monitors:

;;; SUMMARIZE-MONITORS prints a summary of the monitor information ;;; that has been collected. The keyword argument :NUMBER-OF-CALLS
;;; is set to T to ensure that the number of calls are part of the ;;; summary; the keyword arguments :EXCLUSIVE-TIME and 
;;; :EXCLUSIVE-CONSING are T by default. 
> (summarize-monitors :number-of-calls t) 

Cumulative Exclusive Time (Seconds) 
 1: EXAMPLE-FUNCTION 	-- 0.398 
 2: EXAMPLE-FUNCTION-2	-- 0.019 

Cumulative Exclusive Consing (Words) 
 1: EXAMPLE-FUNCTION 	-- 2000 
 2: EXAMPLE-FUNCTION-2  -- 2004
 
Cumulative Total Calls 
 1: LIQUID:SET-CURRENT-AREA 	-- 47 
 2: EXAMPLE-FUNCTION	--  1
 3: EXAMPLE-FUNCTION-2	--  1

NIL

Note that the summary includes information about some internal functions of the implementation, such as liquid:set-current-area.

If the amount of run-time or storage used by a function seems unreasonable, you have found a place where rewriting might make a difference.

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

Generated with Harlequin WebMaker