master: Reimplement low-level logging
snuglas via Sbcl-commits <[email protected]>
| Newsgroups | gmane.lisp.steel-bank.cvs |
|---|---|
| Message-ID | <[email protected]> |
The branch "master" has been updated in SBCL:
via bad56f62b651a7ad676bda45b6bfed3e3f54ef2a (commit)
from c2df85fe12dd412c0db10ba716b1bb33e40cbc3b (commit)
- Log -----------------------------------------------------------------
commit bad56f62b651a7ad676bda45b6bfed3e3f54ef2a
Author: Douglas Katzman <[email protected]>
Date: Thu Apr 30 03:02:07 2026 -0400
Reimplement low-level logging
Store an enum, not a printf format string, in the event buffer
---
src/code/cross-early.lisp | 21 ++++++++++
src/compiler/generic/genesis.lisp | 53 ++++++++++++++++++++++++
src/runtime/atomiclog.inc | 84 ---------------------------------------
src/runtime/interrupt.c | 15 ++++---
src/runtime/linux-os.c | 3 ++
src/runtime/monitor.c | 46 +++++++++++----------
src/runtime/stop-the-world.c | 16 ++++----
src/runtime/thread.c | 1 -
8 files changed, 118 insertions(+), 121 deletions(-)
diff --git a/src/code/cross-early.lisp b/src/code/cross-early.lisp
index 7f687dd23..d958b073e 100644
--- a/src/code/cross-early.lisp
+++ b/src/code/cross-early.lisp
@@ -300,3 +300,24 @@
(defun simple-rank-1-array-*-p (x)
(typep x '(simple-array * (*))))
+
+;;; This table defines a more modern approach to the event logging macros.
+;;; The identifier-to-number mapping is autogenerated, the argument count to EVENT can
+;;; not be gotten wrong due to user error, and you can filter events at recording time.
+;;; odxprint tries to something vaguely similar, but in my experience odxprint is actively
+;;; harmful to low-level debugging just when you most want it to work, because
+;;; snprintf can drastically affect the timing of events, and stdio can deadlock,
+;;; whereas the event buffer does not suffer from those problems.
+(defparameter *c-runtime-events*
+ '((|GotSignal| "got signal %d @ pc=%p")
+ (|SigDeferred_IntDisabled| "can_handle_now(%p,%d): deferred (RACE=%d)")
+ (|SigDeferred_PA| "can_handle_now(%p,%d): deferred (PA)")
+ (|StopDeferred_GCinhibit| "stop_for_gc deferred for *GC-INHIBIT*")
+ (|StopDeferred_PA| "stop_for_gc deferred for PA")
+ (|StopForGC| "stop_for_gc")
+ (|AfterGCblockedDeferrables| "cleaning up after gc_blocked_deferrables")
+ (|Suspended| "suspended")
+ (|Resumed| "resumed")
+ (|STW_end| "/gc_stop_the_world:end")
+ (|FutexWait| "futex_wait %p")
+ (|FutexWake| "futex_wake %p")))
diff --git a/src/compiler/generic/genesis.lisp b/src/compiler/generic/genesis.lisp
index 443d2c692..df57432f2 100644
--- a/src/compiler/generic/genesis.lisp
+++ b/src/compiler/generic/genesis.lisp
@@ -4525,6 +4525,58 @@ static inline uword_t word_has_stickymark(uword_t word) {
c-const (sb-kernel::choose-layout-id type nil))))
(terpri stream))
+(defun write-events (output &aux (defs sb-impl::*c-runtime-events*))
+ ;; Only 5 bits are allocated to the ID in an event record
+ (aver (<= (length defs) 32))
+ (format output "enum vmevent {~% Event~A=0~{,~% Event~A~}~%};~2%"
+ (caar defs) (mapcar 'car (cdr defs)))
+ (format output "#include <stdint.h>
+#define EVENTBUFMAX 400000
+extern uintptr_t *eventdata;
+extern int n_logevents;
+#ifndef should_record_event
+#define should_record_event(x) 0
+#endif~%")
+ ;; eventN = record event with N parameters
+ ;; NOTE 1: The buffer is oversized by enough to ensure that i_+N does not
+ ;; overrun, so we need not adjust the comparison of 'i_ <' by the number
+ ;; of format arguments. A more sophisticated approach would have the log
+ ;; be a ring buffer, which would work fine in most cases since the focus
+ ;; of a crash is generally on the most recent events.
+ ;; NOTE 2: Assume that pthread_self() can be cast to 'uword_t' - which is
+ ;; true for or supported platforms - and that the low 3 bits are 0 (which
+ ;; may not hold for 32-bit, but surely does for 64-bit). Hence the low 3 can
+ ;; can be used for the ID. But in fact we would like 5 bits for that, so
+ ;; left-shift an additional 2 bits. This is OK as long as the upper 2 bits
+ ;; of pthread_t are 0, which they are if it's a virtual address.
+ (flet ((count-printf-args (str &aux (count 0) (start 0))
+ (loop (let ((p (position #\% str :start start)))
+ (setq start (cond ((not p) (return count))
+ ((char= (char str (1+ p)) #\%) (+ p 2))
+ (t (incf count) (1+ p)))))))
+ (formals (arity)
+ (if (> arity 0)
+ (format nil "~{,arg~D~}" (loop for i from 1 repeat arity collect i))
+ "")))
+ (format output "#ifdef WANT_EVENTLOG_FORMAT_STRINGS
+static char event_printf_nargs[32] = {~{~D~^,~}};
+static char *event_printf_format[] = {~{~% ~S~^,~}~%};~%#endif~2%"
+ (mapcar (lambda (x) (count-printf-args (cadr x))) defs)
+ (mapcar 'cadr defs))
+ (dotimes (argc 7)
+ (format output "#define EVENT~D(id~A) { if(should_record_event(id)) \\
+ { int i_ = __sync_fetch_and_add(&n_logevents, ~A); if (i_ < EVENTBUFMAX) { \\
+ eventdata[i_] = ((uword_t)pthread_self() << 2) | id;~
+~{ eventdata[i_+~D] = (uword_t)arg~:*~D;~^ \\~%~} }}}~%"
+ argc (formals argc) (1+ argc) (loop for n from 1 to argc collect n)))
+ (dolist (x defs)
+ (let* ((event (car x))
+ (arity (count-printf-args (cadr x)))
+ (formals (formals arity)))
+ (format output "#define event_~A(~A) EVENT~D(Event~A~A)~%"
+ event (subseq formals (min 1 (length formals)))
+ arity event formals)))))
+
(defparameter numeric-primitive-objects
(remove nil ; SINGLE-FLOAT and/or the SIMD-PACKs might not exist
(mapcar #'get-primitive-obj
@@ -4572,6 +4624,7 @@ static inline uword_t word_has_stickymark(uword_t word) {
(out-to "cardmarks" (write-mark-array-operators stream))
(out-to "tagnames" (write-tagnames-h stream))
(out-to "print.inc" (write-c-print-dispatch stream))
+ (out-to "events" (write-events stream))
(let* ((skip `(,(get-primitive-obj 'funcallable-instance)
,(get-primitive-obj 'binding)
,(get-primitive-obj 'catch-block)
diff --git a/src/runtime/atomiclog.inc b/src/runtime/atomiclog.inc
deleted file mode 100644
index 38f50855b..000000000
--- a/src/runtime/atomiclog.inc
+++ /dev/null
@@ -1,84 +0,0 @@
-/* -*- Mode: C -*- */
-
-#ifndef ATOMIC_LOGGING
-#define event0(fmt)
-#define event1(fmt,a)
-#define event2(fmt,a,b)
-#define event3(fmt,a,b,c)
-#define event4(fmt,a,b,c,d)
-#define event5(fmt,a,b,c,d,e)
-#define event6(fmt,a,b,c,d,e,f)
-#else
-
-#define EVENTBUFMAX 400000
-extern uword_t *eventdata;
-extern int n_logevents;
-
-/// eventN = record event with N parameters
-
-/// NOTE 1: The buffer is oversized by enough to ensure that i_+7 does not
-/// overrun the buffer. So we don't need to adjust the comparison of 'i_ <'
-/// by the number of additional arguments.
-
-/// NOTE 2: Assume that pthread_self() can be cast to 'uword_t', which is
-/// pretty much true everywhere, and that the low 3 bits are 0
-/// (which may not be true for 32-bit, but almost surely is for 64-bit).
-/// So we can stuff the low 3 bits with something.
-
-#define event0(fmt) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 2); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = (uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; } }
-
-#define event1(fmt, arg1) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 3); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = 1|(uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; \
- eventdata[i_+2] = (uword_t)arg1; } }
-
-#define event2(fmt, arg1, arg2) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 4); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = 2|(uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; \
- eventdata[i_+2] = (uword_t)arg1; \
- eventdata[i_+3] = (uword_t)arg2; } }
-
-#define event3(fmt, arg1, arg2, arg3) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 5); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = 3|(uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; \
- eventdata[i_+2] = (uword_t)arg1; \
- eventdata[i_+3] = (uword_t)arg2; \
- eventdata[i_+4] = (uword_t)arg3; } }
-
-#define event4(fmt, arg1, arg2, arg3, arg4) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 6); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = 4|(uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; \
- eventdata[i_+2] = (uword_t)arg1; \
- eventdata[i_+3] = (uword_t)arg2; \
- eventdata[i_+4] = (uword_t)arg3; \
- eventdata[i_+5] = (uword_t)arg4; } }
-
-#define event5(fmt, arg1, arg2, arg3, arg4, arg5) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 7); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = 5|(uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; \
- eventdata[i_+2] = (uword_t)arg1; \
- eventdata[i_+3] = (uword_t)arg2; \
- eventdata[i_+4] = (uword_t)arg3; \
- eventdata[i_+5] = (uword_t)arg4; \
- eventdata[i_+6] = (uword_t)arg5; } }
-
-#define event6(fmt, arg1, arg2, arg3, arg4, arg5, arg6) \
- { int i_ = __sync_fetch_and_add(&n_logevents, 8); if (i_ < EVENTBUFMAX) { \
- eventdata[i_ ] = 6|(uword_t)pthread_self(); \
- eventdata[i_+1] = (uword_t)fmt; \
- eventdata[i_+2] = (uword_t)arg1; \
- eventdata[i_+3] = (uword_t)arg2; \
- eventdata[i_+4] = (uword_t)arg3; \
- eventdata[i_+5] = (uword_t)arg4; \
- eventdata[i_+6] = (uword_t)arg5; \
- eventdata[i_+7] = (uword_t)arg6; } }
-
-#endif
diff --git a/src/runtime/interrupt.c b/src/runtime/interrupt.c
index 766355045..ea471bec6 100644
--- a/src/runtime/interrupt.c
+++ b/src/runtime/interrupt.c
@@ -68,9 +68,9 @@
#include "genesis/cons.h"
#include "genesis/vector.h"
#include "genesis/thread.h"
-#include "atomiclog.inc"
+#include "genesis/events.h"
-#ifdef ATOMIC_LOGGING
+#ifdef VM_EVENT_RECORDING
uword_t *eventdata;
int n_logevents;
#endif
@@ -263,10 +263,10 @@ resignal_to_lisp_thread(int signal, os_context_t *context)
* kernel properly, so we fix it up ourselves in the
* arch_os_get_context(..) function. -- CSR, 2002-07-23
*/
-#ifdef ATOMIC_LOGGING
+#ifdef VM_EVENT_RECORDING
static void record_signal(int sig, void* context)
{
- event2("got signal %d @ pc=%p", sig, os_context_pc(context));
+ event_GotSignal(sig, os_context_pc(context));
}
#define RECORD_SIGNAL(sig,ctxt) if(sig!=SIGSEGV)record_signal(sig,ctxt);
#else
@@ -1259,8 +1259,7 @@ can_handle_now(void *handler, struct interrupt_data *data,
*/
if ((read_TLS(INTERRUPTS_ENABLED,thread) == NIL) ||
in_leaving_without_gcing_race_p(thread)) {
- event3("can_handle_now(%p,%d): deferred (RACE=%d)", handler, signal,
- in_leaving_without_gcing_race_p(thread));
+ event_SigDeferred_IntDisabled(handler, signal, in_leaving_without_gcing_race_p(thread));
store_signal_data_for_later(data,handler,signal,info,context);
write_TLS(INTERRUPT_PENDING, LISP_T, thread);
answer = 0;
@@ -1269,7 +1268,7 @@ can_handle_now(void *handler, struct interrupt_data *data,
* actually use its argument for anything on x86, so this branch
* may succeed even when context is null (gencgc alloc()) */
else if (arch_pseudo_atomic_atomic(thread)) {
- event2("can_handle_now(%p,%d): deferred (PA)", handler, signal);
+ event_SigDeferred_PA(handler, signal);
store_signal_data_for_later(data,handler,signal,info,context);
arch_set_pseudo_atomic_interrupted(thread);
answer = 0;
@@ -1879,7 +1878,7 @@ sigabrt_handler(int __attribute__((unused)) signal,
void
interrupt_init(void)
{
-#ifdef ATOMIC_LOGGING
+#ifdef VM_EVENT_RECORDING
// If fetch_and_add gives us an index that is less than EVENTBUFMAX,
// we assume that there is room to record an event with up to 8 arguments
// which means the prefix, the format string, and the arguments.
diff --git a/src/runtime/linux-os.c b/src/runtime/linux-os.c
index 0581c985d..851bbb48c 100644
--- a/src/runtime/linux-os.c
+++ b/src/runtime/linux-os.c
@@ -33,6 +33,7 @@
#include "runtime.h"
#include "genesis/static-symbols.h"
#include "genesis/symbol.h"
+#include "genesis/events.h"
#include <errno.h>
@@ -134,6 +135,7 @@ futex_wait(int *lock_word, int oldval, long sec, unsigned long usec)
int t;
if (sec<0) {
+ event_FutexWait(lock_word);
t = sys_futex(lock_word, futex_wait_op(), oldval, 0);
}
else {
@@ -155,6 +157,7 @@ futex_wait(int *lock_word, int oldval, long sec, unsigned long usec)
int
futex_wake(int *lock_word, int n)
{
+ event_FutexWake(lock_word);
return sys_futex(lock_word, futex_wake_op(),n,0);
}
#endif
diff --git a/src/runtime/monitor.c b/src/runtime/monitor.c
index decb15055..299a0df67 100644
--- a/src/runtime/monitor.c
+++ b/src/runtime/monitor.c
@@ -10,6 +10,7 @@
*/
#define _GNU_SOURCE
+#define WANT_EVENTLOG_FORMAT_STRINGS
#include "genesis/sbcl.h"
#include "lispobj.h"
@@ -281,7 +282,8 @@ static cmd flush_cmd, regs_cmd, exit_cmd, print_code, set_context_cmd;
static cmd print_context_cmd, pte_cmd, search_cmd, hashtable_cmd;
static cmd backtrace_cmd, threadbt_cmd, catchers_cmd;
static cmd threads_cmd, findpath_cmd, layouts_cmd;
-#ifdef ATOMIC_LOGGING
+#ifdef VM_EVENT_RECORDING
+#include "genesis/events.h"
static cmd events_cmd;
#endif
@@ -473,7 +475,7 @@ static struct cmd {
{"set_context", "Set the current context.", set_context_cmd},
{"dump", "Dump memory starting at ADDRESS for COUNT words.", dump_cmd},
{"d", "(an alias for dump)", dump_cmd},
-#ifdef ATOMIC_LOGGING
+#ifdef VM_EVENT_RECORDING
{"events", "Dump signal-related event log", events_cmd},
#endif
{"exit", "Exit this instance of the monitor.", exit_cmd},
@@ -1164,8 +1166,7 @@ static int monitor_loop(char *(*getline_fun)(char*, int, FILE*),
}
}
-#ifdef ATOMIC_LOGGING
-#include "atomiclog.inc"
+#ifdef VM_EVENT_RECORDING
char* thread_name_from_pthread(pthread_t thread) {
static char name[64];
#if defined LISP_FEATURE_LINUX || defined LISP_FEATURE_DARWIN
@@ -1175,12 +1176,12 @@ char* thread_name_from_pthread(pthread_t thread) {
#endif
}
-static void dump_eventlog(int fd)
+static void dump_eventlog(int fd, int decode_thread_names)
{
int i = 0;
uword_t *e = eventdata;
char buf[1024];
- int nc, nc1; // number of chars in buffer
+ int nc, nc1=0; // number of chars in buffer
// Define buflen to be smaller than 'buf' so that we can prefix it
// with thread pointer and suffix it with a newline
// without too much hassle.
@@ -1188,31 +1189,36 @@ static void dump_eventlog(int fd)
nc = snprintf(buf, buflen, "Event log: used %d elements of %d max\n", n_logevents, EVENTBUFMAX);
write(fd, buf, nc);
while (i<n_logevents) { // FIXME: crashes if n_logevents exceeds max
- char *fmt = (char*)e[i+1];
uword_t prefix = e[i];
- int nargs = prefix & 7;
- void* thread_pointer = (void*)(prefix & ~7);
- char* name = thread_name_from_pthread((pthread_t)thread_pointer);
+ int id = prefix & 0x1f;
+ int nargs = event_printf_nargs[id];
+ char *fmt;
+ if ((fmt=event_printf_format[id])==NULL) { printf("busted event log"); return; }
+ void* thread_pointer = (void*)((prefix & ~0x1f) >> 2);
+ // Don't use decode_thread_names if threads come and go, or you could get screwed
+ char* name = 0;
+ if (decode_thread_names) {
+ name = thread_name_from_pthread((pthread_t)thread_pointer);
+ }
if (name) nc = sprintf(buf, "%s: ", name); else nc = sprintf(buf, "%p: ", thread_pointer);
switch (nargs) {
- default: printf("busted event log"); return;
case 0: nc1 = snprintf(buf+nc, buflen, fmt, 0); break; // the 0 inhibits a warning
- case 1: nc1 = snprintf(buf+nc, buflen, fmt, e[i+2]); break;
- case 2: nc1 = snprintf(buf+nc, buflen, fmt, e[i+2], e[i+3]); break;
- case 3: nc1 = snprintf(buf+nc, buflen, fmt, e[i+2], e[i+3], e[i+4]); break;
- case 4: nc1 = snprintf(buf+nc, buflen, fmt, e[i+2], e[i+3], e[i+4], e[i+5]); break;
- case 5: nc1 = snprintf(buf+nc, buflen, fmt, e[i+2], e[i+3], e[i+4], e[i+5], e[i+6]); break;
- case 6: nc1 = snprintf(buf+nc, buflen, fmt, e[i+2], e[i+3], e[i+4], e[i+5], e[i+6],
- e[i+7]); break;
+ case 1: nc1 = snprintf(buf+nc, buflen, fmt, e[i+1]); break;
+ case 2: nc1 = snprintf(buf+nc, buflen, fmt, e[i+1], e[i+2]); break;
+ case 3: nc1 = snprintf(buf+nc, buflen, fmt, e[i+1], e[i+2], e[i+3]); break;
+ case 4: nc1 = snprintf(buf+nc, buflen, fmt, e[i+1], e[i+2], e[i+3], e[i+4]); break;
+ case 5: nc1 = snprintf(buf+nc, buflen, fmt, e[i+1], e[i+2], e[i+3], e[i+4], e[i+5]); break;
+ case 6: nc1 = snprintf(buf+nc, buflen, fmt, e[i+1], e[i+2], e[i+3], e[i+4], e[i+5],
+ e[i+6]); break;
}
#undef buflen
buf[nc+nc1] = '\n';
write(fd, buf, 1+nc+nc1);
- i += nargs + 2;
+ i += nargs + 1;
}
}
static int events_cmd(__attribute__((unused)) char **ptr, iochannel_t io) {
- dump_eventlog(fileno(io->out));
+ dump_eventlog(fileno(io->out), 0);
return 0;
}
#endif
diff --git a/src/runtime/stop-the-world.c b/src/runtime/stop-the-world.c
index bf9f71e31..7b6876050 100644
--- a/src/runtime/stop-the-world.c
+++ b/src/runtime/stop-the-world.c
@@ -16,7 +16,7 @@
#include "pseudo-atomic.h"
#include "interrupt.h"
#include "lispregs.h"
-#include "atomiclog.inc"
+#include "genesis/events.h"
#ifdef LISP_FEATURE_SB_THREAD
@@ -132,17 +132,17 @@ sig_stop_for_gc_handler(int __attribute__((unused)) signal,
/* Test for GC_INHIBIT _first_, else we'd trap on every single
* pseudo atomic until gc is finally allowed. */
if (read_TLS(GC_INHIBIT,thread) != NIL) {
- event0("stop_for_gc deferred for *GC-INHIBIT*");
+ event_StopDeferred_GCinhibit();
write_TLS(STOP_FOR_GC_PENDING, LISP_T, thread);
return;
} else if (arch_pseudo_atomic_atomic(thread)) {
- event0("stop_for_gc deferred for PA");
+ event_StopDeferred_PA();
write_TLS(STOP_FOR_GC_PENDING, LISP_T, thread);
arch_set_pseudo_atomic_interrupted(thread);
maybe_save_gc_mask_and_block_deferrables(context);
return;
}
- event0("stop_for_gc");
+ event_StopForGC();
if (!thread->state_word.control_stack_guard_page_protected) {
protect_control_stack_return_guard_page(0, thread);
@@ -171,7 +171,7 @@ sig_stop_for_gc_handler(int __attribute__((unused)) signal,
* GC. GC_BLOCKED_DEFERRABLES is also left at 1. So let's tidy it
* up. */
if (thread_interrupt_data(thread).gc_blocked_deferrables) {
- event0("cleaning up after gc_blocked_deferrables");
+ event_AfterGCblockedDeferrables();
clear_pseudo_atomic_interrupted(thread);
struct interrupt_data *interrupt_data = &thread_interrupt_data(thread);
sigcopyset(os_context_sigmask_addr(context), &interrupt_data->pending_mask);
@@ -194,7 +194,7 @@ sig_stop_for_gc_handler(int __attribute__((unused)) signal,
* occurs below at thread_wait_until_not(STATE_STOPPED). Note that sem_post()
* is expressly permitted in signal handlers, and set_thread_state uses it */
set_thread_state(thread, STATE_STOPPED, 0);
- event0("suspended");
+ event_Suspended();
/* While waiting for gc to finish occupy ourselves with zeroing
* the unused portion of the control stack to reduce conservatism.
@@ -219,7 +219,7 @@ sig_stop_for_gc_handler(int __attribute__((unused)) signal,
sigdelset(os_context_sigmask_addr(context), SIG_STOP_FOR_GC);
#endif
- event0("resumed");
+ event_Resumed();
/* The state can't go from STOPPED to DEAD because it's this thread is reading
* its own state, hence it must be running.
@@ -419,7 +419,7 @@ void gc_stop_the_world()
#ifdef LISP_FEATURE_NONSTOP_FOREIGN_CALL
atomic_store(&stopping_the_world, 0);
#endif
- event0("/gc_stop_the_world:end");
+ event_STW_end();
}
void gc_start_the_world()
diff --git a/src/runtime/thread.c b/src/runtime/thread.c
index a2ad55faa..ede780866 100644
--- a/src/runtime/thread.c
+++ b/src/runtime/thread.c
@@ -47,7 +47,6 @@
#include "pseudo-atomic.h"
#include "interrupt.h"
#include "lispregs.h"
-#include "atomiclog.inc"
#ifdef LISP_FEATURE_SB_THREAD
-----------------------------------------------------------------------
hooks/post-receive
--
SBCL