[prev in list] [next in list] [prev in thread] [next in thread]
List: sbcl-devel
Subject: Re: [Sbcl-devel] [Sbcl-commits] master: Bring in *GC-REAL-TIME* variable from Hayley Patton's GC
From: Douglas Katzman via Sbcl-devel <sbcl-devel () lists ! sourceforge ! net>
Date: 2023-07-20 11:58:29
Message-ID: CAOrNaswvR0RhYF1mL8LjQmMZR+SVhDvZTwnZB3Mq+gYZV5DutA () mail ! gmail ! com
[Download RAW message or body]
[Attachment #2 (multipart/alternative)]
seems a shame to lose this code so I'm going to try to conditionalize it
out using as few #+/- as I can.
If nothing else, this bears out that it was a good idea to start on tiny
subsets of the patch rather than cause random bits of damage here and there.
On Thu, Jul 20, 2023 at 5:46 AM Stas Boukarev <stassats@gmail.com> wrote:
> This breaks 32-bit and foreign thread callbacks.
> If a gc is run in enter-foreign-callback before *current-thread* is set
> up, get-internal-real-time can't work.
>
> See fcb-threads.impure.lisp
>
> On Thu, Jul 20, 2023 at 5:39 AM snuglas via Sbcl-commits <
> sbcl-commits@lists.sourceforge.net> wrote:
>
>> The branch "master" has been updated in SBCL:
>> via 480237bc2544e306e841c3ee12a70d7b8d766350 (commit)
>> from 1835d7bd31877a85b8c3466e358dec12098d43ea (commit)
>>
>> - Log -----------------------------------------------------------------
>> commit 480237bc2544e306e841c3ee12a70d7b8d766350
>> Author: Douglas Katzman <dougk@google.com>
>> Date: Wed Jul 19 22:37:45 2023 -0400
>>
>> Bring in *GC-REAL-TIME* variable from Hayley Patton's GC
>>
>> Not very interesting without multi-core parallelism,
>> but innocuous and stands on its own.
>> ---
>> src/code/gc.lisp | 10 +++++++---
>> src/code/time.lisp | 22 +++++++++++++++++++---
>> src/cold/exports.lisp | 1 +
>> tests/run-tests.lisp | 1 +
>> 4 files changed, 28 insertions(+), 6 deletions(-)
>>
>> diff --git a/src/code/gc.lisp b/src/code/gc.lisp
>> index 5f0a6b217..47186073f 100644
>> --- a/src/code/gc.lisp
>> +++ b/src/code/gc.lisp
>> @@ -56,7 +56,8 @@
>> ;; and we need a function in C to do that.
>> (gc)
>> (setf *n-bytes-freed-or-purified* 0
>> - *gc-run-time* 0))
>> + *gc-run-time* 0
>> + *gc-real-time* 0))
>>
>> (declaim (ftype (sfunction () unsigned-byte) get-bytes-consed))
>> (defun get-bytes-consed ()
>> @@ -137,10 +138,13 @@ run in any thread.")
>> ;; awkwardly long piece of code to nest so deeply.
>> (let ((old-usage (dynamic-usage))
>> (new-usage 0)
>> - (start-time (get-internal-run-time)))
>> + (start-time (get-internal-run-time))
>> + (start-real-time (get-internal-real-time)))
>> (collect-garbage gen)
>> (setf *gc-epoch* (cons 0 0))
>> - (let ((run-time (- (get-internal-run-time)
>> start-time)))
>> + (let ((run-time (- (get-internal-run-time)
>> start-time))
>> + (real-time (- (get-internal-real-time)
>> start-real-time)))
>> + (incf *gc-real-time* real-time)
>> ;; KLUDGE: Sometimes we see the second getrusage()
>> call
>> ;; return a smaller value than the first, which can
>> ;; lead to *GC-RUN-TIME* to going negative, which
>> in
>> diff --git a/src/code/time.lisp b/src/code/time.lisp
>> index eacabded3..706cc3586 100644
>> --- a/src/code/time.lisp
>> +++ b/src/code/time.lisp
>> @@ -242,15 +242,18 @@ format."
>>
>> ;;;; TIME
>>
>> +(defvar *gc-real-time* 0
>> + "Total real time spent doing garbage collection (as reported by
>> +GET-INTERNAL-REAL-TIME.) Initialized to zero on startup.")
>> (defvar *gc-run-time* 0
>> "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*))
>> +(declaim (type index *gc-run-time* *gc-real-time*))
>>
>> (defun print-time (&key real-time-ms user-run-time-us system-run-time-us
>> - gc-run-time-ms processor-cycles eval-calls
>> + gc-run-time-ms gc-real-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))
>> @@ -263,6 +266,8 @@ doing so may interfere with results reported by eg.
>> TIME.")
>> ~@< ~@;~/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)~%~
>> + ~[[ Real times consist of
>> ~/sb-impl::format-milliseconds/ GC time, ~
>> + and
>> ~/sb-impl::format-milliseconds/ non-GC time. ]~%~;~2*~]~
>> ~[[ Run times consist of
>> ~/sb-impl::format-milliseconds/ GC time, ~
>> and
>> ~/sb-impl::format-milliseconds/ non-GC time. ]~%~;~2*~]~
>> ~,2F% CPU~%~
>> @@ -276,6 +281,9 @@ doing so may interfere with results reported by eg.
>> TIME.")
>> total-run-time-us
>> user-run-time-us
>> system-run-time-us
>> + (if (zerop gc-real-time-ms) 1 0)
>> + gc-real-time-ms
>> + (- real-time-ms gc-real-time-ms)
>> (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...
>> @@ -398,6 +406,9 @@ returns values returned by FUNCTION.
>> :GC-RUN-TIME-MS
>> GC run time in milliseconds (included in user and system run time.)
>>
>> + :GC-REAL-TIME-MS
>> + GC real time in milliseconds.
>> +
>> :PROCESSOR-CYCLES
>> Approximate number of processor cycles used. (Omitted if not
>> supported on
>> the platform -- currently available on x86 and x86-64 only.)
>> @@ -454,6 +465,7 @@ EXPERIMENTAL: Interface subject to change."
>> (time-get-sys-info))
>> (setq old-real-time (get-internal-real-time))
>> (let ((start-gc-internal-run-time *gc-run-time*)
>> + (start-gc-internal-real-time *gc-real-time*)
>> (*eval-calls* 0)
>> (sb-c::*lambda-conversions* 0)
>> (aborted t))
>> @@ -462,12 +474,14 @@ EXPERIMENTAL: Interface subject to change."
>> (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*))
>> + (let ((stop-gc-internal-run-time *gc-run-time*)
>> + (stop-gc-internal-real-time *gc-real-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))
>> + (gc-internal-real-time (max (-
>> stop-gc-internal-real-time start-gc-internal-real-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))
>> @@ -487,6 +501,8 @@ EXPERIMENTAL: Interface subject to change."
>> (note :eval-calls *eval-calls* #'zerop)
>> (note :gc-run-time-ms (floor gc-internal-run-time
>> (/
>> internal-time-units-per-second 1000)))
>> + (note :gc-real-time-ms (floor gc-internal-real-time
>> + (/
>> internal-time-units-per-second 1000)))
>> (note :system-run-time-us system-run-time)
>> (note :user-run-time-us user-run-time)
>> (note :real-time-ms (floor real-time
>> diff --git a/src/cold/exports.lisp b/src/cold/exports.lisp
>> index d2d93a2f1..72219eefb 100644
>> --- a/src/cold/exports.lisp
>> +++ b/src/cold/exports.lisp
>> @@ -791,6 +791,7 @@ like *STACK-TOP-HINT* and unsupported stuff like
>> *TRACED-FUN-LIST*.")
>> "BYTES-CONSED-BETWEEN-GCS"
>> "GC" "GET-BYTES-CONSED"
>> "*GC-RUN-TIME*"
>> + "*GC-REAL-TIME*"
>> "PURIFY"
>> "DYNAMIC-SPACE-SIZE"
>> ;; Gencgc only, but symbols exist for manual building
>> diff --git a/tests/run-tests.lisp b/tests/run-tests.lisp
>> index e49b6bf34..aa39a9e5e 100644
>> --- a/tests/run-tests.lisp
>> +++ b/tests/run-tests.lisp
>> @@ -214,6 +214,7 @@
>> ,(maybe "SB-KERNEL" "*EVAL-CALLS*")
>> sb-kernel::*type-cache-nonce*
>> sb-ext:*gc-run-time*
>> + sb-ext:*gc-real-time*
>> sb-kernel::*gc-epoch*
>> sb-int:*n-bytes-freed-or-purified*
>> ,(maybe "SB-VM" "*BINDING-STACK-POINTER*")
>>
>> -----------------------------------------------------------------------
>>
>>
>> hooks/post-receive
>> --
>> SBCL
>>
>>
>> _______________________________________________
>> Sbcl-commits mailing list
>> Sbcl-commits@lists.sourceforge.net
>> https://lists.sourceforge.net/lists/listinfo/sbcl-commits
>>
>
[Attachment #5 (text/html)]
<div dir="ltr"><div dir="ltr">seems a shame to lose this code so I'm going to try \
to conditionalize it out using as few #+/- as I can.<div>If nothing else, this bears \
out that it was a good idea to start on tiny subsets of the patch rather than cause \
random bits of damage here and there.</div></div><br><div class="gmail_quote"><div \
dir="ltr" class="gmail_attr">On Thu, Jul 20, 2023 at 5:46 AM Stas Boukarev <<a \
href="mailto:stassats@gmail.com">stassats@gmail.com</a>> \
wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px \
0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">This \
breaks 32-bit and foreign thread callbacks.<div>If a gc is run in \
enter-foreign-callback before *current-thread* is set up, get-internal-real-time \
can't work.</div><div><br>See fcb-threads.impure.lisp</div></div><br><div \
class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, Jul 20, 2023 at \
5:39 AM snuglas via Sbcl-commits <<a \
href="mailto:sbcl-commits@lists.sourceforge.net" \
target="_blank">sbcl-commits@lists.sourceforge.net</a>> \
wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px \
0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">The branch \
"master" has been updated in SBCL:<br> via \
480237bc2544e306e841c3ee12a70d7b8d766350 (commit)<br> from \
1835d7bd31877a85b8c3466e358dec12098d43ea (commit)<br> <br>
- Log -----------------------------------------------------------------<br>
commit 480237bc2544e306e841c3ee12a70d7b8d766350<br>
Author: Douglas Katzman <<a href="mailto:dougk@google.com" \
target="_blank">dougk@google.com</a>><br>
Date: Wed Jul 19 22:37:45 2023 -0400<br>
<br>
Bring in *GC-REAL-TIME* variable from Hayley Patton's GC<br>
<br>
Not very interesting without multi-core parallelism,<br>
but innocuous and stands on its own.<br>
---<br>
src/code/gc.lisp | 10 +++++++---<br>
src/code/time.lisp | 22 +++++++++++++++++++---<br>
src/cold/exports.lisp | 1 +<br>
tests/run-tests.lisp | 1 +<br>
4 files changed, 28 insertions(+), 6 deletions(-)<br>
<br>
diff --git a/src/code/gc.lisp b/src/code/gc.lisp<br>
index 5f0a6b217..47186073f 100644<br>
--- a/src/code/gc.lisp<br>
+++ b/src/code/gc.lisp<br>
@@ -56,7 +56,8 @@<br>
;; and we need a function in C to do that.<br>
(gc)<br>
(setf *n-bytes-freed-or-purified* 0<br>
- *gc-run-time* 0))<br>
+ *gc-run-time* 0<br>
+ *gc-real-time* 0))<br>
<br>
(declaim (ftype (sfunction () unsigned-byte) get-bytes-consed))<br>
(defun get-bytes-consed ()<br>
@@ -137,10 +138,13 @@ run in any thread.")<br>
;; awkwardly long piece of code to nest so deeply.<br>
(let ((old-usage (dynamic-usage))<br>
(new-usage 0)<br>
- (start-time (get-internal-run-time)))<br>
+ (start-time (get-internal-run-time))<br>
+ (start-real-time (get-internal-real-time)))<br>
(collect-garbage gen)<br>
(setf *gc-epoch* (cons 0 0))<br>
- (let ((run-time (- (get-internal-run-time) \
start-time)))<br> + (let ((run-time (- \
(get-internal-run-time) start-time))<br> + \
(real-time (- (get-internal-real-time) start-real-time)))<br> + \
(incf *gc-real-time* real-time)<br>
;; KLUDGE: Sometimes we see the second getrusage() \
call<br>
;; return a smaller value than the first, which \
can<br>
;; lead to *GC-RUN-TIME* to going negative, which \
in<br>
diff --git a/src/code/time.lisp b/src/code/time.lisp<br>
index eacabded3..706cc3586 100644<br>
--- a/src/code/time.lisp<br>
+++ b/src/code/time.lisp<br>
@@ -242,15 +242,18 @@ format."<br>
<br>
;;;; TIME<br>
<br>
+(defvar *gc-real-time* 0<br>
+ "Total real time spent doing garbage collection (as reported by<br>
+GET-INTERNAL-REAL-TIME.) Initialized to zero on startup.")<br>
(defvar *gc-run-time* 0<br>
"Total CPU time spent doing garbage collection (as reported by<br>
GET-INTERNAL-RUN-TIME.) Initialized to zero on startup. It is safe to bind<br>
this to zero in order to measure GC time inside a certain section of code, but<br>
doing so may interfere with results reported by eg. TIME.")<br>
-(declaim (type index *gc-run-time*))<br>
+(declaim (type index *gc-run-time* *gc-real-time*))<br>
<br>
(defun print-time (&key real-time-ms user-run-time-us system-run-time-us<br>
- gc-run-time-ms processor-cycles eval-calls<br>
+ gc-run-time-ms gc-real-time-ms processor-cycles \
eval-calls<br>
lambdas-converted page-faults bytes-consed<br>
aborted)<br>
(let ((total-run-time-us (+ user-run-time-us system-run-time-us))<br>
@@ -263,6 +266,8 @@ doing so may interfere with results reported by eg. \
TIME.")<br>
~@< ~@;~/sb-impl::format-milliseconds/ of \
real time~%~<br>
~/sb-impl::format-microseconds/ of \
total run time ~<br>
\
(~@/sb-impl::format-microseconds/ user, ~@/sb-impl::format-microseconds/ \
system)~%~<br> + ~[[ Real times \
consist of ~/sb-impl::format-milliseconds/ GC time, ~<br> + \
and ~/sb-impl::format-milliseconds/ non-GC time. ]~%~;~2*~]~<br>
~[[ Run times consist of \
~/sb-impl::format-milliseconds/ GC time, ~<br>
\
and ~/sb-impl::format-milliseconds/ non-GC time. ]~%~;~2*~]~<br> ~,2F% CPU~%~<br>
@@ -276,6 +281,9 @@ doing so may interfere with results reported by eg. \
TIME.")<br> total-run-time-us<br>
user-run-time-us<br>
system-run-time-us<br>
+ (if (zerop gc-real-time-ms) 1 0)<br>
+ gc-real-time-ms<br>
+ (- real-time-ms gc-real-time-ms)<br>
(if (zerop gc-run-time-ms) 1 0)<br>
gc-run-time-ms<br>
;; Round up so we don't mislead by saying 0.0 seconds of \
non-GC time...<br> @@ -398,6 +406,9 @@ returns values returned by FUNCTION.<br>
:GC-RUN-TIME-MS<br>
GC run time in milliseconds (included in user and system run time.)<br>
<br>
+ :GC-REAL-TIME-MS<br>
+ GC real time in milliseconds.<br>
+<br>
:PROCESSOR-CYCLES<br>
Approximate number of processor cycles used. (Omitted if not supported \
on<br>
the platform -- currently available on x86 and x86-64 only.)<br>
@@ -454,6 +465,7 @@ EXPERIMENTAL: Interface subject to change."<br>
(time-get-sys-info))<br>
(setq old-real-time (get-internal-real-time))<br>
(let ((start-gc-internal-run-time *gc-run-time*)<br>
+ (start-gc-internal-real-time *gc-real-time*)<br>
(*eval-calls* 0)<br>
(sb-c::*lambda-conversions* 0)<br>
(aborted t))<br>
@@ -462,12 +474,14 @@ EXPERIMENTAL: Interface subject to change."<br>
(multiple-value-prog1 (apply fun arguments)<br>
(setf aborted nil))<br>
(multiple-value-bind (h1 l1) (read-cycle-counter)<br>
- (let ((stop-gc-internal-run-time *gc-run-time*))<br>
+ (let ((stop-gc-internal-run-time *gc-run-time*)<br>
+ (stop-gc-internal-real-time *gc-real-time*))<br>
(multiple-value-setq<br>
(new-run-utime new-run-stime new-page-faults \
new-bytes-consed)<br> (time-get-sys-info))<br>
(setq new-real-time (- (get-internal-real-time) \
real-time-overhead))<br>
(let* ((gc-internal-run-time (max (- stop-gc-internal-run-time \
start-gc-internal-run-time) 0))<br> + \
(gc-internal-real-time (max (- stop-gc-internal-real-time \
start-gc-internal-real-time) 0))<br>
(real-time (max (- new-real-time old-real-time) \
0))<br>
(user-run-time (max (- new-run-utime old-run-utime) \
0))<br>
(system-run-time (max (- new-run-stime \
old-run-stime) 0))<br> @@ -487,6 +501,8 @@ EXPERIMENTAL: Interface subject to \
change."<br>
(note :eval-calls *eval-calls* #'zerop)<br>
(note :gc-run-time-ms (floor gc-internal-run-time<br>
(/ \
internal-time-units-per-second 1000)))<br> + (note \
:gc-real-time-ms (floor gc-internal-real-time<br> + \
(/ internal-time-units-per-second 1000)))<br>
(note :system-run-time-us system-run-time)<br>
(note :user-run-time-us user-run-time)<br>
(note :real-time-ms (floor real-time<br>
diff --git a/src/cold/exports.lisp b/src/cold/exports.lisp<br>
index d2d93a2f1..72219eefb 100644<br>
--- a/src/cold/exports.lisp<br>
+++ b/src/cold/exports.lisp<br>
@@ -791,6 +791,7 @@ like *STACK-TOP-HINT* and unsupported stuff like \
*TRACED-FUN-LIST*.")<br> "BYTES-CONSED-BETWEEN-GCS"<br>
"GC" "GET-BYTES-CONSED"<br>
"*GC-RUN-TIME*"<br>
+ "*GC-REAL-TIME*"<br>
"PURIFY"<br>
"DYNAMIC-SPACE-SIZE"<br>
;; Gencgc only, but symbols exist for manual building<br>
diff --git a/tests/run-tests.lisp b/tests/run-tests.lisp<br>
index e49b6bf34..aa39a9e5e 100644<br>
--- a/tests/run-tests.lisp<br>
+++ b/tests/run-tests.lisp<br>
@@ -214,6 +214,7 @@<br>
,(maybe "SB-KERNEL" "*EVAL-CALLS*")<br>
sb-kernel::*type-cache-nonce*<br>
sb-ext:*gc-run-time*<br>
+ sb-ext:*gc-real-time*<br>
sb-kernel::*gc-epoch*<br>
sb-int:*n-bytes-freed-or-purified*<br>
,(maybe "SB-VM" "*BINDING-STACK-POINTER*")<br>
<br>
-----------------------------------------------------------------------<br>
<br>
<br>
hooks/post-receive<br>
-- <br>
SBCL<br>
<br>
<br>
_______________________________________________<br>
Sbcl-commits mailing list<br>
<a href="mailto:Sbcl-commits@lists.sourceforge.net" \
target="_blank">Sbcl-commits@lists.sourceforge.net</a><br> <a \
href="https://lists.sourceforge.net/lists/listinfo/sbcl-commits" rel="noreferrer" \
target="_blank">https://lists.sourceforge.net/lists/listinfo/sbcl-commits</a><br> \
</blockquote></div> </blockquote></div></div>
_______________________________________________
Sbcl-devel mailing list
Sbcl-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/sbcl-devel
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic