X-Git-Url: http://repo.macrolet.net/gitweb/?a=blobdiff_plain;f=src%2Fcode%2Ftime.lisp;h=13897422f9600d7a76b53f10a6de963dae2cc554;hb=82cd148d729c241e79c8df04b700beec1b7c55de;hp=180b6b6bc1b414d107f6e89fb3aafd694539cac4;hpb=95a014cffbb243fdc59adbdd6ab7f6dbb0058ca4;p=sbcl.git diff --git a/src/code/time.lisp b/src/code/time.lisp index 180b6b6..1389742 100644 --- a/src/code/time.lisp +++ b/src/code/time.lisp @@ -11,62 +11,21 @@ (in-package "SB!IMPL") -(defconstant sb!xc:internal-time-units-per-second 1000 - #!+sb-doc - "The number of internal time units that fit into a second. See - GET-INTERNAL-REAL-TIME and GET-INTERNAL-RUN-TIME.") - -(defconstant micro-seconds-per-internal-time-unit - (/ 1000000 sb!xc:internal-time-units-per-second)) - -;;; The base number of seconds for our internal "epoch". We initialize -;;; this to the time of the first call to GET-INTERNAL-REAL-TIME, and -;;; then subtract this out of the result. -(defvar *internal-real-time-base-seconds* nil) -(declaim (type (or (unsigned-byte 32) null) *internal-real-time-base-seconds*)) +(defun time-reinit () + (reinit-internal-real-time)) -(defun get-internal-real-time () - #!+sb-doc - "Return the real time in the internal time format. (See - INTERNAL-TIME-UNITS-PER-SECOND.) This is useful for finding elapsed time." - (multiple-value-bind (ignore seconds useconds) (sb!unix:unix-gettimeofday) - (declare (ignore ignore) (type (unsigned-byte 32) seconds useconds)) - (let ((base *internal-real-time-base-seconds*) - (uint (truncate useconds - micro-seconds-per-internal-time-unit))) - (declare (type (unsigned-byte 32) uint)) - (cond (base - (truly-the (unsigned-byte 32) - (+ (the (unsigned-byte 32) - (* (the (unsigned-byte 32) (- seconds base)) - sb!xc:internal-time-units-per-second)) - uint))) - (t - (setq *internal-real-time-base-seconds* seconds) - uint))))) +;;; Implemented in unix.lisp and win32.lisp. +#!+sb-doc +(setf (fdocumentation 'get-internal-real-time 'function) + "Return the real time (\"wallclock time\") since startup in the internal +time format. (See INTERNAL-TIME-UNITS-PER-SECOND.)") (defun get-internal-run-time () #!+sb-doc - "Return the run time in the internal time format. (See - INTERNAL-TIME-UNITS-PER-SECOND.) This is useful for finding CPU usage." - (declare (values (unsigned-byte 32))) - (multiple-value-bind (ignore utime-sec utime-usec stime-sec stime-usec) - (sb!unix:unix-fast-getrusage sb!unix:rusage_self) - (declare (ignore ignore) - (type (unsigned-byte 31) utime-sec stime-sec) - ;; (Classic CMU CL had these (MOD 1000000) instead, but - ;; at least in Linux 2.2.12, the type doesn't seem to be - ;; documented anywhere and the observed behavior is to - ;; sometimes return 1000000 exactly.) - (type (integer 0 1000000) utime-usec stime-usec)) - (let ((result (+ (the (unsigned-byte 32) - (* (the (unsigned-byte 32) (+ utime-sec stime-sec)) - sb!xc:internal-time-units-per-second)) - (floor (+ utime-usec - stime-usec - (floor micro-seconds-per-internal-time-unit 2)) - micro-seconds-per-internal-time-unit)))) - result))) + "Return the run time used by the process in the internal time format. (See +INTERNAL-TIME-UNITS-PER-SECOND.) This is useful for finding CPU usage. +Includes both \"system\" and \"user\" time." + (system-internal-run-time)) ;;;; Encode and decode universal times. @@ -87,11 +46,11 @@ ;;; number of seconds since 1970-01-01 ;;; I'm obliged to Erik Naggum's "Long, Painful History of Time" paper -;;; for the choice of epoch -;;; here. By starting the year in March, we avoid having to test the month -;;; whenever deciding whether to account for a leap day. 2000 is especially -;;; special, because it's disvisible by 400, hence the start of a 400 year -;;; leap year cycle +;;; for the choice of epoch here. +;;; By starting the year in March, we avoid having to test the month +;;; whenever deciding whether to account for a leap day. 2000 is +;;; especially special, because it's divisible by 400, hence the start +;;; of a 400 year leap year cycle ;;; If a universal-time is after time_t runs out, we find its offset ;;; from 1st March of whichever year it falls in, then add that to @@ -134,11 +93,9 @@ (defun get-universal-time () #!+sb-doc - "Return a single integer for the current time of - day in universal time format." - (multiple-value-bind (res secs) (sb!unix:unix-gettimeofday) - (declare (ignore res)) - (+ secs unix-to-universal-time))) + "Return a single integer for the current time of day in universal time +format." + (+ (get-time-of-day) unix-to-universal-time)) (defun get-decoded-time () #!+sb-doc @@ -300,24 +257,180 @@ (defvar *gc-run-time* 0 #!+sb-doc - "the total CPU time spent doing garbage collection (as reported by - GET-INTERNAL-RUN-TIME)") + "Total CPU time spent doing garbage collection (as reported by +GET-INTERNAL-RUN-TIME.) Initialized to zero on startup. It is safe to bind +this to zero in order to measure GC time inside a certain section of code, but +doing so may interfere with results reported by eg. TIME.") (declaim (type index *gc-run-time*)) +(defun print-time (&key real-time-ms user-run-time-us system-run-time-us + gc-run-time-ms processor-cycles eval-calls + lambdas-converted page-faults bytes-consed + aborted) + (let ((total-run-time-us (+ user-run-time-us system-run-time-us))) + (format *trace-output* + "~&Evaluation took:~%~ + ~@< ~@;~/sb-impl::format-milliseconds/ of real time~%~ + ~/sb-impl::format-microseconds/ of total run time ~ + (~@/sb-impl::format-microseconds/ user, ~@/sb-impl::format-microseconds/ system)~%~ + ~[[ Run times consist of ~/sb-impl::format-milliseconds/ GC time, ~ + and ~/sb-impl::format-milliseconds/ non-GC time. ]~%~;~2*~]~ + ~,2F% CPU~%~ + ~@[~:D form~:P interpreted~%~]~ + ~@[~:D lambda~:P converted~%~]~ + ~@[~:D processor cycles~%~]~ + ~@[~:D page fault~:P~%~]~ + ~:D bytes consed~%~ + ~@[~%before it was aborted by a non-local transfer of control.~%~]~:>~%" + real-time-ms + total-run-time-us + user-run-time-us + system-run-time-us + (if (zerop gc-run-time-ms) 1 0) + gc-run-time-ms + ;; Round up so we don't mislead by saying 0.0 seconds of non-GC time... + (- (ceiling total-run-time-us 1000) gc-run-time-ms) + (if (zerop real-time-ms) + 100.0 + (float (* 100 (/ (round total-run-time-us 1000) real-time-ms)))) + eval-calls + lambdas-converted + processor-cycles + page-faults + bytes-consed + aborted))) + (defmacro time (form) #!+sb-doc - "Execute FORM and print timing information on *TRACE-OUTPUT*." - `(%time (lambda () ,form))) + "Execute FORM and print timing information on *TRACE-OUTPUT*. + +On some hardware platforms estimated processor cycle counts are +included in this output; this number is slightly inflated, since it +includes the pipeline involved in reading the cycle counter -- +executing \(TIME NIL) a few times will give you an idea of the +overhead, and its variance. The cycle counters are also per processor, +not per thread: if multiple threads are running on the same processor, +the reported counts will include cycles taken up by all threads +running on the processor where TIME was executed. Furthermore, if the +operating system migrates the thread to another processor between +reads of the cycle counter, the results will be completely bogus. +Finally, the counter is cycle counter, incremented by the hardware +even when the process is halted -- which is to say that cycles pass +normally during operations like SLEEP." + `(call-with-timing #'print-time (lambda () ,form))) ;;; Return all the data that we want TIME to report. (defun time-get-sys-info () (multiple-value-bind (user sys faults) (sb!sys:get-system-info) (values user sys faults (get-bytes-consed)))) +(defun elapsed-cycles (h0 l0 h1 l1) + (declare (ignorable h0 l0 h1 l1)) + #!+cycle-counter + (+ (ash (- h1 h0) 32) + (- l1 l0)) + #!-cycle-counter + nil) +(declaim (inline read-cycle-counter)) +(defun read-cycle-counter () + #!+cycle-counter + (sb!vm::%read-cycle-counter) + #!-cycle-counter + (values 0 0)) + +;;; This is so that we don't have to worry about the vagaries of +;;; floating point printing, or about conversions to floats dropping +;;; or introducing decimals, which are liable to imply wrong precision. +(defun format-microseconds (stream usec &optional colonp atp) + (declare (ignore colonp)) + (%format-decimal stream usec 6) + (unless atp + (write-string " seconds" stream))) + +(defun format-milliseconds (stream usec &optional colonp atp) + (declare (ignore colonp)) + (%format-decimal stream usec 3) + (unless atp + (write-string " seconds" stream))) + +(defun %format-decimal (stream number power) + (declare (stream stream) + (integer number power)) + (when (minusp number) + (write-char #\- stream) + (setf number (- number))) + (let ((scale (expt 10 power))) + (labels ((%fraction (fraction) + (if (zerop fraction) + (%zeroes) + (let ((scaled (* 10 fraction))) + (loop while (< scaled scale) + do (write-char #\0 stream) + (setf scaled (* scaled 10))))) + (format stream "~D" fraction)) + (%zeroes () + (let ((scaled (/ scale 10))) + (write-char #\0 stream) + (loop while (> scaled 1) + do (write-char #\0 stream) + (setf scaled (/ scaled 10)))))) + (cond ((zerop number) + (write-string "0." stream) + (%zeroes)) + ((< number scale) + (write-string "0." stream) + (%fraction number)) + ((= number scale) + (write-string "1." stream) + (%zeroes)) + ((> number scale) + (multiple-value-bind (whole fraction) (floor number scale) + (format stream "~D." whole) + (%fraction fraction)))))) + nil) + ;;; The guts of the TIME macro. Compute overheads, run the (compiled) ;;; function, report the times. -(defun %time (fun) - (declare (type function fun)) +(defun call-with-timing (timer function &rest arguments) + #!+sb-doc + "Calls FUNCTION with ARGUMENTS, and gathers timing information about it. +Then calls TIMER with keyword arguments describing the information collected. +Calls TIMER even if FUNCTION performs a non-local transfer of control. Finally +returns values returned by FUNCTION. + + :USER-RUN-TIME-US + User run time in microseconds. + + :SYSTEM-RUN-TIME-US + System run time in microseconds. + + :REAL-TIME-MS + Real time in milliseconds. + + :GC-RUN-TIME-MS + GC run time in milliseconds (included in user and system run time.) + + :PROCESSOR-CYCLES + Approximate number of processor cycles used. (Omitted if not supported on + the platform -- currently available on x86 and x86-64 only.) + + :EVAL-CALLS + Number of calls to EVAL. (Omitted if zero.) + + :LAMBDAS-CONVERTED + Number of lambdas converted. (Omitted if zero.) + + :PAGE-FAULTS + Number of page faults. (Omitted if zero.) + + :BYTES-CONSED + Approximate number of bytes consed. + + :ABORTED + True if FUNCTION caused a non-local transfer of control. (Omitted if + NIL.) + +EXPERIMENTAL: Interface subject to change." (let (old-run-utime new-run-utime old-run-stime @@ -332,7 +445,9 @@ page-faults-overhead old-bytes-consed new-bytes-consed - cons-overhead) + cons-overhead + (fun (if (functionp function) function (fdefinition function)))) + (declare (function fun)) ;; Calculate the overhead... (multiple-value-setq (old-run-utime old-run-stime old-page-faults old-bytes-consed) @@ -357,30 +472,41 @@ (old-run-utime old-run-stime old-page-faults old-bytes-consed) (time-get-sys-info)) (setq old-real-time (get-internal-real-time)) - (let ((start-gc-run-time *gc-run-time*)) - (multiple-value-prog1 - ;; Execute the form and return its values. - (funcall fun) - (multiple-value-setq - (new-run-utime new-run-stime new-page-faults new-bytes-consed) - (time-get-sys-info)) - (setq new-real-time (- (get-internal-real-time) real-time-overhead)) - (let ((gc-run-time (max (- *gc-run-time* start-gc-run-time) 0))) - (format *trace-output* - "~&Evaluation took:~% ~ - ~S second~:P of real time~% ~ - ~S second~:P of user run time~% ~ - ~S second~:P of system run time~% ~ -~@[ [Run times include ~S second~:P GC run time.]~% ~]~ - ~S page fault~:P and~% ~ - ~:D bytes consed.~%" - (max (/ (- new-real-time old-real-time) - (float sb!xc:internal-time-units-per-second)) - 0.0) - (max (/ (- new-run-utime old-run-utime) 1000000.0) 0.0) - (max (/ (- new-run-stime old-run-stime) 1000000.0) 0.0) - (unless (zerop gc-run-time) - (/ (float gc-run-time) - (float sb!xc:internal-time-units-per-second))) - (max (- new-page-faults old-page-faults) 0) - (max (- new-bytes-consed old-bytes-consed) 0))))))) + (let ((start-gc-internal-run-time *gc-run-time*) + (*eval-calls* 0) + (sb!c::*lambda-conversions* 0) + (aborted t)) + (declare (special *eval-calls* sb!c::*lambda-conversions*)) + (multiple-value-bind (h0 l0) (read-cycle-counter) + (unwind-protect + (multiple-value-prog1 (apply fun arguments) + (setf aborted nil)) + (multiple-value-bind (h1 l1) (read-cycle-counter) + (let ((stop-gc-internal-run-time *gc-run-time*)) + (multiple-value-setq + (new-run-utime new-run-stime new-page-faults new-bytes-consed) + (time-get-sys-info)) + (setq new-real-time (- (get-internal-real-time) real-time-overhead)) + (let* ((gc-internal-run-time (max (- stop-gc-internal-run-time start-gc-internal-run-time) 0)) + (real-time (max (- new-real-time old-real-time) 0)) + (user-run-time (max (- new-run-utime old-run-utime) 0)) + (system-run-time (max (- new-run-stime old-run-stime) 0)) + (cycles (elapsed-cycles h0 l0 h1 l1)) + (page-faults (max (- new-page-faults old-page-faults) 0))) + (let (plist) + (flet ((note (name value &optional test) + (unless (and test (funcall test value)) + (setf plist (list* name value plist))))) + (note :aborted aborted #'not) + (note :bytes-consed (max (- new-bytes-consed old-bytes-consed) 0)) + (note :page-faults page-faults #'zerop) + ;; cycle counting isn't supported everywhere. + (when cycles + (note :processor-cycles cycles #'zerop) + (note :lambdas-converted sb!c::*lambda-conversions* #'zerop)) + (note :eval-calls *eval-calls* #'zerop) + (note :gc-run-time-ms gc-internal-run-time) + (note :system-run-time-us system-run-time) + (note :user-run-time-us user-run-time) + (note :real-time-ms real-time)) + (apply timer plist))))))))))