timing: Allocate all timing events dynamically

This paves the way for a Julia-side API that can create new events
on-the-fly without having to modify timing.h

The core of the change is to introduce two different structs:
  - An "event" stores all of the statically-determined attributes of a
    profiler event (typically, zone name and source location info)
  - A "timing block" stores the dynamic information relevant to a
    particular span/measurement in the timing run

Events and timing blocks have a one-to-many relationship. The intended
pattern for a Julia-side API is to construct an event once at parse-time
using `jl_timing_event_create` (since this is relatively expensive due
to profiler traffic and allocations) and then to create its own timing
block on-the-fly for each block entry/exit.

This also re-factors the API a bit to hopefully be more consistently
named

Author: topolarity

src/julia.expmap

@@ -30,6 +30,7 @@
     _Z24jl_coverage_data_pointerN4llvm9StringRefEi;
     _Z22jl_coverage_alloc_lineN4llvm9StringRefEi;
     _Z22jl_malloc_data_pointerN4llvm9StringRefEi;
+    _jl_timing_*;
     LLVMExtra*;
     JLJIT*;
     llvmGetPassPluginInfo;

src/julia.h

@@ -1982,6 +1982,7 @@ JL_DLLEXPORT void jl_sigatomic_end(void);
 // tasks and exceptions -------------------------------------------------------
 
 typedef struct _jl_timing_block_t jl_timing_block_t;
+typedef struct _jl_timing_event_t jl_timing_event_t;
 typedef struct _jl_excstack_t jl_excstack_t;
 
 // info describing an exception handler

src/task.c

@@ -646,7 +646,7 @@ JL_DLLEXPORT void jl_switch(void) JL_NOTSAFEPOINT_LEAVE JL_NOTSAFEPOINT_ENTER
     int finalizers_inhibited = ptls->finalizers_inhibited;
     ptls->finalizers_inhibited = 0;
 
-    jl_timing_block_t *blk = jl_timing_block_exit_task(ct, ptls);
+    jl_timing_block_t *blk = jl_timing_block_task_exit(ct, ptls);
     ctx_switch(ct);
 
 #ifdef MIGRATE_TASKS
@@ -666,7 +666,7 @@ JL_DLLEXPORT void jl_switch(void) JL_NOTSAFEPOINT_LEAVE JL_NOTSAFEPOINT_ENTER
            0 != ct->ptls &&
            0 == ptls->finalizers_inhibited);
     ptls->finalizers_inhibited = finalizers_inhibited;
-    jl_timing_block_enter_task(ct, ptls, blk); (void)blk;
+    jl_timing_block_task_enter(ct, ptls, blk); (void)blk;
 
     sig_atomic_t other_defer_signal = ptls->defer_signal;
     ptls->defer_signal = defer_signal;
@@ -705,7 +705,7 @@ JL_DLLEXPORT JL_NORETURN void jl_no_exc_handler(jl_value_t *e, jl_task_t *ct)
 #define pop_timings_stack()                                                    \
         jl_timing_block_t *cur_block = ptls->timing_stack;                     \
         while (cur_block && eh->timing_stack != cur_block) {                   \
-            cur_block = jl_pop_timing_block(cur_block);                        \
+            cur_block = jl_timing_block_pop(cur_block);                        \
         }                                                                      \
         assert(cur_block == eh->timing_stack);
 #else
