WIP thread cpu time

base/locks-mt.jl

@@ -39,8 +39,10 @@ end
 Base.assert_havelock(l::SpinLock) = islocked(l) ? nothing : Base.concurrency_violation()
 
 function lock(l::SpinLock)
+    # t0 = time_ns()
     while true
         if @inline trylock(l)
+            # ccall(:jl_record_lock_spin_time, Cvoid, (Culonglong,), time_ns() - t0)
             return
         end
         ccall(:jl_cpu_suspend, Cvoid, ())

base/timing.jl

@@ -114,6 +114,32 @@ function jit_total_bytes()
     return ccall(:jl_jit_total_bytes, Csize_t, ())
 end
 
+thread_up_time() = ccall(:jl_thread_up_time, UInt64, ())
+
+_unsafe_thread_user_time(tid::Integer) = ccall(:jl_thread_user_time, UInt64, (Cint,), Cint(tid))
+
+function thread_user_time(tid::Integer)
+    max_tid = Threads.threadpoolsize(:interactive) + Threads.threadpoolsize(:default)
+    0 < tid ≤ max_tid || throw(ArgumentError("invalid thread id `$(tid)`"))
+    return _unsafe_thread_user_time(tid)
+end
+
+function thread_user_time(pool::Symbol=:all)
+    total = UInt64(0)
+    pool in (:all, :default, :interactive) || throw(ArgumentError("invalid threadpool `$(repr(pool))`"))
+    if pool === :all || pool === :default
+        for tid in Threads.threadpooltids(:default)
+            total += _unsafe_thread_user_time(tid)
+        end
+    end
+    if pool === :all || pool === :interactive
+        for tid in Threads.threadpooltids(:interactive)
+            total += _unsafe_thread_user_time(tid)
+        end
+    end
+    return total
+end
+
 # print elapsed time, return expression value
 const _mem_units = ["byte", "KiB", "MiB", "GiB", "TiB", "PiB"]
 const _cnt_units = ["", " k", " M", " G", " T", " P"]

src/gc.c

@@ -3741,7 +3741,7 @@ JL_DLLEXPORT void jl_gc_collect(jl_gc_collection_t collection)
     int8_t old_state = jl_atomic_load_relaxed(&ptls->gc_state);
     jl_atomic_store_release(&ptls->gc_state, JL_GC_STATE_WAITING);
     // `jl_safepoint_start_gc()` makes sure only one thread can run the GC.
