Recording events downwards from the top of the buffer so that they can be recovered by a backtrace.

Copied from Perforce
 Change: 179131
 ServerID: perforce.ravenbrook.com

5 files changed, 58 insertions, 37 deletions

diff --git a/mps/code/event.c b/mps/code/event.c
index b97714f62b4..d3ea72277fc 100644
--- a/mps/code/event.c
+++ b/mps/code/event.c
@@ -33,12 +33,12 @@ SRCID(event, "$Id$");
 
 static Bool eventInited = FALSE;
 static mps_io_t eventIO;
-static char eventBuffer[EventBufferSIZE];
 static Count eventUserCount;
 static Serial EventInternSerial;
 
-char *EventNext, *EventLimit; /* Used by macros in <code/event.h> */
-EventControlSet EventKindControl; /* Bit set used to control output. */
+char EventBuffer[EventBufferSIZE];      /* in which events are recorded */
+char *EventLast;                        /* points to last written event */
+EventControlSet EventKindControl;       /* Bit set used to control output. */
 
 
 /* EventFlush -- flush event buffer to the event stream */
@@ -47,18 +47,24 @@ Res EventFlush(void)
 {
   Res res;
   size_t size;
- 
+
   AVER(eventInited);
 
-  AVER(eventBuffer <= EventNext);
-  AVER(EventNext <= eventBuffer + EventBufferSIZE);
-  size = (size_t)(EventNext - eventBuffer);
+  AVER(EventBuffer <= EventLast);
+  AVER(EventLast <= EventBuffer + EventBufferSIZE);
+  size = (size_t)(EventBuffer + EventBufferSIZE - EventLast);
 
-  res = (Res)mps_io_write(eventIO, (void *)eventBuffer, size);
-  EventNext = eventBuffer;
-  if (res != ResOK) return res;
+  /* Writing might be faster if the size is aligned to a multiple of the
+     C library or kernel's buffer size.  We could pad out the buffer with
+     a marker for this purpose. */
 
-  return ResOK;
+  res = (Res)mps_io_write(eventIO, (void *)EventLast, size);
+
+  /* Flush the in-memory buffer whether or not we succeeded, so that we can
+     record recent events there. */
+  EventLast = EventBuffer + EventBufferSIZE;
+
+  return res;
 }
 
 
@@ -98,9 +104,21 @@ Res EventInit(void)
   /* Check consistency of the event definitions.  These are all compile-time
      checks and should get optimised away. */
 