@@ -1084,7 +1084,7 @@ JL_DLLEXPORT jl_task_t *jl_new_task(jl_function_t *start, jl_value_t *completion
     t->ptls = NULL;
     t->world_age = ct->world_age;
     t->reentrant_timing = 0;
-    jl_timing_init_task(t);
+    jl_timing_task_init(t);
 
 #ifdef COPY_STACKS
     if (!t->copy_stack) {
@@ -1221,7 +1221,7 @@ CFI_NORETURN
 
     ct->started = 1;
     JL_PROBE_RT_START_TASK(ct);
-    jl_timing_block_enter_task(ct, ptls, NULL);
+    jl_timing_block_task_enter(ct, ptls, NULL);
     if (jl_atomic_load_relaxed(&ct->_isexception)) {
         record_backtrace(ptls, 0);
         jl_push_excstack(&ct->excstack, ct->result,
@@ -1693,7 +1693,7 @@ jl_task_t *jl_init_root_task(jl_ptls_t ptls, void *stack_lo, void *stack_hi)
     ct->ctx.asan_fake_stack = NULL;
 #endif
 
-    jl_timing_block_enter_task(ct, ptls, NULL);
+    jl_timing_block_task_enter(ct, ptls, NULL);
 
 #ifdef COPY_STACKS
     // initialize the base_ctx from which all future copy_stacks will be copies

src/timing.c

@@ -24,44 +24,47 @@ extern "C" {
 
 static uint64_t t0;
 
-JL_DLLEXPORT _Atomic(uint64_t) jl_timing_disable_mask[(JL_TIMING_LAST + sizeof(uint64_t) * CHAR_BIT - 1) / (sizeof(uint64_t) * CHAR_BIT)];
+JL_DLLEXPORT _Atomic(uint64_t) jl_timing_disable_mask[(JL_TIMING_SUBSYSTEM_LAST + sizeof(uint64_t) * CHAR_BIT - 1) / (sizeof(uint64_t) * CHAR_BIT)];
 
-JL_DLLEXPORT _Atomic(uint64_t) jl_timing_self_counts[(int)JL_TIMING_EVENT_LAST];
-JL_DLLEXPORT _Atomic(uint64_t) jl_timing_full_counts[(int)JL_TIMING_EVENT_LAST];
+static arraylist_t jl_timing_counts_events;
 
 // Used to as an item limit when several strings of metadata can
 // potentially be associated with a single timing zone.
 JL_DLLEXPORT uint32_t jl_timing_print_limit = 10;
 
-static const char *jl_timing_names[(int)JL_TIMING_EVENT_LAST] =
+const char *jl_timing_subsystems[(int)JL_TIMING_SUBSYSTEM_LAST] =
     {
 #define X(name) #name,
-        JL_TIMING_EVENTS
+        JL_TIMING_SUBSYSTEMS
 #undef X
     };
 
-static int jl_timing_names_sorted[(int)JL_TIMING_EVENT_LAST];
-
 JL_DLLEXPORT jl_timing_counter_t jl_timing_counters[JL_TIMING_COUNTER_LAST];
 
 void jl_print_timings(void)
 {
 #ifdef USE_TIMING_COUNTS
     uint64_t total_time = cycleclock() - t0;
     uint64_t root_time = total_time;
-    for (int i = 0; i < JL_TIMING_EVENT_LAST; i++) {
-        root_time -= jl_atomic_load_relaxed(jl_timing_self_counts + i);
+    for (int i = 0; i < jl_timing_counts_events.len; i++) {
+        jl_timing_counts_event_t *other_event = (jl_timing_counts_event_t *)jl_timing_counts_events.items[i];
+        root_time -= jl_atomic_load_relaxed(&other_event->self);
     }
-    jl_atomic_store_relaxed(jl_timing_self_counts + JL_TIMING_ROOT, root_time);
-    jl_atomic_store_relaxed(jl_timing_full_counts + JL_TIMING_ROOT, total_time);
+    jl_timing_counts_event_t *root_event = (jl_timing_counts_event_t *)jl_timing_counts_events.items[0];
+    jl_atomic_store_relaxed(&root_event->self, root_time);
+    jl_atomic_store_relaxed(&root_event->total, total_time);
+
     fprintf(stderr, "\nJULIA TIMINGS\n");
     fprintf(stderr, "%-25s, %-30s, %-30s\n", "Event", "Self Cycles (% of Total)", "Total Cycles (% of Total)");
-    for (int i = 0; i < JL_TIMING_EVENT_LAST; i++) {
-        int j = jl_timing_names_sorted[i];
-        uint64_t self = jl_atomic_load_relaxed(jl_timing_self_counts + j);
-        uint64_t total = jl_atomic_load_relaxed(jl_timing_full_counts + j);
+    for (int i = 0; i < jl_timing_counts_events.len; i++) {
+        jl_timing_counts_event_t *event = (jl_timing_counts_event_t *)jl_timing_counts_events.items[i];
+        uint64_t self = jl_atomic_load_relaxed(&event->self);
+        uint64_t total = jl_atomic_load_relaxed(&event->total);
         if (total != 0)
-            fprintf(stderr, "%-25s, %20" PRIu64 " (%5.2f %%), %20" PRIu64 " (%5.2f %%)\n", jl_timing_names[j], self, 100 * (((double)self) / total_time), total, 100 * (((double)total) / total_time));
+            fprintf(stderr, "%-25s, %20" PRIu64 " (%5.2f %%), %20" PRIu64 " (%5.2f %%)\n",
+                    event->name,
+                    self, 100 * (((double)self) / total_time),
+                    total, 100 * (((double)total) / total_time));
     }
 
     fprintf(stderr, "\nJULIA COUNTERS\n");
@@ -77,22 +80,32 @@ void jl_print_timings(void)
 #endif
 }
 
-int cmp_names(const void *a, const void *b) {
-    int ia = *(const int*)a;
-    int ib = *(const int*)b;
-    return strcmp(jl_timing_names[ia], jl_timing_names[ib]);
+static const int indirect_strcmp(const void *a, const void *b) {
+    return strcmp(*(const char **)a, *(const char **)b);
 }
 
 void jl_init_timing(void)
 {
     t0 = cycleclock();
 
-    _Static_assert((int)JL_TIMING_LAST <= (int)JL_TIMING_EVENT_LAST, "More owners than events!");
+    _Static_assert(JL_TIMING_SUBSYSTEM_LAST < sizeof(uint64_t) * CHAR_BIT, "Too many timing subsystems!");
 
-    for (int i = 0; i < JL_TIMING_EVENT_LAST; i++) {
-        jl_timing_names_sorted[i] = i;
-    }
-    qsort(jl_timing_names_sorted, JL_TIMING_EVENT_LAST, sizeof(int), cmp_names);
+#ifdef USE_TIMING_COUNTS
+    // Create events list for counts backend
+    arraylist_new(&jl_timing_counts_events, 1);
+
+    jl_timing_counts_event_t *new_event = (jl_timing_counts_event_t *)malloc(sizeof(jl_timing_counts_event_t));
+    arraylist_push(&jl_timing_counts_events, (void *)new_event);
+
+    new_event->name = "ROOT";
+    jl_atomic_store_relaxed(&new_event->total, 0);
+#endif
+
+    // Sort the subsystem names for quick enable/disable lookups
+    qsort(
+        jl_timing_subsystems, JL_TIMING_SUBSYSTEM_LAST,
+        sizeof(const char *), indirect_strcmp
+    );
 
     int i __attribute__((unused)) = 0;
 #ifdef USE_ITTAPI
@@ -142,18 +155,157 @@ void jl_destroy_timing(void)
     jl_ptls_t ptls = jl_current_task->ptls;
     jl_timing_block_t *stack = ptls->timing_stack;
     while (stack) {
-        _jl_timing_block_destroy(stack);
+        jl_timing_block_end(stack);
         stack = stack->prev;
     }
 }
 
-jl_timing_block_t *jl_pop_timing_block(jl_timing_block_t *cur_block)
+static const int get_timing_subsystem(const char *subsystem) {
+    const char **match = (const char **)bsearch(
+        &subsystem, jl_timing_subsystems, JL_TIMING_SUBSYSTEM_LAST,
+        sizeof(const char *), indirect_strcmp
+    );
+    if (!match)
+        return JL_TIMING_SUBSYSTEM_LAST;
+
+    return (int)(match - &jl_timing_subsystems[0]);
+}
+
+#ifdef USE_TIMING_COUNTS
+
+// This function is analogous to __itt_event_create but for the counts backend
+//
+// `event` is required to live forever
+static jl_timing_counts_event_t *_jl_timing_counts_event_create(const char *event) {
+    const size_t n = jl_timing_counts_events.len;
+    for (size_t i = 0; i < n; i++) {
+        jl_timing_counts_event_t *other_event = (jl_timing_counts_event_t *)jl_timing_counts_events.items[i];
+        if (strcmp(event, other_event->name) == 0)
+            return other_event;
+    }
+
+    // No matching event found - create a new one
+    jl_timing_counts_event_t *new_event = (jl_timing_counts_event_t *)malloc(sizeof(jl_timing_counts_event_t));
+    arraylist_push(&jl_timing_counts_events, (void *)new_event);
+    new_event->name = event;
+    jl_atomic_store_relaxed(&new_event->total, 0);
+    return new_event;
+}
+
+STATIC_INLINE void _jl_timing_counts_pause(jl_timing_counts_t *block, uint64_t t) JL_NOTSAFEPOINT {
+#ifdef JL_DEBUG_BUILD
+    assert(block->running);
+    block->running = 0;
+#endif
+    block->total += t - block->start;
+}
+
+STATIC_INLINE void _jl_timing_counts_resume(jl_timing_counts_t *block, uint64_t t) JL_NOTSAFEPOINT {
+#ifdef JL_DEBUG_BUILD
+    assert(!block->running);
+    block->running = 1;
+#endif
+    block->start = t;
+}
+
+STATIC_INLINE void _jl_timing_counts_start(jl_timing_counts_t *block, uint64_t t) JL_NOTSAFEPOINT {
+    block->total = 0;
+    block->start = t;
+    block->t0 = t;
+#ifdef JL_DEBUG_BUILD
+    block->running = 1;
+#endif
+}
+
+STATIC_INLINE void _jl_timing_counts_stop(jl_timing_block_t *block, uint64_t t) JL_NOTSAFEPOINT {
+#ifdef JL_DEBUG_BUILD
+    assert(block->counts_ctx.running);
+    block->counts_ctx.running = 0;
+#endif
+    jl_timing_counts_event_t *event = block->event->counts_event;
+    block->counts_ctx.total += t - block->counts_ctx.start;
+    jl_atomic_fetch_add_relaxed(&event->self, block->counts_ctx.total);
+    jl_atomic_fetch_add_relaxed(&event->total, t - block->counts_ctx.t0);
+}
+
+#endif // USE_TIMING_COUNTS
+
+JL_DLLEXPORT jl_timing_event_t *_jl_timing_event_create(const char *subsystem, const char *name, const char *function, const char *file, int line, int color) {
+    int maybe_subsystem = get_timing_subsystem(subsystem);
+    if (maybe_subsystem >= JL_TIMING_SUBSYSTEM_LAST) {
+        jl_errorf("invalid timing subsystem name: %s", subsystem);
+        return NULL;
+    }
+
+    jl_timing_event_t *event = (jl_timing_event_t *) malloc(sizeof(jl_timing_event_t));
+    event->subsystem = maybe_subsystem;
+
+#ifdef USE_TIMING_COUNTS
+    event->counts_event = _jl_timing_counts_event_create(name);
+#endif // USE_TIMING_COUNTS
+
+#ifdef USE_TRACY
+    event->tracy_srcloc.name = name;
+    event->tracy_srcloc.function = function;
+    event->tracy_srcloc.file = file;
+    event->tracy_srcloc.line = line;
+    event->tracy_srcloc.color = color;
+#endif // USE_TRACY
+
+#ifdef USE_ITTAPI
+    event->ittapi_event = __itt_event_create(name, strlen(name));
+#endif // USE_ITTAPI
+
+    return event;
+}
+
+JL_DLLEXPORT void _jl_timing_block_init(jl_timing_block_t *block, jl_timing_event_t *event) {
+    memset(block, 0, sizeof(*block));
+    block->event = event;
+}
+
+JL_DLLEXPORT void _jl_timing_block_start(jl_timing_block_t *block) {
+    assert(!block->is_running);
+    if (!_jl_timing_enabled(block->event->subsystem)) return;
+
+    uint64_t t = cycleclock(); (void)t;
+    _COUNTS_START(&block->counts_ctx, t);
+    _ITTAPI_START(block);
+    _TRACY_START(block);
+
+    jl_timing_block_t **prevp = &jl_current_task->ptls->timing_stack;
+    block->prev = *prevp;
+    block->is_running = 1;
+    if (block->prev) {
+        _COUNTS_PAUSE(&block->prev->counts_ctx, t);
+    }
+    *prevp = block;
+}
+
+JL_DLLEXPORT void _jl_timing_block_end(jl_timing_block_t *block) {
+    if (block->is_running) {
+        uint64_t t = cycleclock(); (void)t;
+        _ITTAPI_STOP(block);
+        _TRACY_STOP(block->tracy_ctx);
+        _COUNTS_STOP(block, t);
+
+        jl_task_t *ct = jl_current_task;
+        jl_timing_block_t **pcur = &ct->ptls->timing_stack;
+        assert(*pcur == block);
+        *pcur = block->prev;
+        if (block->prev) {
+            _COUNTS_RESUME(&block->prev->counts_ctx, t);
+        }
+    }
+}
+
+jl_timing_block_t *jl_timing_block_pop(jl_timing_block_t *cur_block)
 {
-    _jl_timing_block_destroy(cur_block);
+    jl_timing_block_end(cur_block);
     return cur_block->prev;
 }
 
-void jl_timing_block_enter_task(jl_task_t *ct, jl_ptls_t ptls, jl_timing_block_t *prev_blk)
+void jl_timing_block_task_enter(jl_task_t *ct, jl_ptls_t ptls, jl_timing_block_t *prev_blk)
 {
     if (prev_blk != NULL) {
         assert(ptls->timing_stack == NULL);
@@ -171,7 +323,7 @@ void jl_timing_block_enter_task(jl_task_t *ct, jl_ptls_t ptls, jl_timing_block_t
 #endif
 }
 
-jl_timing_block_t *jl_timing_block_exit_task(jl_task_t *ct, jl_ptls_t ptls)
+jl_timing_block_t *jl_timing_block_task_exit(jl_task_t *ct, jl_ptls_t ptls)
 {
 #ifdef USE_TRACY
     // Tracy is fairly strict about not leaving a fiber that hasn't
@@ -323,7 +475,7 @@ JL_DLLEXPORT void jl_timing_puts(jl_timing_block_t *cur_block, const char *str)
 #endif
 }
 
-void jl_timing_init_task(jl_task_t *t)
+void jl_timing_task_init(jl_task_t *t)
 {
 #ifdef USE_TRACY
     jl_value_t *start_type = jl_typeof(t->start);
@@ -359,20 +511,12 @@ void jl_timing_init_task(jl_task_t *t)
 #endif
 }
 
-int cmp_name_idx(const void *name, const void *idx) {
-    return strcmp((const char *)name, jl_timing_names[*(const int *)idx]);
-}
-
 JL_DLLEXPORT int jl_timing_set_enable(const char *subsystem, uint8_t enabled)
 {
-    const int *idx = (const int *)bsearch(subsystem, jl_timing_names_sorted, JL_TIMING_EVENT_LAST, sizeof(int), cmp_name_idx);
-    if (idx == NULL)
-        return -1;
-    int i = *idx;
-    // sorted names include events, so skip if we're looking at an event instead of a subsystem
-    // events are always at least JL_TIMING_LAST
-    if (i >= JL_TIMING_LAST)
+    int i = get_timing_subsystem(subsystem);
+    if (i >= JL_TIMING_SUBSYSTEM_LAST)
         return -1;
+
     uint64_t subsystem_bit = 1ul << (i % (sizeof(uint64_t) * CHAR_BIT));
     if (enabled) {
         jl_atomic_fetch_and_relaxed(jl_timing_disable_mask + (i / (sizeof(uint64_t) * CHAR_BIT)), ~subsystem_bit);
@@ -445,6 +589,13 @@ void jl_timing_apply_env(void)
 
 void jl_init_timing(void) { }
 void jl_destroy_timing(void) { }
+
+JL_DLLEXPORT jl_timing_event_t *_jl_timing_event_create(const char *subsystem, const char *name, const char *function, const char *file, int line, int color) { return NULL; }
+
+JL_DLLEXPORT void _jl_timing_block_init(jl_timing_block_t *block, jl_timing_event_t *event) { }
+JL_DLLEXPORT void _jl_timing_block_start(jl_timing_block_t *block) { }
+JL_DLLEXPORT void _jl_timing_block_end(jl_timing_block_t *block) { }
+
 JL_DLLEXPORT int jl_timing_set_enable(const char *subsystem, uint8_t enabled) { return -1; }
 JL_DLLEXPORT uint32_t jl_timing_print_limit = 0;