Why are the number of bytes consed reported by TIME differing for different calls?

Question

Using SBCL 1.4.12, I am looking at Exercise 17.9 from Stuart Shapiro's Common Lisp: An Interactive Approach, and timing a reverse function applied to a list of 10,000 elements. When I time this function using the same list, the time function reports a different number of bytes consed each time.

Here is the code for the reverse function:

(defun reverse2 (l1 l2)
  "Returns a list consisting of the members of L1 in reverse order
   followed by the members of L2 in original order."
  (check-type l1 list)
  (check-type l2 list)
  (if (endp l1) l2
      (reverse2 (rest l1)
                (cons (first l1) l2))))

(defun reverse1 (l)
  "Returns a copy of the list L1
   with the order of members reversed."
  (check-type l list)
  (reverse2 l '()))

I generated the list in the REPL with:

(defvar *test-list* '())
(dotimes (x 10000)
  (setf *test-list* (cons x *test-list*)))

Here are the results of four test-runs:

CL-USER> (time (ch17:reverse1 *test-list*))
Evaluation took:
  0.000 seconds of real time
  0.000000 seconds of total run time (0.000000 user, 0.000000 system)
  100.00% CPU
  520,386 processor cycles
  145,696 bytes consed

CL-USER> (time (ch17:reverse1 *test-list*))
Evaluation took:
  0.000 seconds of real time
  0.000000 seconds of total run time (0.000000 user, 0.000000 system)
  100.00% CPU
  260,640 processor cycles
  178,416 bytes consed

CL-USER> (time (ch17:reverse1 *test-list*))
Evaluation took:
  0.000 seconds of real time
  0.000000 seconds of total run time (0.000000 user, 0.000000 system)
  100.00% CPU
  279,822 processor cycles
  178,416 bytes consed

CL-USER> (time (ch17:reverse1 *test-list*))
Evaluation took:
  0.000 seconds of real time
  0.000000 seconds of total run time (0.000000 user, 0.000000 system)
  100.00% CPU
  264,700 processor cycles
  161,504 bytes consed

The second and third test runs (which were several minutes apart) show the same number of bytes consed, but the other two show different numbers. I expected the timing to vary, but I did not expect the number of bytes consed to vary. I see that the HyperSpec says of the time function that:

In general, these timings are not guaranteed to be reliable enough for marketing comparisons. Their value is primarily heuristic, for tuning purposes.

But I expected that this applies to timings, not to byte counts. Are the bytes consed values reported by time unreliable? Is there an optimization behind the scenes that is responsible for this? What am I missing?

Answer 1

The amount of consing (in the 'bytes of memory allocated' sense) depends on everything:

• it depends on how many objects of what types you allocate;
• it depends on fine implementation details of the allocator such as whether it allocates in large chunks and whether 'allocation' between the allocating of large chunks is recorded;
• it depends on the garbage collector -- was one triggered? if so what sort of one? how hairy is the GC? does the GC itself allocate? how is allocation counted across GCs?
• it depends on whether the system is doing other allocation, for instance in other threads, and whether that allocation gets counted or not in your thread -- is there just one allocator or are there per-thread allocators?
• it depends on the phase of the Moon & whether Pluto is a planet;
• and so on.

In general, if you have a very simple single-threaded implementation with a very simple allocator and a very simple GC then keeping track of allocation is easy and you will get reliable numbers. Many Lisp implementations were once like that: they were easy to understand and you got to drink a lot of tea while they did anything (OK, machines were slower then, but still they were often impressively slow even by the standards of the time). Now Lisps have multiple threads, sophisticated allocators and GCs and they're really fast, but how much allocation happens has become a question which is very hard to answer and often slightly unpredictable.