results.profile.txt

TESTED: jesse.franz.com on Mon Jul 22 12:56:58 PDT 2019
make[1]: Entering directory `/acl/acl10.1/src/uri'
rm -f build.tmp *.fasl
echo '(load (compile-file "bench.cl"))' >> build.tmp
echo '(profile)' >> build.tmp
echo '(exit 0)' >> build.tmp
../lisp -I dcl.dxl +s build.tmp -qq -batch
Allegro CL [master]
10.1 [32-bit Linux (x86)] (Jul 22, 2019 12:40)
Copyright (C) 1985-2019, Franz Inc., Oakland, CA, USA.  All Rights Reserved.

This development copy of Allegro CL is licensed to:
   Franz Inc. Staff

;; Optimization settings: safety 1, space 1, speed 1, debug 2.
;; For a complete description of all compiler switches given the
;; current optimization settings evaluate (explain-compiler-settings).
;;---
;; Current reader case mode: :case-sensitive-lower
;;; Compiling file bench.cl
;;; Writing fasl file bench.fasl
;;; Fasl write complete
; Fast loading /acl/acl10.1/src/uri/bench.fasl

t 

;;;;;;; :time #<Function run-bm1>


;; Testing #<Function uri-perf-parse>..

; cpu time (non-gc) 9.517555 sec user, 0.003000 sec system
; cpu time (gc)     0.254959 sec user, 0.008998 sec system
; cpu time (total)  9.772514 sec user, 0.011998 sec system
; real time  9.785742 sec (99.99%)
; space allocation:
;  0 cons cells, 838,400,000 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 3 (gc: 0)

; cpu time (non-gc) 9.473560 sec user, 0.002000 sec system
; cpu time (gc)     0.294955 sec user, 0.013998 sec system
; cpu time (total)  9.768515 sec user, 0.015998 sec system
; real time  9.785821 sec (99.99%)
; space allocation:
;  0 cons cells, 838,400,000 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)

; cpu time (non-gc) 9.529549 sec user, 0.000000 sec system
; cpu time (gc)     0.243965 sec user, 0.011998 sec system
; cpu time (total)  9.773514 sec user, 0.011998 sec system
; real time  9.786720 sec (99.99%)
; space allocation:
;  0 cons cells, 838,400,000 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)
Sampling stopped after 2934 samples taken for the time profiler.

Sample represents 29.3 seconds of user+system CPU time (out of a total of 29.4).

Times below 1.0% will be suppressed.

 %    %   self total         self   total  Function                                  
Time Cum. secs  secs calls ms/call ms/call   name                                    
38.8 38.8 11.4  11.4                       net.uri::looking-at
10.4 49.3  3.1  11.9                       ... net.uri::scan-forward
 8.8 58.1  2.6   3.2                       net.uri::val
 5.3 63.4  1.5   2.6                       net.uri::percent-decode-string
 2.9 66.2  0.8   0.8                       "values"
 2.8 69.0  0.8   0.8                       "(after-libnss_files.so.2-lib)"
 2.1 71.1  0.6   1.1                       net.uri::scan-pct-encoded
 2.0 73.1  0.6   0.6                       excl::simple-string-equal
 1.8 74.9  0.5  28.5                       ... parse-uri
 1.8 76.7  0.5  23.7                       ... parse-uri-string-rfc3986
 1.7 78.4  0.5   0.5                       "new_simple_string"
 1.4 79.8  0.4   3.2                       ... net.uri::scan-pchar
 1.3 81.1  0.4  13.2                       ... net.uri::state-absolute-uri
 1.2 82.3  0.4   3.6                       net.uri::state-path-abempty
 1.2 83.5  0.3   0.3                       length
 1.2 84.7  0.3   0.3                       excl::internal-string-equal
Time profile of sampled pc values by function, children, and parents.

Total times below 1.0% will be suppressed.
Parent and child times less 2.0% of the node will be suppressed.
Sampling stopped after 2934 samples taken for the time profiler.

Sample represents 29.3 seconds of user+system CPU time (out of a total of 29.4).

  %     %                       Parent
 self total   total local  Function
 Time  Time    secs   %         Child

  0.0 100.0    29.3   0.0  ==> ... "start"
               29.3 100.0        ... "start_reborn_lisp"
-----------------------------------------------------
               29.3 100.0        ... "start"
  0.0 100.0    29.3   0.0  ==> "start_reborn_lisp"
               29.3 100.0        "first_lisp_thread"
-----------------------------------------------------
               29.3 100.0        "start_reborn_lisp"
  0.0 100.0    29.3   0.0  ==> "first_lisp_thread"
               29.3 100.0        excl::lisp-thread-start
-----------------------------------------------------
               29.3 100.0        "first_lisp_thread"
  0.0 100.0    29.3   0.0  ==> excl::lisp-thread-start
               29.3 100.0        excl::run-initial-thread
-----------------------------------------------------
               29.3 100.0        excl::lisp-thread-start
  0.0 100.0    29.3   0.0  ==> ... excl::run-initial-thread
               29.3 100.0        ... excl::thread-reset-catcher
-----------------------------------------------------
               29.3 100.0        ... excl::run-initial-thread
  0.0 100.0    29.3   0.0  ==> excl::thread-reset-catcher
               29.3 100.0        excl::thread-bind-and-call
-----------------------------------------------------
               29.3 100.0        excl::thread-reset-catcher
  0.0 100.0    29.3   0.0  ==> ... excl::thread-bind-and-call
               29.3 100.0        ... excl::process-script
-----------------------------------------------------
               29.3 100.0        ... excl::thread-bind-and-call
  0.0 100.0    29.3   0.0  ==> excl::process-script
               29.3 100.0        eval
-----------------------------------------------------
               29.3 100.0        excl::process-script
  0.0 100.0    29.3   0.0  ==> eval
               29.3 100.0        profile
-----------------------------------------------------
               29.3 100.0        eval
  0.0 100.0    29.3   0.0  ==> profile
               29.3 100.0        profile-bm1
-----------------------------------------------------
               29.3 100.0        profile
  0.0 100.0    29.3   0.0  ==> profile-bm1
               29.3 100.0        prof::prof-a-funcall
-----------------------------------------------------
               29.3 100.0        profile-bm1
  0.0 100.0    29.3   0.0  ==> prof::prof-a-funcall
               29.3 100.0        (:internal profile-bm1 0)
-----------------------------------------------------
               29.3 100.0        prof::prof-a-funcall
  0.0 100.0    29.3   0.0  ==> (:internal profile-bm1 0)
               29.3 100.0        run-bm1
-----------------------------------------------------
               29.3 100.0        (:internal profile-bm1 0)
  0.0 100.0    29.3   0.0  ==> run-bm1
               29.3 100.0        do-bm
-----------------------------------------------------
               29.3 100.0        run-bm1
  0.0 100.0    29.3   0.0  ==> do-bm
               29.3 100.0        excl::time-a-funcall
-----------------------------------------------------
               29.3 100.0        do-bm
  0.0 100.0    29.3   0.0  ==> ... excl::time-a-funcall
               29.3 100.0        ... (:internal do-bm 2)
-----------------------------------------------------
               29.3 100.0        ... excl::time-a-funcall
  0.0 100.0    29.3   0.0  ==> (:internal do-bm 2)
               29.3  99.8        uri-perf-parse
-----------------------------------------------------
               29.3 100.0        (:internal do-bm 2)
  0.4  99.8    29.3   0.4  ==> ... uri-perf-parse
               28.4  97.0        parse-uri
-----------------------------------------------------
               28.4  99.8        uri-perf-parse
  1.8  97.0    28.5   1.9  ==> ... parse-uri
               23.5  82.7        parse-uri-string-rfc3986
                2.5   8.7        net.uri::percent-decode-string
-----------------------------------------------------
               23.5  99.4        parse-uri
  1.8  80.7    23.7   2.2  ==> ... parse-uri-string-rfc3986
               13.2  55.6        net.uri::state-absolute-uri
                5.9  25.0        net.uri::state-uri-reference
                2.9  12.4        net.uri::val
-----------------------------------------------------
               13.2  99.8        parse-uri-string-rfc3986
  1.3  45.0    13.2   2.9  ==> ... net.uri::state-absolute-uri
                6.9  52.3        net.uri::state-hier-part
                2.3  17.3        net.uri::state-urn-namestring
                1.8  13.6        net.uri::state-query
                1.2   8.9        net.uri::state-scheme
                0.4   2.7        net.uri::looking-at
-----------------------------------------------------
                2.5  21.4        net.uri::scan-pchar
                2.2  18.2        net.uri::state-query
                2.0  16.5        net.uri::state-userinfo
                1.7  14.6        net.uri::state-reg-name
                0.9   7.9        net.uri::state-scheme
                0.8   6.9        net.uri::state-urn-nss
                0.8   6.6        net.uri::state-urn-nid
                0.3   2.9        net.uri::state-fragment
 10.4  40.5    11.9  25.7  ==> ... net.uri::scan-forward
                7.9  66.3        net.uri::looking-at
                0.9   7.9        net.uri::scan-pct-encoded
-----------------------------------------------------
                7.9  69.2        net.uri::scan-forward
                0.5   4.4        net.uri::scan-pct-encoded
                0.4   3.2        net.uri::state-absolute-uri
                0.3   3.1        net.uri::state-scheme
                0.3   2.7        net.uri::state-hier-part
                0.3   2.4        net.uri::state-userinfo
 38.8  38.8    11.4 100.0  ==> net.uri::looking-at
-----------------------------------------------------
                6.9  65.0        net.uri::state-absolute-uri
                3.7  34.6        net.uri::state-uri
  0.9  36.2    10.6   2.4  ==> ... net.uri::state-hier-part
                6.2  58.5        net.uri::state-authority
                3.6  33.6        net.uri::state-path-abempty
                0.3   2.9        net.uri::looking-at
-----------------------------------------------------
                6.2  99.7        net.uri::state-hier-part
  0.9  21.2     6.2   4.2  ==> net.uri::state-authority
                3.0  47.7        net.uri::state-host
                2.4  38.4        net.uri::state-userinfo
                0.2   3.5        net.uri::state-port
                0.2   2.4        "values"
-----------------------------------------------------
                5.9  99.8        parse-uri-string-rfc3986
  0.2  20.2     5.9   1.2  ==> net.uri::state-uri-reference
                5.7  95.8        net.uri::state-uri
-----------------------------------------------------
                5.7 100.0        net.uri::state-uri-reference
  0.5  19.4     5.7   2.6  ==> ... net.uri::state-uri
                3.7  64.6        net.uri::state-hier-part
                0.8  14.1        net.uri::state-query
                0.4   7.6        net.uri::state-fragment
                0.3   6.0        net.uri::state-scheme
                0.2   2.8        net.uri::looking-at
-----------------------------------------------------
                3.6  98.9        net.uri::state-hier-part
  1.2  12.3     3.6  10.0  ==> net.uri::state-path-abempty
                3.0  84.5        net.uri::scan-pchar
                0.2   4.4        net.uri::looking-at
-----------------------------------------------------
                3.0  95.0        net.uri::state-path-abempty
                0.1   3.1        net.uri::state-urn-nss
  1.4  10.9     3.2  13.1  ==> ... net.uri::scan-pchar
                2.5  79.4        net.uri::scan-forward
                0.2   6.9        net.uri::looking-at
-----------------------------------------------------
                2.9  92.4        parse-uri-string-rfc3986
                0.2   7.6        parse-uri
  8.8  10.8     3.2  81.7  ==> net.uri::val
                0.3   9.8        "new_simple_string"
                0.3   8.5        "(after-libnss_files.so.2-lib)"
-----------------------------------------------------
                3.0  99.3        net.uri::state-authority
  0.4  10.2     3.0   4.3  ==> net.uri::state-host
                2.1  69.2        net.uri::state-reg-name
                0.4  14.4        net.uri::state-ipv4address
                0.2   5.0        net.uri::state-ip-literal
                0.1   3.3        net.uri::scan-ipv4address
-----------------------------------------------------
                1.8  68.6        net.uri::state-absolute-uri
                0.8  30.7        net.uri::state-uri
  0.5   8.9     2.6   6.1  ==> ... net.uri::state-query
                2.2  82.8        net.uri::scan-forward
                0.2   7.3        net.uri::looking-at
                0.1   3.8        net.uri::scan-pct-encoded
-----------------------------------------------------
                2.5  96.5        parse-uri
                0.1   3.5        uri-perf-parse
  5.3   8.8     2.6  60.3  ==> net.uri::percent-decode-string
                0.5  21.0        "(after-libnss_files.so.2-lib)"
                0.2   6.6        "new_simple_string"
                0.1   4.3        digit-char-p
                0.1   3.5        length
                0.1   2.7        "shrink_svector"
-----------------------------------------------------
                2.4  98.8        net.uri::state-authority
  0.6   8.2     2.4   7.0  ==> ... net.uri::state-userinfo
                2.0  81.0        net.uri::scan-forward
                0.3  11.2        net.uri::looking-at
-----------------------------------------------------
                2.3  99.6        net.uri::state-absolute-uri
  0.1   7.8     2.3   1.7  ==> net.uri::state-urn-namestring
                2.2  97.8        net.uri::state-urn-assigned-name
-----------------------------------------------------
                2.2 100.0        net.uri::state-urn-namestring
  0.1   7.6     2.2   1.8  ==> net.uri::state-urn-assigned-name
                1.1  49.1        net.uri::state-urn-nss
                1.0  44.2        net.uri::state-urn-nid
                0.1   2.7        net.uri::looking-at
-----------------------------------------------------
                2.1  99.5        net.uri::state-host
  0.3   7.1     2.1   4.3  ==> net.uri::state-reg-name
                1.7  83.7        net.uri::scan-forward
                0.2  10.1        net.uri::looking-at
-----------------------------------------------------
                1.2  75.2        net.uri::state-absolute-uri
                0.3  21.7        net.uri::state-uri
                0.1   3.2        parse-uri-string-rfc3986
  1.0   5.4     1.6  17.8  ==> net.uri::state-scheme
                0.9  59.9        net.uri::scan-forward
                0.3  22.3        net.uri::looking-at
-----------------------------------------------------
                0.9  83.2        net.uri::scan-forward
                0.1   8.8        net.uri::state-query
                0.0   3.5        net.uri::state-reg-name
                0.0   2.7        net.uri::scan-pchar
  2.1   3.9     1.1  55.8  ==> net.uri::scan-pct-encoded
                0.5  44.2        net.uri::looking-at
-----------------------------------------------------
                1.1 100.0        net.uri::state-urn-assigned-name
  0.1   3.7     1.1   2.7  ==> net.uri::state-urn-nss
                0.8  74.5        net.uri::scan-forward
                0.2  13.6        net.uri::looking-at
                0.1   9.1        net.uri::scan-pchar
-----------------------------------------------------
                1.0 100.0        net.uri::state-urn-assigned-name
  0.2   3.4     1.0   5.1  ==> net.uri::state-urn-nid
                0.8  78.8        net.uri::scan-forward
                0.2  16.2        net.uri::looking-at
-----------------------------------------------------
                0.2  27.4        ... parse-uri-string-rfc3986
                0.2  20.2        ... net.uri::state-absolute-uri
                0.2  17.9        net.uri::state-authority
                0.1  14.3        net.uri::state-hier-part
                0.1   7.1        ... net.uri::state-uri
                0.0   4.8        net.uri::state-uri-reference
                0.0   3.6        ... parse-uri
                0.0   3.6        net.uri::state-urn-assigned-name
  2.9   2.9     0.8 100.0  ==> "values"
-----------------------------------------------------
                0.5  66.7        net.uri::percent-decode-string
                0.3  33.3        net.uri::val
  2.8   2.8     0.8 100.0  ==> "(after-libnss_files.so.2-lib)"
-----------------------------------------------------
                0.5  79.7        parse-uri
                0.1  20.3        uri-perf-parse
  2.0   2.0     0.6 100.0  ==> excl::simple-string-equal
-----------------------------------------------------
                0.3  59.6        net.uri::val
                0.2  32.7        net.uri::percent-decode-string
                0.0   3.8        ... parse-uri
                0.0   3.8        parse-uri-string-rfc3986
  1.7   1.8     0.5  94.2  ==> "new_simple_string"
                0.0   5.8        "scavenge"
-----------------------------------------------------
                0.4  93.5        net.uri::state-uri
                0.0   6.5        net.uri::state-uri-reference
  0.2   1.6     0.5  10.9  ==> net.uri::state-fragment
                0.3  76.1        net.uri::scan-forward
                0.1  13.0        net.uri::looking-at
-----------------------------------------------------
                0.4  97.7        net.uri::state-host
                0.0   2.3        net.uri::state-authority
  0.2   1.5     0.4  13.6  ==> net.uri::state-ipv4address
                0.3  77.3        net.uri::scan-ipv4address
                0.0   9.1        net.uri::scan-dec-octet
-----------------------------------------------------
                0.3  77.3        net.uri::state-ipv4address
                0.1  22.7        net.uri::state-host
  0.4   1.5     0.4  27.3  ==> net.uri::scan-ipv4address
                0.2  56.8        net.uri::scan-dec-octet
                0.1  15.9        net.uri::scan-forward
-----------------------------------------------------
                0.1  41.2        parse-uri
                0.1  26.5        net.uri::percent-decode-string
                0.0  11.8        parse-uri-string-rfc3986
                0.0  11.8        uri-perf-parse
                0.0   5.9        net.uri::check-xri-string
                0.0   2.9        parse-integer
  1.2   1.2     0.3 100.0  ==> length
-----------------------------------------------------
                0.2  55.9        uri-perf-parse
                0.2  44.1        parse-uri
  1.2   1.2     0.3 100.0  ==> excl::internal-string-equal
-----------------------------------------------------
                0.3  90.9        parse-uri-string-rfc3986
                0.0   9.1        parse-uri
  0.4   1.1     0.3  39.4  ==> parse-integer
                0.1  27.3        char
                0.0  12.1        digit-char-p
                0.0   9.1        "kwdscan"
                0.0   6.1        excl::*_2op
                0.0   3.0        excl::readtable-attribute-table
                0.0   3.0        length
-----------------------------------------------------
                0.3  90.3        parse-uri
                0.0   9.7        uri-perf-parse
  0.5   1.1     0.3  45.2  ==> ... (:internal (:anonymous-lambda 16) 0)
                0.2  48.4        "vector"
                0.0   6.5        ...
                0.0   6.5        ... "new_other"
-----------------------------------------------------


;;;;;;; :time #<Function run-bm2>


;; Testing #<Function uri-perf-render-uri>..

; cpu time (non-gc) 9.471562 sec user, 0.001000 sec system
; cpu time (gc)     0.140976 sec user, 0.004000 sec system
; cpu time (total)  9.612538 sec user, 0.005000 sec system
; real time  9.618825 sec (99.99%)
; space allocation:
;  38,400,067 cons cells, 768,000,880 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 121 (gc: 0)

; cpu time (non-gc) 9.481552 sec user, 0.003000 sec system
; cpu time (gc)     0.130987 sec user, 0.006998 sec system
; cpu time (total)  9.612539 sec user, 0.009998 sec system
; real time  9.623765 sec (99.99%)
; space allocation:
;  38,400,000 cons cells, 768,000,000 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 1 (gc: 0)

; cpu time (non-gc) 9.476559 sec user, 0.000000 sec system
; cpu time (gc)     0.132980 sec user, 0.005999 sec system
; cpu time (total)  9.609539 sec user, 0.005999 sec system
; real time  9.617124 sec (99.98%)
; space allocation:
;  38,400,000 cons cells, -3,526,967,296 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)
Sampling stopped after 2884 samples taken for the time profiler.

Sample represents 28.8 seconds of user+system CPU time (out of a total of 28.9).

Times below 1.0% will be suppressed.

 %    %   self total         self   total  Function                                  
Time Cum. secs  secs calls ms/call ms/call   name                                    
37.1 37.1 10.7  11.0                       util.string::%string+
26.7 63.8  7.7   8.2                       subseq
 7.1 70.9  2.1  20.8                       ... (method
                                                render-uri
                                                (uri t))
 3.0 73.9  0.9   0.9                       "st_restify"
 2.1 76.0  0.6   1.5                       net.uri::render-parsed-path
 1.7 77.8  0.5  20.1                       ... util.string:string+
 1.7 79.5  0.5   0.5                       stringp
 1.7 81.2  0.5   0.5                       "gc_setf_protect"
 1.6 82.8  0.4  28.1                       ... uri-perf-render-uri
 1.4 84.2  0.4   0.4                       (:discriminator
                                            (:checking (class) nil))
 1.4 85.6  0.4   0.4                       "new_simple_string"
 1.4 86.9  0.4   0.4                       "list_nreverse"
 1.1 88.1  0.3   0.3                       "(after-libnss_files.so.2-lib)"
 1.1 89.2  0.3   0.3                       (:discriminator
                                            (:caching (class t) nil))
 1.1 90.3  0.3   0.3                       util.string::print-fixnum
 1.0 91.3  0.3   5.5                       ... (method
                                                render-uri
                                                (urn t))
Time profile of sampled pc values by function, children, and parents.

Total times below 1.0% will be suppressed.
Parent and child times less 2.0% of the node will be suppressed.
Sampling stopped after 2884 samples taken for the time profiler.

Sample represents 28.8 seconds of user+system CPU time (out of a total of 28.9).

  %     %                       Parent
 self total   total local  Function
 Time  Time    secs   %         Child

  0.0 100.0    28.8   0.0  ==> ... "start"
               28.8 100.0        ... "start_reborn_lisp"
-----------------------------------------------------
               28.8 100.0        ... "start"
  0.0 100.0    28.8   0.0  ==> "start_reborn_lisp"
               28.8 100.0        "first_lisp_thread"
-----------------------------------------------------
               28.8 100.0        "start_reborn_lisp"
  0.0 100.0    28.8   0.0  ==> "first_lisp_thread"
               28.8 100.0        excl::lisp-thread-start
-----------------------------------------------------
               28.8 100.0        "first_lisp_thread"
  0.0 100.0    28.8   0.0  ==> excl::lisp-thread-start
               28.8 100.0        excl::run-initial-thread
-----------------------------------------------------
               28.8 100.0        excl::lisp-thread-start
  0.0 100.0    28.8   0.0  ==> ... excl::run-initial-thread
               28.8 100.0        ... excl::thread-reset-catcher
-----------------------------------------------------
               28.8 100.0        ... excl::run-initial-thread
  0.0 100.0    28.8   0.0  ==> excl::thread-reset-catcher
               28.8 100.0        excl::thread-bind-and-call
-----------------------------------------------------
               28.8 100.0        excl::thread-reset-catcher
  0.0 100.0    28.8   0.0  ==> ... excl::thread-bind-and-call
               28.8 100.0        ... excl::process-script
-----------------------------------------------------
               28.8 100.0        ... excl::thread-bind-and-call
  0.0 100.0    28.8   0.0  ==> excl::process-script
               28.8 100.0        eval
-----------------------------------------------------
               28.8 100.0        excl::process-script
  0.0 100.0    28.8   0.0  ==> eval
               28.8 100.0        profile
-----------------------------------------------------
               28.8 100.0        eval
  0.0 100.0    28.8   0.0  ==> profile
               28.8 100.0        profile-bm2
-----------------------------------------------------
               28.8 100.0        profile
  0.0 100.0    28.8   0.0  ==> profile-bm2
               28.8 100.0        prof::prof-a-funcall
-----------------------------------------------------
               28.8 100.0        profile-bm2
  0.0 100.0    28.8   0.0  ==> prof::prof-a-funcall
               28.8 100.0        (:internal profile-bm2 0)
-----------------------------------------------------
               28.8 100.0        prof::prof-a-funcall
  0.0 100.0    28.8   0.0  ==> (:internal profile-bm2 0)
               28.8 100.0        run-bm2
-----------------------------------------------------
               28.8 100.0        (:internal profile-bm2 0)
  0.0 100.0    28.8   0.0  ==> run-bm2
               28.8 100.0        do-bm
-----------------------------------------------------
               28.8 100.0        run-bm2
  0.0 100.0    28.8   0.0  ==> do-bm
               28.8 100.0        excl::time-a-funcall
-----------------------------------------------------
               28.8 100.0        do-bm
  0.0 100.0    28.8   0.0  ==> ... excl::time-a-funcall
               28.8 100.0        ... (:internal do-bm 2)
-----------------------------------------------------
               28.8 100.0        ... excl::time-a-funcall
  0.2 100.0    28.8   0.2  ==> ... (:internal do-bm 2)
               28.1  97.5        uri-perf-render-uri
-----------------------------------------------------
               28.1 100.0        (:internal do-bm 2)
  1.6  97.5    28.1   1.6  ==> ... uri-perf-render-uri
               20.7  73.6        (method render-uri (uri t))
                5.4  19.4        (method render-uri (urn t))
-----------------------------------------------------
               20.7  99.3        uri-perf-render-uri
  7.1  72.2    20.8   9.9  ==> ... (method render-uri (uri t))
               15.4  74.0        util.string:string+
                1.4   6.8        net.uri::render-parsed-path
                1.1   5.3        ...
                0.7   3.6        ... "st_restify"
-----------------------------------------------------
               15.4  76.9        ... (method render-uri (uri t))
                4.5  22.5        (method render-uri (urn t))
  1.7  69.6    20.1   2.5  ==> ... util.string:string+
               10.9  54.5        util.string::%string+
                8.1  40.4        subseq
                0.5   2.5        stringp
-----------------------------------------------------
               10.9  99.5        util.string:string+
 37.1  38.1    11.0  97.2  ==> util.string::%string+
                0.3   2.8        util.string::print-fixnum
-----------------------------------------------------
                8.1  98.2        util.string:string+
 26.7  28.6     8.2  93.3  ==> subseq
                0.4   4.6        "new_simple_string"
                0.2   2.1        "(after-libnss_files.so.2-lib)"
-----------------------------------------------------
                5.4  99.1        uri-perf-render-uri
  1.0  19.0     5.5   5.3  ==> ... (method render-uri (urn t))
                4.5  82.3        util.string:string+
                0.2   4.4        (:discriminator
                                  (:checking (class) nil))
                0.1   2.4        ... "st_restify"
-----------------------------------------------------
                1.4  95.3        (method render-uri (uri t))
                0.1   4.7        uri-perf-render-uri
  2.1   5.1     1.5  41.2  ==> net.uri::render-parsed-path
                0.4  24.3        "list_nreverse"
                0.3  19.6        "gc_setf_protect"
                0.2  10.8        "(after-libnss_files.so.2-lib)"
                0.0   2.7        keywordp
-----------------------------------------------------
                0.7  85.1        ... (method render-uri (uri t))
                0.1  14.9        ... (method render-uri (urn t))
  3.0   3.0     0.9 100.0  ==> "st_restify"
-----------------------------------------------------
                0.3  58.0        net.uri::render-parsed-path
                0.1  20.0        ... (method render-uri (uri t))
                0.1  16.0        uri-perf-render-uri
                0.0   6.0        ... (method render-uri (urn t))
  1.7   1.7     0.5 100.0  ==> "gc_setf_protect"
-----------------------------------------------------
                0.5 100.0        util.string:string+
  1.7   1.7     0.5 100.0  ==> stringp
-----------------------------------------------------
                0.2  58.5        (method render-uri (urn t))
                0.1  29.3        (method render-uri (uri t))
                0.1  12.2        uri-perf-render-uri
  1.4   1.4     0.4 100.0  ==> (:discriminator (:checking (class) nil))
-----------------------------------------------------
                0.4  92.3        net.uri::render-parsed-path
                0.0   7.7        (method render-uri (uri t))
  1.4   1.4     0.4 100.0  ==> "list_nreverse"
-----------------------------------------------------
                0.4  97.4        subseq
                0.0   2.6        ... util.string:string+
  1.4   1.4     0.4 100.0  ==> "new_simple_string"
-----------------------------------------------------
                0.2  69.7        uri-perf-render-uri
                0.1  30.3        (:internal do-bm 2)
  1.1   1.1     0.3 100.0  ==> (:discriminator (:caching (class t) nil))
-----------------------------------------------------
                0.2  51.5        subseq
                0.2  48.5        net.uri::render-parsed-path
  1.1   1.1     0.3 100.0  ==> "(after-libnss_files.so.2-lib)"
-----------------------------------------------------
                0.3  96.9        util.string::%string+
                0.0   3.1        util.string:string+
  1.1   1.1     0.3 100.0  ==> util.string::print-fixnum
-----------------------------------------------------


;;;;;;; :time #<Function run-bm3>


;; Testing #<Function uri-perf-format>..

; cpu time (non-gc) 10.672370 sec user, 0.000000 sec system
; cpu time (gc)     0.123988 sec user, 0.003000 sec system
; cpu time (total)  10.796358 sec user, 0.003000 sec system
; real time  10.800604 sec (99.99%)
; space allocation:
;  27,500,936 cons cells, 710,004,944 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)

; cpu time (non-gc) 10.673378 sec user, 0.000000 sec system
; cpu time (gc)     0.118982 sec user, 0.003999 sec system
; cpu time (total)  10.792360 sec user, 0.003999 sec system
; real time  10.797964 sec (99.99%)
; space allocation:
;  27,500,878 cons cells, 710,000,000 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)

; cpu time (non-gc) 10.672375 sec user, 0.002000 sec system
; cpu time (gc)     0.119984 sec user, 0.000999 sec system
; cpu time (total)  10.792359 sec user, 0.002999 sec system
; real time  10.797430 sec (99.98%)
; space allocation:
;  27,500,879 cons cells, 710,000,000 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)
Sampling stopped after 3239 samples taken for the time profiler.

Sample represents 32.4 seconds of user+system CPU time (out of a total of 32.5).

Times below 1.0% will be suppressed.

 %    %   self total         self   total  Function                                  
Time Cum. secs  secs calls ms/call ms/call   name                                    
19.0 19.0  6.1   6.1                       excl::string-output-write-chars
17.7 36.6  5.7   5.8                       util.string::%string+
13.0 49.6  4.2   4.5                       subseq
 7.4 57.0  2.4   2.7                       get-output-stream-string
 3.0 60.0  1.0  17.6                       ... (method
                                                render-uri
                                                (uri t))
 2.5 62.5  0.8   1.0                       "bind_one_spec"
 2.1 64.6  0.7   0.7                       ... (:discriminator
                                                (:caching
                                                 (class t)
                                                 nil))
 1.9 66.5  0.6  31.6                       ... format
 1.9 68.4  0.6  27.0                       excl::process-format-string
 1.9 70.3  0.6   0.6                       "gc_setf_protect"
 1.7 72.0  0.6   0.6                       (:internal
                                            excl::defresource-1
                                            1)
 1.5 73.5  0.5  24.1                       ... excl::basic-write
 1.4 74.9  0.4   0.5                       "unbind_count"
 1.3 76.2  0.4   0.7                       net.uri::render-parsed-path
 1.2 77.4  0.4   0.4                       "st_restify"
 1.1 78.6  0.4   0.4                       "(after-libnss_files.so.2-lib)"
 1.1 79.7  0.3  10.7                       ... util.string:string+
 1.0 80.7  0.3  25.8                       ... excl::format-engine
 1.0 81.8  0.3  25.0                       ... princ
 1.0 82.8  0.3   0.3                       "gc_setf_protect_1"
Time profile of sampled pc values by function, children, and parents.

Total times below 1.0% will be suppressed.
Parent and child times less 2.0% of the node will be suppressed.
Sampling stopped after 3239 samples taken for the time profiler.

Sample represents 32.4 seconds of user+system CPU time (out of a total of 32.5).

  %     %                       Parent
 self total   total local  Function
 Time  Time    secs   %         Child

  0.0 100.0    32.4   0.0  ==> ... "start"
               32.4 100.0        ... "start_reborn_lisp"
-----------------------------------------------------
               32.4 100.0        ... "start"
  0.0 100.0    32.4   0.0  ==> "start_reborn_lisp"
               32.4 100.0        "first_lisp_thread"
-----------------------------------------------------
               32.4 100.0        "start_reborn_lisp"
  0.0 100.0    32.4   0.0  ==> "first_lisp_thread"
               32.4 100.0        excl::lisp-thread-start
-----------------------------------------------------
               32.4 100.0        "first_lisp_thread"
  0.0 100.0    32.4   0.0  ==> excl::lisp-thread-start
               32.4 100.0        excl::run-initial-thread
-----------------------------------------------------
               32.4 100.0        excl::lisp-thread-start
  0.0 100.0    32.4   0.0  ==> ... excl::run-initial-thread
               32.4 100.0        ... excl::thread-reset-catcher
-----------------------------------------------------
               32.4 100.0        ... excl::run-initial-thread
  0.0 100.0    32.4   0.0  ==> excl::thread-reset-catcher
               32.4 100.0        excl::thread-bind-and-call
-----------------------------------------------------
               32.4 100.0        excl::thread-reset-catcher
  0.0 100.0    32.4   0.0  ==> ... excl::thread-bind-and-call
               32.4 100.0        ... excl::process-script
-----------------------------------------------------
               32.4 100.0        ... excl::thread-bind-and-call
  0.0 100.0    32.4   0.0  ==> excl::process-script
               32.4 100.0        eval
-----------------------------------------------------
               32.4 100.0        excl::process-script
  0.0 100.0    32.4   0.0  ==> eval
               32.4 100.0        profile
-----------------------------------------------------
               32.4 100.0        eval
  0.0 100.0    32.4   0.0  ==> profile
               32.4 100.0        profile-bm3
-----------------------------------------------------
               32.4 100.0        profile
  0.0 100.0    32.4   0.0  ==> profile-bm3
               32.4 100.0        prof::prof-a-funcall
-----------------------------------------------------
               32.4 100.0        profile-bm3
  0.0 100.0    32.4   0.0  ==> prof::prof-a-funcall
               32.4 100.0        (:internal profile-bm3 0)
-----------------------------------------------------
               32.4 100.0        prof::prof-a-funcall
  0.0 100.0    32.4   0.0  ==> (:internal profile-bm3 0)
               32.4 100.0        run-bm3
-----------------------------------------------------
               32.4 100.0        (:internal profile-bm3 0)
  0.0 100.0    32.4   0.0  ==> run-bm3
               32.4 100.0        do-bm
-----------------------------------------------------
               32.4 100.0        run-bm3
  0.0 100.0    32.4   0.0  ==> do-bm
               32.4 100.0        excl::time-a-funcall
-----------------------------------------------------
               32.4 100.0        do-bm
  0.0 100.0    32.4   0.0  ==> ... excl::time-a-funcall
               32.4 100.0        ... (:internal do-bm 2)
-----------------------------------------------------
               32.4 100.0        ... excl::time-a-funcall
  0.0 100.0    32.4   0.0  ==> (:internal do-bm 2)
               32.2  99.3        uri-perf-format
-----------------------------------------------------
               32.2 100.0        (:internal do-bm 2)
  0.5  99.3    32.2   0.5  ==> ... uri-perf-format
               31.5  97.9        format
-----------------------------------------------------
               31.5  99.8        uri-perf-format
  1.9  97.5    31.6   2.0  ==> ... format
               27.0  85.4        excl::process-format-string
                2.7   8.5        get-output-stream-string
-----------------------------------------------------
               27.0 100.0        format
  1.9  83.3    27.0   2.3  ==> excl::process-format-string
               25.7  95.3        excl::format-engine
-----------------------------------------------------
               25.7  99.8        excl::process-format-string
  1.0  79.5    25.8   1.3  ==> ... excl::format-engine
               24.9  96.7        princ
-----------------------------------------------------
               24.9  99.8r       excl::format-engine
                6.3  25.1r       (method render-uri (uri t))
  1.0  77.0    25.0   1.4  ==> ... princ
               24.1  96.6r       excl::basic-write
-----------------------------------------------------
               24.1  99.9r       princ
  1.5  74.5    24.1   2.0  ==> ... excl::basic-write
               17.5  72.6r       (method render-uri (uri t))
                5.3  22.0r       (method print-object (t t))
                4.8  20.0r       (method render-uri (urn t))
                0.6   2.6r       (:discriminator
                                  (:caching (class t) nil))
-----------------------------------------------------
               17.5  99.8        excl::basic-write
  3.0  54.3    17.6   5.5  ==> ... (method render-uri (uri t))
                8.2  46.9        util.string:string+
                6.3  35.7        princ
                0.6   3.5        net.uri::render-parsed-path
                0.4   2.2        ...
-----------------------------------------------------
                8.2  76.8        ... (method render-uri (uri t))
                2.4  22.7        (method render-uri (urn t))
  1.1  33.1    10.7   3.3  ==> ... util.string:string+
                5.8  53.7        util.string::%string+
                4.4  40.6        subseq
                0.2   2.3        stringp
-----------------------------------------------------
                4.4  72.1        excl::write-string-nokey-se
                1.6  26.9        excl::write-string-nokey
 19.0  19.0     6.1 100.0  ==> excl::string-output-write-chars
-----------------------------------------------------
                5.8  99.7        util.string:string+
 17.7  17.8     5.8  99.1  ==> util.string::%string+
-----------------------------------------------------
                5.3  99.3        excl::basic-write
  0.3  16.5     5.4   2.1  ==> (method print-object (t t))
                4.9  91.6        (flet
                                  (method print-object (t t))
                                  excl::print-object-1)
                0.2   3.4        excl::maybe-print-fast
-----------------------------------------------------
                4.9  97.0        (method print-object (t t))
                0.2   3.0        excl::basic-write
  1.0  15.6     5.1   6.3  ==> (flet
                                (method print-object (t t))
                                excl::print-object-1)
                4.7  93.7        excl::maybe-print-fast-1
-----------------------------------------------------
                4.8  99.2        excl::basic-write
  0.6  15.0     4.9   4.3  ==> ... (method render-uri (urn t))
                2.4  50.1        util.string:string+
                1.8  36.8        excl::write-string-nokey
-----------------------------------------------------
                4.7  98.3        (flet
                                  (method print-object (t t))
                                  excl::print-object-1)
  0.8  14.9     4.8   5.6  ==> excl::maybe-print-fast-1
                4.5  93.6        excl::write-string-nokey-se
-----------------------------------------------------
                4.4  96.5        util.string:string+
                0.1   3.1        (method render-uri (uri t))
 13.0  14.0     4.5  92.9  ==> subseq
                0.2   3.8        "(after-libnss_files.so.2-lib)"
                0.1   3.1        "new_simple_string"
-----------------------------------------------------
                4.5 100.0        excl::maybe-print-fast-1
  0.2  13.9     4.5   1.8  ==> excl::write-string-nokey-se
                4.4  98.2        excl::string-output-write-chars
-----------------------------------------------------
                2.7  98.2        format
  7.4   8.4     2.7  88.2  ==> get-output-stream-string
                0.2   7.4        "(after-libnss_files.so.2-lib)"
                0.1   4.4        "new_simple_string"
-----------------------------------------------------
                1.8  98.4        (method render-uri (urn t))
  0.5   5.6     1.8   9.3  ==> excl::write-string-nokey
                1.6  90.7        excl::string-output-write-chars
-----------------------------------------------------
                0.3  26.5        princ
                0.3  26.5        excl::process-format-string
                0.2  15.3        format
                0.1  14.3        (method render-uri (uri t))
                0.1   9.2        ... excl::format-engine
                0.1   6.1        (method render-uri (urn t))
                0.0   2.0        excl::basic-write
  2.5   3.0     1.0  82.7  ==> "bind_one_spec"
                0.2  17.3        "gc_setf_protect_1"
-----------------------------------------------------
                0.6  82.7        excl::basic-write
                0.1  17.3        princ
  2.1   2.3     0.7  92.0  ==> ... (:discriminator
                                    (:caching (class t) nil))
                0.1   6.7        excl::internal-wrapper-of
-----------------------------------------------------
                0.6  86.1        (method render-uri (uri t))
                0.1  13.9        excl::basic-write
  1.3   2.2     0.7  58.3  ==> net.uri::render-parsed-path
                0.2  22.2        "list_nreverse"
                0.1  18.1        "gc_setf_protect"
-----------------------------------------------------
                0.2  36.1        ... format
                0.2  26.2        ... (method render-uri (uri t))
                0.1  21.3        net.uri::render-parsed-path
                0.1   8.2        ... (method render-uri (urn t))
                0.1   8.2        uri-perf-format
  1.9   1.9     0.6 100.0  ==> "gc_setf_protect"
-----------------------------------------------------
                0.5  92.9        format
                0.0   7.1        uri-perf-format
  1.7   1.7     0.6 100.0  ==> (:internal excl::defresource-1 1)
-----------------------------------------------------
                0.3  69.4        princ
                0.1  28.6        excl::process-format-string
                0.0   2.0        ... excl::format-engine
  1.4   1.5     0.5  89.8  ==> "unbind_count"
                0.1  10.2        "gc_setf_protect_1"
-----------------------------------------------------
                0.3  87.5        ... (method render-uri (uri t))
                0.1  12.5        ... (method render-uri (urn t))
  1.2   1.2     0.4 100.0  ==> "st_restify"
-----------------------------------------------------
                0.2  54.1        get-output-stream-string
                0.2  45.9        subseq
  1.1   1.1     0.4 100.0  ==> "(after-libnss_files.so.2-lib)"
-----------------------------------------------------
                0.2  50.0        "bind_one_spec"
                0.1  14.7        "unbind_count"
                0.0  11.8        excl::format-engine
                0.0  11.8        format
                0.0   8.8        princ
                0.0   2.9        ... excl::basic-write
  1.0   1.0     0.3 100.0  ==> "gc_setf_protect_1"
-----------------------------------------------------


;;;;;;; :time #<Function run-bm4>


;; Testing #<Function uri-perf-slot-access>..

; cpu time (non-gc) 4.877259 sec user, 0.000000 sec system
; cpu time (gc)     0.000000 sec user, 0.000000 sec system
; cpu time (total)  4.877259 sec user, 0.000000 sec system
; real time  4.877093 sec (100.0%)
; space allocation:
;  0 cons cells, 0 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)

; cpu time (non-gc) 4.876258 sec user, 0.000000 sec system
; cpu time (gc)     0.000000 sec user, 0.000000 sec system
; cpu time (total)  4.876258 sec user, 0.000000 sec system
; real time  4.876823 sec (99.99%)
; space allocation:
;  0 cons cells, 0 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)

; cpu time (non-gc) 4.876259 sec user, 0.000000 sec system
; cpu time (gc)     0.000000 sec user, 0.000000 sec system
; cpu time (total)  4.876259 sec user, 0.000000 sec system
; real time  4.876908 sec (99.99%)
; space allocation:
;  0 cons cells, 0 other bytes, 0 static bytes
; Page Faults: major: 0 (gc: 0), minor: 0 (gc: 0)
Sampling stopped after 1463 samples taken for the time profiler.

Sample represents 14.6 seconds of user+system CPU time (out of a total of 14.7).

Times below 1.0% will be suppressed.

  %     %   self total         self   total  Function                                  
 Time  Cum. secs  secs calls ms/call ms/call   name                                    
100.0 100.0 14.6  14.6                       uri-perf-slot-access
Time profile of sampled pc values by function, children, and parents.

Total times below 1.0% will be suppressed.
Parent and child times less 2.0% of the node will be suppressed.
Sampling stopped after 1463 samples taken for the time profiler.

Sample represents 14.6 seconds of user+system CPU time (out of a total of 14.7).

  %     %                       Parent
 self total   total local  Function
 Time  Time    secs   %         Child

  0.0 100.0    14.6   0.0  ==> ... "start"
               14.6 100.0        ... "start_reborn_lisp"
-----------------------------------------------------
               14.6 100.0        ... "start"
  0.0 100.0    14.6   0.0  ==> "start_reborn_lisp"
               14.6 100.0        "first_lisp_thread"
-----------------------------------------------------
               14.6 100.0        "start_reborn_lisp"
  0.0 100.0    14.6   0.0  ==> "first_lisp_thread"
               14.6 100.0        excl::lisp-thread-start
-----------------------------------------------------
               14.6 100.0        "first_lisp_thread"
  0.0 100.0    14.6   0.0  ==> excl::lisp-thread-start
               14.6 100.0        excl::run-initial-thread
-----------------------------------------------------
               14.6 100.0        excl::lisp-thread-start
  0.0 100.0    14.6   0.0  ==> ... excl::run-initial-thread
               14.6 100.0        ... excl::thread-reset-catcher
-----------------------------------------------------
               14.6 100.0        ... excl::run-initial-thread
  0.0 100.0    14.6   0.0  ==> excl::thread-reset-catcher
               14.6 100.0        excl::thread-bind-and-call
-----------------------------------------------------
               14.6 100.0        excl::thread-reset-catcher
  0.0 100.0    14.6   0.0  ==> ... excl::thread-bind-and-call
               14.6 100.0        ... excl::process-script
-----------------------------------------------------
               14.6 100.0        ... excl::thread-bind-and-call
  0.0 100.0    14.6   0.0  ==> excl::process-script
               14.6 100.0        eval
-----------------------------------------------------
               14.6 100.0        excl::process-script
  0.0 100.0    14.6   0.0  ==> eval
               14.6 100.0        profile
-----------------------------------------------------
               14.6 100.0        eval
  0.0 100.0    14.6   0.0  ==> profile
               14.6 100.0        profile-bm4
-----------------------------------------------------
               14.6 100.0        profile
  0.0 100.0    14.6   0.0  ==> profile-bm4
               14.6 100.0        prof::prof-a-funcall
-----------------------------------------------------
               14.6 100.0        profile-bm4
  0.0 100.0    14.6   0.0  ==> prof::prof-a-funcall
               14.6 100.0        (:internal profile-bm4 0)
-----------------------------------------------------
               14.6 100.0        prof::prof-a-funcall
  0.0 100.0    14.6   0.0  ==> (:internal profile-bm4 0)
               14.6 100.0        run-bm4
-----------------------------------------------------
               14.6 100.0        (:internal profile-bm4 0)
  0.0 100.0    14.6   0.0  ==> run-bm4
               14.6 100.0        do-bm
-----------------------------------------------------
               14.6 100.0        run-bm4
  0.0 100.0    14.6   0.0  ==> do-bm
               14.6 100.0        excl::time-a-funcall
-----------------------------------------------------
               14.6 100.0        do-bm
  0.0 100.0    14.6   0.0  ==> ... excl::time-a-funcall
               14.6 100.0        ... (:internal do-bm 2)
-----------------------------------------------------
               14.6 100.0        ... excl::time-a-funcall
  0.0 100.0    14.6   0.0  ==> (:internal do-bm 2)
               14.6 100.0        uri-perf-slot-access
-----------------------------------------------------
               14.6 100.0        (:internal do-bm 2)
100.0 100.0    14.6 100.0  ==> uri-perf-slot-access
-----------------------------------------------------
; Exiting
make[1]: Leaving directory `/acl/acl10.1/src/uri'