+#define EVENT_PARAM_CHECK_P(name, index, ident)
+#define EVENT_PARAM_CHECK_A(name, index, ident)
+#define EVENT_PARAM_CHECK_W(name, index, ident)
+#define EVENT_PARAM_CHECK_U(name, index, ident)
+#define EVENT_PARAM_CHECK_D(name, index, ident)
+#define EVENT_PARAM_CHECK_B(name, index, ident)
+#define EVENT_PARAM_CHECK_S(name, index, ident) \
+  AVER(index + 1 == Event##name##ParamLIMIT); /* strings must come last */ \
+  AVER(offsetof(Event##name##Struct, f##index.str) + EventStringLengthMAX \
+       <= EventSizeMAX);
+
 #define EVENT_PARAM_CHECK(name, index, sort, ident) \
   AVER(index == Event##name##Param##ident); \
-  AVER(sizeof(EventF##sort) >= 0); /* check existence of type */
+  AVER(sizeof(EventF##sort) >= 0); /* check existence of type */ \
+  EVENT_PARAM_CHECK_##sort(name, index, ident)
 
 #define EVENT_CHECK(X, name, code, always, kind) \
   AVER(size_tAlignUp(sizeof(Event##name##Struct), MPS_PF_ALIGN) \
@@ -114,18 +132,16 @@ Res EventInit(void)
   EVENT_##name##_PARAMS(EVENT_PARAM_CHECK, name)
 
   EVENT_LIST(EVENT_CHECK, X)
-
+  
   /* Ensure that no event can be larger than the maximum event size. */
   AVER(EventBufferSIZE <= EventSizeMAX);
 
   /* Only if this is the first call. */
   if(!eventInited) { /* See .trans.log */
-    AVER(EventNext == 0);
-    AVER(EventLimit == 0);
+    AVER(EventLast == NULL);
     res = (Res)mps_io_create(&eventIO);
     if(res != ResOK) return res;
-    EventNext = eventBuffer;
-    EventLimit = &eventBuffer[EventBufferSIZE];
+    EventLast = EventBuffer + EventBufferSIZE;
     eventUserCount = (Count)1;
     eventInited = TRUE;
     EventKindControl = (Word)mps_lib_telemetry_control();
diff --git a/mps/code/event.h b/mps/code/event.h
index 9af0225d7fd..d4c2ce83b95 100644
--- a/mps/code/event.h
+++ b/mps/code/event.h
@@ -38,12 +38,13 @@ extern Res EventFlush(void);
 
 /* Event writing support */
 
-extern char *EventNext, *EventLimit;
+extern char EventBuffer[EventBufferSIZE];  /* in which events are recorded */
+extern char *EventLast;                    /* points to last written event */
 extern Word EventKindControl;
 
 
-/* TODO: Append a size at EventNext - sizeof(EventSize) so that a backtrace
-   can step backwards through the event buffer. */
+/* Events are written into the buffer from the top down, so that a backtrace
+   can find them all starting at EventNext. */
 
 #define EVENT_BEGIN(name, structSize) \
   BEGIN \
@@ -51,16 +52,16 @@ extern Word EventKindControl;
        BS_IS_MEMBER(EventKindControl, (Index)Event##name##Kind)) { \
       Event##name##Struct *_event; \
       size_t _size = size_tAlignUp(structSize, MPS_PF_ALIGN); \
-      if (_size > (size_t)(EventLimit - EventNext)) \
+      if (_size > (size_t)(EventLast - EventBuffer)) \
         EventFlush(); \
-      AVER(_size <= (size_t)(EventLimit - EventNext)); \
-      _event = (void *)EventNext; \
+      AVER(_size <= (size_t)(EventLast - EventBuffer)); \
+      _event = (void *)(EventLast - _size); \
       _event->code = Event##name##Code; \
       _event->size = (EventSize)_size; \
       EVENT_CLOCK(_event->clock);
 
 #define EVENT_END(name, size) \
-      EventNext += _size; \
+      EventLast -= _size; \
     } \
   END
 
diff --git a/mps/code/eventcnv.c b/mps/code/eventcnv.c
index c5a436d1df9..ffdad909ad6 100644
--- a/mps/code/eventcnv.c
+++ b/mps/code/eventcnv.c
@@ -55,7 +55,7 @@ static Bool verbose = FALSE;
 static char style = '\0';
 static Bool reportEvents = FALSE;
 static Bool eventEnabled[EventCodeMAX+1];
-static Bool partialLog = FALSE;
+static Bool partialLog = FALSE; /* FIXME: can't read out-of-order labels */
 static Word bucketSize = 0;
 
 
@@ -454,23 +454,25 @@ static void readLog(EventProc proc)
       if (style == 'L') putchar('(');
 
       switch (style) {
+      case '\0': case 'L':
+        EVENT_CLOCK_PRINT(stdout, eventTime);
+        putchar(' ');
+        break;
+      case 'C':
+        EVENT_CLOCK_PRINT(stdout, eventTime);
+        fputs(", ", stdout);
+        break;
+      }
+
+      switch (style) {
       case '\0': case 'L': {
-        printf("%-19s", EventCode2Name(code));
+        printf("%-19s ", EventCode2Name(code));
       } break;
       case 'C':
         printf("%u", (unsigned)code);
         break;
       }
 
-     switch (style) {
-     case '\0':
-       printf(" %8"PRIuLONGEST, (ulongest_t)eventTime); break;
-     case 'C':
-       printf(", %"PRIuLONGEST, (ulongest_t)eventTime); break;
-     case 'L':
-       printf(" %"PRIXLONGEST, (ulongest_t)eventTime); break;
-     }
-
      switch (event->any.code) {
 
      case EventLabelCode:
diff --git a/mps/code/eventcom.h b/mps/code/eventcom.h
index d5e3959d72c..d572c56bdc8 100644
--- a/mps/code/eventcom.h
+++ b/mps/code/eventcom.h
@@ -68,7 +68,9 @@ __extension__ typedef unsigned long long EventClock;
   END
 
 #define EVENT_CLOCK_PRINT(stream, clock) \
-  fprintf(stream, "%lu", (unsigned long)clock) /* FIXME: Should be %llu */
+  fprintf(stream, "%08lX%08lX",  /* FIXME: Should be %llu */ \
+          (unsigned long)((clock) >> 32), \
+          (unsigned long)(clock))
 
 #endif /* Intel, GCC or Clang */
 
diff --git a/mps/code/eventdef.h b/mps/code/eventdef.h
index 77a1269369b..27bb3bb6320 100644
--- a/mps/code/eventdef.h
+++ b/mps/code/eventdef.h
@@ -168,7 +168,7 @@
  *   - the positional index of the parameter in the list, used to define
  *     numeric field names using the C preprocessor
  *   - the parameter sort, similar to writef (Pointer, Addr, Word, Unsigned,
- *     String, Double)
+ *     String, Double, Bool)
  *   - a parameter identifier for display or use in code
  *
  * TODO: Add a doc string to each parameter.