Feature: improvements to tracing infrastructure?

[shwestrick]

Some thoughts:

• MaPLe has a rudimentary tracing infrastructure, but it’s not well documented and a bit fragile.
• It’s discussed briefly here and here
• Here’s a somewhat recent example of extending it with additional events.
• It would be really useful to track other events.

Additional events that would be useful:

• (Done: Export a counter event for block allocations. #235) Block allocations and deallocations, perhaps also keeping track of block usage as a tracing counter.
  • In MaPLe, one "block" is essentially one OS page, and the block allocator is responsible for allocating and freeing blocks.
  • Every block allocation goes through allocateBlocks, and every deallocation through freeBlocks
  • Adding support for tracing might be pretty straightforward.
• TODO more!

(11/27/25, Sam) Taking notes here of other ideas for additional functionality:

• Only tracing a subset of events during a run
• Allowing for application-level user-customizable events

[pscollins]

Block allocate/free should be "point events" like EVENT_SCHED_SPAWN or EVENT_SCHED_JOIN, right?

[shwestrick]

Yes, I think that would work well

[pscollins]

With:

diff --git a/mltrace/tracetr.c b/mltrace/tracetr.c
index dc214efd2..97675184e 100644
--- a/mltrace/tracetr.c
+++ b/mltrace/tracetr.c
@@ -83,6 +83,9 @@ static const char *EventKindStrings[] = {
 
   [EVENT_SCHED_SLEEP_ENTER] = "SCHED_SLEEP_ENTER",
   [EVENT_SCHED_SLEEP_LEAVE] = "SCHED_SLEEP_LEAVE",
+
+  [EVENT_BLOCK_ALLOCATE] = "BLOCK_ALLOCATE",
+  [EVENT_BLOCK_FREE] = "BLOCK_FREE",
 };
 
 void processFiles(size_t filecount, FILE **files, void (*func)(struct Event *));
diff --git a/runtime/gc/block-allocator.c b/runtime/gc/block-allocator.c
index abc97d9a4..fa8b0c15e 100644
--- a/runtime/gc/block-allocator.c
+++ b/runtime/gc/block-allocator.c
@@ -519,6 +519,7 @@ static MegaBlock mmapNewMegaBlock(GC_state s, size_t numBlocks, enum BlockPurpos
 
 
 Blocks allocateBlocksWithPurpose(GC_state s, size_t numBlocks, enum BlockPurpose purpose) {
+  Trace0(EVENT_BLOCK_ALLOCATE);
   BlockAllocator local = s->blockAllocatorLocal;
   assertBlockAllocatorOkay(s, local);
 
@@ -578,6 +579,7 @@ Blocks allocateBlocks(GC_state s, size_t numBlocks) {
 
 
 void freeBlocks(GC_state s, Blocks bs, writeFreedBlockInfoFnClosure f) {
+  Trace0(EVENT_BLOCK_FREE);
   BlockAllocator local = s->blockAllocatorLocal;
   assertBlockAllocatorOkay(s, local);
 
diff --git a/runtime/trace.h b/runtime/trace.h
index 23b262613..1b3d1f560 100644
--- a/runtime/trace.h
+++ b/runtime/trace.h
@@ -81,7 +81,10 @@ enum EventKind {
   EVENT_MANAGE_ENTANGLED_LEAVE = 47,
 
   EVENT_SCHED_SLEEP_ENTER     = 48,
-  EVENT_SCHED_SLEEP_LEAVE     = 49
+  EVENT_SCHED_SLEEP_LEAVE     = 49,
+
+  EVENT_BLOCK_ALLOCATE = 50,
+  EVENT_BLOCK_FREE = 51,
 };
 
 #define EventKindCount (sizeof EventKindStrings / sizeof *EventKindStrings)

I get the attached trace. It looks like there are a ton of these events, it might make the chart a bit hard to read?

Maybe something like the following would help?

diff --git a/mltrace/tracetr.c b/mltrace/tracetr.c
index 97675184e..66420f5d9 100644
--- a/mltrace/tracetr.c
+++ b/mltrace/tracetr.c
@@ -88,8 +88,9 @@ static const char *EventKindStrings[] = {
   [EVENT_BLOCK_FREE] = "BLOCK_FREE",
 };
 
-void processFiles(size_t filecount, FILE **files, void (*func)(struct Event *));
-void processFilesChromeTracingJSON(size_t filecount, FILE **files);
+void processFiles(size_t filecount, FILE **files, void (*func)(struct Event *),
+                  int verbosity);
+void processFilesChromeTracingJSON(size_t filecount, FILE **files, int verbosity);
 
 void printEventText(struct Event *);
 void printEventCSV(struct Event *);
@@ -103,6 +104,7 @@ void usage() {
           "  -c                 display contents in CSV format\n"
           "  -j                 display contents in Chrome Tracing JSON format\n"
           "  -h                 display this message\n"
+          "  -h                 verbosity level (repeat for higher level)\n"
     );
 }
 
@@ -112,10 +114,11 @@ int main(int argc, char *argv[]) {
   bool display = false, csv = false, chromeTracingJSON = false;
   bool read_stdin = false;
   FILE **files;
+  int verbosity = 0;
 
   /* Parse command line arguments. */
 
-  while ((opt = getopt(argc, argv, "dhcj")) != -1) {
+  while ((opt = getopt(argc, argv, "dhcjv")) != -1) {
     switch (opt) {
     case 'd':
       display = true;
@@ -126,6 +129,9 @@ int main(int argc, char *argv[]) {
     case 'j':
       chromeTracingJSON = true;
       break;
+    case 'v':
+      ++verbosity;
+      break;
     case 'h':
       usage();
       return 0;
@@ -165,13 +171,13 @@ int main(int argc, char *argv[]) {
   /* Perform the requested actions. */
 
   if (display)
-    processFiles(fcount, files, printEventText);
+    processFiles(fcount, files, printEventText, verbosity);
 
   if (csv)
-    processFiles(fcount, files, printEventCSV);
+    processFiles(fcount, files, printEventCSV, verbosity);
 
   if (chromeTracingJSON)
-    processFilesChromeTracingJSON(fcount, files);
+    processFilesChromeTracingJSON(fcount, files, verbosity);
 
   /* Close and free files. */
 
@@ -186,8 +192,26 @@ int main(int argc, char *argv[]) {
 
 #define BUFFER_SIZE 10000
 
+/* Returns the minimum verbosity level required for event `kind`  */
+int getRequiredVerbosity(int kind) {
+  switch (kind) {
+    /* For now, only "verbose" events: */
+  case EVENT_BLOCK_ALLOCATE:
+  case EVENT_BLOCK_FREE:
+    return 1;
+    /* All other events display by default */
+  default:
+    return 0;
+  }
+}
+
+bool matchesVerbosity(struct Event* e, int verbosity) {
+  return getRequiredVerbosity(e->kind) <= verbosity;
+}
+
 void processFiles(size_t filecount, FILE **files,
-                  void (*func)(struct Event *)) {
+                  void (*func)(struct Event *),
+                  int verbosity) {
   struct Event events[BUFFER_SIZE];
 
   for (size_t i = 0; i < filecount; ++i) {
@@ -198,14 +222,18 @@ void processFiles(size_t filecount, FILE **files,
                           files[i]);
       evcount += evbatchsize;
 
-      for (int j = 0; j < evbatchsize; j++)
+      for (int j = 0; j < evbatchsize; j++) {
+        if (!matchesVerbosity(&events[j], verbosity)) {
+          continue;
+        }
         func(&events[j]);
-
+      }
     } while (evbatchsize == BUFFER_SIZE);
   }
 }
 
-void processFilesChromeTracingJSON(size_t filecount, FILE **files)
+void processFilesChromeTracingJSON(size_t filecount, FILE **files,
+                                   int verbosity)
 {
   struct Event events[BUFFER_SIZE];
 
@@ -222,6 +250,9 @@ void processFilesChromeTracingJSON(size_t filecount, FILE **files)
       evcount += evbatchsize;
 
       for (int j = 0; j < evbatchsize; j++) {
+        if (!matchesVerbosity(&events[j], verbosity)) {
+          continue;
+        }
 
         if (first) first = false;
         else printf(",\n");

Then I can get either:

$ gunzip -c $(ls -1t primes.trace.*.gz | head -n 1) | ../mltrace/tracetr -j > non_verbose.json 

for a trace like the original:

or:

$ gunzip -c $(ls -1t primes.trace.*.gz | head -n 1) | ../mltrace/tracetr -j -v > verbose.json

to get:

primes.trace.483658.json

[shwestrick]

I agree -- that's quite a lot of events. Controlling verbosity seems useful!

I wonder if for block usage, it would be more helpful to track blocks allocated/deallocated as a dynamic counter, instead of discrete events? I've vaguely aware that the Perfetto visualizer supports a counter event, but I don't know the details off the top of my head.

[pscollins]

I got this working in main...pscollins:mpl:counter-metric2

Running (in examples/):

$ make primes.trace
$ ../mltrace/mltrace record bin/primes.trace @mpl procs 4 --
$ gunzip -c $(ls -1t primes.trace.*.gz | head -n 1) | ../mltrace/tracetr -j > /tmp/out.json

gives me the attached json.

Does the plot look plausible to you?

out.json

[shwestrick]

Excellent! Looks great. A couple notes.

Just to be safe, could we use a 64-bit counter? (A 32-bit overflow seems practically impossible, but hey, might as well...)

Could you use ENABLE_TRACING to enable and disable code that is only used in the tracing version of the runtime system? I think both the live_blocks counter and the increment/decrement functions could be put underneath ENABLE_TRACING.

For example:

mpl/runtime/gc/init.c

Line 782 in a71659b

#ifdef ENABLE_TRACING

And, if it's helpful:

mpl/runtime/gc.c

Lines 31 to 37 in a71659b

	#ifdef ENABLE_TRACING
	#define ARG_USED_FOR_TRACING
	#define LOCAL_USED_FOR_TRACING
	#else
	#define ARG_USED_FOR_TRACING __attribute__ ((unused))
	#define LOCAL_USED_FOR_TRACING __attribute__ ((unused))
	#endif

[pscollins]

Done!