-    uint64_t t0 = jl_hrtime();
+    uint64_t t0 = jl_hrtime(); // time we entered GC
     if (!jl_safepoint_start_gc()) {
         // either another thread is running GC, or the GC got disabled just now.
         jl_gc_state_set(ptls, old_state, JL_GC_STATE_WAITING);
@@ -3770,7 +3770,7 @@ JL_DLLEXPORT void jl_gc_collect(jl_gc_collection_t collection)
     jl_gc_wait_for_the_world(gc_all_tls_states, gc_n_threads);
     JL_PROBE_GC_STOP_THE_WORLD();
 
-    uint64_t t1 = jl_hrtime();
+    uint64_t t1 = jl_hrtime();  // time user code stopped running
     uint64_t duration = t1 - t0;
     if (duration > gc_num.max_time_to_safepoint)
         gc_num.max_time_to_safepoint = duration;
@@ -3798,6 +3798,8 @@ JL_DLLEXPORT void jl_gc_collect(jl_gc_collection_t collection)
     jl_safepoint_end_gc();
     jl_gc_state_set(ptls, old_state, JL_GC_STATE_WAITING);
     JL_PROBE_GC_END();
+    // Time how long GC took.
+    ptls->timing_tls.gc_time += jl_hrtime() - t1;
 
     // Only disable finalizers on current thread
     // Doing this on all threads is racy (it's impossible to check

src/julia_threads.h

@@ -124,6 +124,14 @@ typedef struct {
 
 struct _jl_bt_element_t;
 
+typedef struct {
+    uint64_t start_time;
+    uint64_t sleep_time;
+    uint64_t scheduler_time;
+    /* uint64_t lock_spin_time; */
+    uint64_t gc_time;
+} jl_timing_tls_states_t;
+
 // This includes all the thread local states we care about for a thread.
 // Changes to TLS field types must be reflected in codegen.
 #define JL_MAX_BT_SIZE 80000
@@ -155,6 +163,7 @@ typedef struct _jl_tls_states_t {
     // Counter to disable finalizer **on the current thread**
     int finalizers_inhibited;
     jl_gc_tls_states_t gc_tls; // this is very large, and the offset of the first member is baked into codegen
+    jl_timing_tls_states_t timing_tls;
     volatile sig_atomic_t defer_signal;
     _Atomic(struct _jl_task_t*) current_task;
     struct _jl_task_t *next_task;

src/partr.c

@@ -389,12 +389,14 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q,
 {
     jl_task_t *ct = jl_current_task;
     uint64_t start_cycles = 0;
-
+    uint64_t t0 = jl_hrtime();
     while (1) {
+        jl_ptls_t ptls = ct->ptls;
         jl_task_t *task = get_next_task(trypoptask, q);
-        if (task)
+        if (task) {
+            ptls->timing_tls.scheduler_time += jl_hrtime() - t0;
             return task;
-
+        }
         // quick, race-y check to see if there seems to be any stuff in there
         jl_cpu_pause();
         if (!check_empty(checkempty)) {
@@ -403,7 +405,6 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q,
         }
 
         jl_cpu_pause();
-        jl_ptls_t ptls = ct->ptls;
         if (sleep_check_after_threshold(&start_cycles) || (ptls->tid == 0 && (!jl_atomic_load_relaxed(&_threadedregion) || wait_empty))) {
             // acquire sleep-check lock
             jl_atomic_store_relaxed(&ptls->sleep_check_state, sleeping);
@@ -425,6 +426,7 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q,
                     JL_PROBE_RT_SLEEP_CHECK_TASK_WAKE(ptls);
                 }
                 if (task)
+                    ptls->timing_tls.scheduler_time += jl_hrtime() - t0;
                     return task;
                 continue;
             }
@@ -433,6 +435,7 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q,
                     jl_atomic_store_relaxed(&ptls->sleep_check_state, not_sleeping); // let other threads know they don't need to wake us
                     JL_PROBE_RT_SLEEP_CHECK_TASK_WAKE(ptls);
                 }
+                ptls->timing_tls.scheduler_time += jl_hrtime() - t0;
                 return task;
             }
 
@@ -507,6 +510,7 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q,
 
             // the other threads will just wait for an individual wake signal to resume
             JULIA_DEBUG_SLEEPWAKE( ptls->sleep_enter = cycleclock() );
+            uint64_t tsleep0 = jl_hrtime();
             int8_t gc_state = jl_gc_safe_enter(ptls);
             uv_mutex_lock(&ptls->sleep_lock);
             while (may_sleep(ptls)) {
@@ -523,6 +527,7 @@ JL_DLLEXPORT jl_task_t *jl_task_get_next(jl_value_t *trypoptask, jl_value_t *q,
             assert(jl_atomic_load_relaxed(&ptls->sleep_check_state) == not_sleeping);
             uv_mutex_unlock(&ptls->sleep_lock);
             JULIA_DEBUG_SLEEPWAKE( ptls->sleep_leave = cycleclock() );
+            ptls->timing_tls.sleep_time += jl_hrtime() - tsleep0;
             jl_gc_safe_leave(ptls, gc_state); // contains jl_gc_safepoint
             start_cycles = 0;
             if (task) {

src/safepoint.c

@@ -161,7 +161,10 @@ void jl_safepoint_wait_gc(void)
     jl_task_t *ct = jl_current_task; (void)ct;
     JL_TIMING_SUSPEND_TASK(GC_SAFEPOINT, ct);
     // The thread should have set this is already
-    assert(jl_atomic_load_relaxed(&ct->ptls->gc_state) != 0);
+    jl_ptls_t ptls = ct->ptls;
+    assert(jl_atomic_load_relaxed(&ptls->gc_state) != 0);
+    // Time how long this thread is stopped while GC is running.
+    uint64_t t0 = jl_hrtime();
     // Use normal volatile load in the loop for speed until GC finishes.
     // Then use an acquire load to make sure the GC result is visible on this thread.
     while (jl_atomic_load_relaxed(&jl_gc_running) || jl_atomic_load_acquire(&jl_gc_running)) {
@@ -173,6 +176,7 @@ void jl_safepoint_wait_gc(void)
             uv_cond_wait(&safepoint_cond, &safepoint_lock);
         uv_mutex_unlock(&safepoint_lock);
     }
+    ptls->timing_tls.gc_time = jl_hrtime() - t0;
 }
 
 void jl_safepoint_enable_sigint(void)

src/threading.c

@@ -49,6 +49,24 @@ JL_DLLEXPORT _Atomic(uint8_t) jl_measure_compile_time_enabled = 0;
 JL_DLLEXPORT _Atomic(uint64_t) jl_cumulative_compile_time = 0;
 JL_DLLEXPORT _Atomic(uint64_t) jl_cumulative_recompile_time = 0;
 
+static uint64_t jl_thread_start_time;
+void jl_set_thread_start_time(void)
+{
+    jl_thread_start_time = jl_hrtime();
+}
+
+// TODO: not just current thread
+JL_DLLEXPORT uint64_t jl_thread_up_time(void)
+{
+    return jl_hrtime() - jl_thread_start_time;
+}
+JL_DLLEXPORT uint64_t jl_thread_user_time(uint8_t tid)
+{
+    jl_ptls_t ptls = jl_atomic_load_relaxed(&jl_all_tls_states)[tid];
+    jl_timing_tls_states_t *timing = &ptls->timing_tls;
+    return jl_thread_up_time() - timing->gc_time - timing->scheduler_time;
+}
+
 JL_DLLEXPORT void *jl_get_ptls_states(void)
 {
     // mostly deprecated: use current_task instead
@@ -765,6 +783,7 @@ void jl_start_threads(void)
         }
         uv_thread_detach(&uvtid);
     }
+    jl_set_thread_start_time();
 }
 
 _Atomic(unsigned) _threadedregion; // HACK: keep track of whether to prioritize IO or threading
@@ -794,6 +813,13 @@ JL_DLLEXPORT void jl_exit_threaded_region(void)
 
 // Profiling stubs
 
+/* JL_DLLEXPORT void jl_record_lock_spin_time(uint64_t time) JL_NOTSAFEPOINT */
+/* { */
+/*     jl_task_t *ct = jl_current_task; */
+/*     jl_ptls_t ptls = ct->ptls; */
+/*     ptls->timing_tls.lock_spin_time += time; */
+/* } */
+
 void _jl_mutex_init(jl_mutex_t *lock, const char *name) JL_NOTSAFEPOINT
 {
     jl_atomic_store_relaxed(&lock->owner, (jl_task_t*)NULL);
@@ -816,10 +842,12 @@ void _jl_mutex_wait(jl_task_t *self, jl_mutex_t *lock, int safepoint)
         return;
     }
     JL_TIMING(LOCK_SPIN, LOCK_SPIN);
+    /* uint64_t t0 = jl_hrtime(); */
     while (1) {
         if (owner == NULL && jl_atomic_cmpswap(&lock->owner, &owner, self)) {
             lock->count = 1;
             jl_profile_lock_acquired(lock);
+            /* jl_record_lock_spin_time(jl_hrtime() - t0); */
             return;
         }
         if (safepoint) {
@@ -919,7 +947,6 @@ void _jl_mutex_unlock(jl_task_t *self, jl_mutex_t *lock)
     }
 }
 
-
 // Make gc alignment available for threading
 // see threads.jl alignment
 JL_DLLEXPORT int jl_alignment(size_t sz)

src/threading.h

@@ -30,6 +30,7 @@ void jl_init_threadinginfra(void);
 void jl_parallel_gc_threadfun(void *arg);
 void jl_concurrent_gc_threadfun(void *arg);
 void jl_threadfun(void *arg);
+void jl_set_thread_start_time(void);
 
 #ifdef __cplusplus
 }