make-instance conses 524k bytes and takes 4msec

Question

(time (make-instance 'Flat-Key :key "hello world" :fragment 1))

Yields:

Evaluation took:  
  0.005 seconds of real time  
  0.004367 seconds of total run time (0.004333 user, 0.000034 system)  
  80.00% CPU  
  22 lambdas converted  
  11,382,613 processor cycles  
  524,032 bytes consed

#<FLAT-KEY ((:KEY "hello world") (:HASH 1308457856027851121) (:BUCKET-INDEX 7)
        (:HASH-AS-MASK "1228937CD01BF9-7-1")) {10045AB573}>

Are these amounts normal?
If not, how can I improve my code?
If normal, what causes this?

The second and third call to #'time in in ±2.5msec and still cons ±500k bytes (second call had #'print-object method removed).

I'm using SBCL in a Emacs-slime session. The class definition has 4 slots. #'print-object does some work; i.e. it formats the lazily calculated hash). But even with #'print-object removed it takes 2ms and conses ±500k bytes.
The class and its functions are loaded via quicklisp's quickload (i'm not sure whether quicklisp has compiled the code or not; slime's slime-compile-file has no effect on speed or bytes consed).

Flat-Key is:

(defclass Flat-Key (Key)
  ()
  (:documentation
   "Keys without any level of nesting as used in conventional hash-tries and
Prokopecs CTrie."))

Key is:

(defclass Key ()
  ((val :initarg :key
    :reader get-key
    :documentation
    "The value of this Key")
   (hash :initarg :hash
     :initform nil
     :documentation
     "Cached `sxhash` of `key-val`, when nil it can be calculated.")
   (hash-fragment-index :initarg :fragment
            :reader get-fragment-index
            :documentation
            "The level in the trie for which `bucket-index` is valid.")
   (bucket-index :initform nil
         :documentation
         "Cached index into the `CNode's` `Bitindexed-List`."))
  (:documentation
   "Common base of all keys in a Trie"))

In Didier Verna CLOS Efficiency: Instantiation: On the Behavior and Performance of Lisp, Part 2.1 International Lisp Conference ILC 2009, Mar 2009, Cambridge, United States. Proceedings of theILC 2009 Conference, 2009. (available via https://hal.archives-ouvertes.fr/hal-01543396/document), Didier Verna measures millions of `#'make-instance' invocations in this timespan.

CLOS make-instance is really slow and causes heap exhaustion in SBCL is also about #'make-instance and the amount of conses, but it appears nrz is doing way more advanced stuff. And I don't think I can apply Rainer Joswig's advice in my situation.

tl; dr

Is it normal that #'make-instance with a 4 slot class takes 2ms-5ms and conses 400k-500k bytes?
If not, what am I doing wrong?
If normal, what is happening?

Answer 1

This is a community answer that regroup various comments. You can contribute to this answer and add other advices about benchmarking, not necessarily specific to SBCL.

• Benchmarking a single call is likely to give unreliable results if the function is fast. Why not compile a function to make an instance N times and find a value of N to give you about 5s execution time or so, then look at the average. (Dan Robertson)

• Also put the code in a compiled function, rather than writing it directly to the REPL. While the REPL does compile the input form, SBCL doesn't optimize it the same way it does for functions. (jkiiski)

• The first make-instance can have an overhead if it needs to call finalize-inheritance. You may want to call that yourself to factor out this overhead from subsequent calls.

• Note that by calling (sb-ext:gc :full t) before time, you generally have less variance in results, removing one source of "noise" in your measures.

• Slime/swank needs to exchange data and in an idle Lisp with Slime, the dynamic-space-size slowly increases over time (and shrinks after each gc). That does not happen with a non-slimed environment. It might not impact much time, but you never know.