From 456cbea36cab0891189d7eebaab35d7cc918252b Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 11:28:46 -0500 Subject: [PATCH 01/14] basic task cpu time tracking --- src/julia.h | 5 +++++ src/task.c | 3 +++ 2 files changed, 8 insertions(+) diff --git a/src/julia.h b/src/julia.h index 03efa773d026c..b8c313bcc1558 100644 --- a/src/julia.h +++ b/src/julia.h @@ -1928,6 +1928,11 @@ typedef struct _jl_task_t { _Atomic(uint8_t) _isexception; // set if `result` is an exception to throw or that we exited with // multiqueue priority uint16_t priority; + + // CPU time tracking + // TODO: int32 of ms instead? + uint64_t last_scheduled_ns; // timestamp this task was last scheduled (TODO: move to hidden?) + uint64_t cpu_time_ns; // time this task has spent running; updated when it yields // hidden state: // id of owning thread - does not need to be defined until the task runs diff --git a/src/task.c b/src/task.c index 7373de937b9ae..a94b436067013 100644 --- a/src/task.c +++ b/src/task.c @@ -640,6 +640,7 @@ JL_DLLEXPORT void jl_switch(void) JL_NOTSAFEPOINT_LEAVE JL_NOTSAFEPOINT_ENTER jl_error("cannot switch to task running on another thread"); JL_PROBE_RT_PAUSE_TASK(ct); + ct->cpu_time_ns += jl_hrtime() - ct->last_scheduled_ns; // Store old values on the stack and reset sig_atomic_t defer_signal = ptls->defer_signal; @@ -688,6 +689,8 @@ JL_DLLEXPORT void jl_switch(void) JL_NOTSAFEPOINT_LEAVE JL_NOTSAFEPOINT_ENTER jl_sigint_safepoint(ptls); JL_PROBE_RT_RUN_TASK(ct); + ct->last_scheduled_ns = jl_hrtime(); + jl_gc_unsafe_leave(ptls, gc_state); } From e535d4026318610a2074e3b0df0ff723b2ac93e6 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 11:46:59 -0500 Subject: [PATCH 02/14] initialize to zero --- src/task.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/task.c b/src/task.c index a94b436067013..52de057730bba 100644 --- a/src/task.c +++ b/src/task.c @@ -945,6 +945,8 @@ JL_DLLEXPORT jl_task_t *jl_new_task(jl_function_t *start, jl_value_t *completion t->reentrant_timing = 0; t->reentrant_inference = 0; t->inference_start_time = 0; + t->last_scheduled_ns = 0; + t->cpu_time_ns = 0; #ifdef COPY_STACKS if (!t->copy_stack) { @@ -1533,6 +1535,8 @@ jl_task_t *jl_init_root_task(jl_ptls_t ptls, void *stack_lo, void *stack_hi) ct->reentrant_timing = 0; ct->reentrant_inference = 0; ct->inference_start_time = 0; + ct->last_scheduled_ns = 0; + ct->cpu_time_ns = 0; ptls->root_task = ct; jl_atomic_store_relaxed(&ptls->current_task, ct); JL_GC_PROMISE_ROOTED(ct); From 7bc1ce8a452139adb489895d571a8d1bb6851107 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 12:01:22 -0500 Subject: [PATCH 03/14] make new task field visible from Julia --- src/jltypes.c | 6 ++++-- src/julia.h | 5 ++--- 2 files changed, 6 insertions(+), 5 deletions(-) diff --git a/src/jltypes.c b/src/jltypes.c index 9428bf6a91092..12039be006c66 100644 --- a/src/jltypes.c +++ b/src/jltypes.c @@ -2707,7 +2707,8 @@ void jl_init_types(void) JL_GC_DISABLED "_state", "sticky", "_isexception", - "priority"), + "priority", + "cpu_time_ns"), jl_svec(15, jl_any_type, jl_any_type, @@ -2723,7 +2724,8 @@ void jl_init_types(void) JL_GC_DISABLED jl_uint8_type, jl_bool_type, jl_bool_type, - jl_uint16_type), + jl_uint16_type, + jl_uint64_type), jl_emptysvec, 0, 1, 6); jl_value_t *listt = jl_new_struct(jl_uniontype_type, jl_task_type, jl_nothing_type); diff --git a/src/julia.h b/src/julia.h index b8c313bcc1558..b280f3690c56d 100644 --- a/src/julia.h +++ b/src/julia.h @@ -1928,13 +1928,12 @@ typedef struct _jl_task_t { _Atomic(uint8_t) _isexception; // set if `result` is an exception to throw or that we exited with // multiqueue priority uint16_t priority; - - // CPU time tracking // TODO: int32 of ms instead? - uint64_t last_scheduled_ns; // timestamp this task was last scheduled (TODO: move to hidden?) uint64_t cpu_time_ns; // time this task has spent running; updated when it yields // hidden state: + // timestamp this task was last scheduled (TODO: int32 of ms instead?) + uint64_t last_scheduled_ns; // id of owning thread - does not need to be defined until the task runs _Atomic(int16_t) tid; // threadpool id From 48db9cec277c07bac2001645265765400ec11af5 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 12:08:26 -0500 Subject: [PATCH 04/14] bump svec size --- src/jltypes.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/jltypes.c b/src/jltypes.c index 12039be006c66..61e57adae78e0 100644 --- a/src/jltypes.c +++ b/src/jltypes.c @@ -2692,7 +2692,7 @@ void jl_init_types(void) JL_GC_DISABLED NULL, jl_any_type, jl_emptysvec, - jl_perm_symsvec(15, + jl_perm_symsvec(16, "next", "queue", "storage", @@ -2709,7 +2709,7 @@ void jl_init_types(void) JL_GC_DISABLED "_isexception", "priority", "cpu_time_ns"), - jl_svec(15, + jl_svec(16, jl_any_type, jl_any_type, jl_any_type, From 21adfe31a080ae66ea59dbad7885789d99a94440 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 12:15:37 -0500 Subject: [PATCH 05/14] add start time --- src/task.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/task.c b/src/task.c index 52de057730bba..be212c457804a 100644 --- a/src/task.c +++ b/src/task.c @@ -294,6 +294,7 @@ void JL_NORETURN jl_finish_task(jl_task_t *t) { jl_task_t *ct = jl_current_task; JL_PROBE_RT_FINISH_TASK(ct); + ct->cpu_time_ns += jl_hrtime() - ct->last_scheduled_time_ns; JL_SIGATOMIC_BEGIN(); if (jl_atomic_load_relaxed(&t->_isexception)) jl_atomic_store_release(&t->_state, JL_TASK_STATE_FAILED); @@ -1082,6 +1083,7 @@ CFI_NORETURN ct->started = 1; JL_PROBE_RT_START_TASK(ct); + ct->last_scheduled_ns = jl_hrtime(); if (jl_atomic_load_relaxed(&ct->_isexception)) { record_backtrace(ptls, 0); jl_push_excstack(&ct->excstack, ct->result, From cd35d07416f9c1b74b784e3e7d4d30131a3fae9c Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 12:16:40 -0500 Subject: [PATCH 06/14] fix typo --- src/task.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/task.c b/src/task.c index be212c457804a..268faf367023a 100644 --- a/src/task.c +++ b/src/task.c @@ -294,7 +294,7 @@ void JL_NORETURN jl_finish_task(jl_task_t *t) { jl_task_t *ct = jl_current_task; JL_PROBE_RT_FINISH_TASK(ct); - ct->cpu_time_ns += jl_hrtime() - ct->last_scheduled_time_ns; + ct->cpu_time_ns += jl_hrtime() - ct->last_scheduled_ns; JL_SIGATOMIC_BEGIN(); if (jl_atomic_load_relaxed(&t->_isexception)) jl_atomic_store_release(&t->_state, JL_TASK_STATE_FAILED); From bee0588f031657eb19ab1df2016b942258ebc17d Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 14:51:18 -0500 Subject: [PATCH 07/14] trailing whitespace --- src/task.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/task.c b/src/task.c index 268faf367023a..5fa0a9ba7b1c4 100644 --- a/src/task.c +++ b/src/task.c @@ -691,7 +691,7 @@ JL_DLLEXPORT void jl_switch(void) JL_NOTSAFEPOINT_LEAVE JL_NOTSAFEPOINT_ENTER JL_PROBE_RT_RUN_TASK(ct); ct->last_scheduled_ns = jl_hrtime(); - + jl_gc_unsafe_leave(ptls, gc_state); } From c52a151b4afbefe922452c885298091036d142b6 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 15:12:00 -0500 Subject: [PATCH 08/14] add test --- test/threads_exec.jl | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/test/threads_exec.jl b/test/threads_exec.jl index 68ba9377cf955..dfb4d67379d33 100644 --- a/test/threads_exec.jl +++ b/test/threads_exec.jl @@ -1067,3 +1067,10 @@ end popfirst!(LOAD_PATH) end end + +@testset "CPU time counter" begin + t = Threads.@spawn begin + peakflops() + end + @test t.cpu_time_ns > 0 +end From 540dd767d3c3eb390027a3a368de45d46808409b Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 18:25:52 -0500 Subject: [PATCH 09/14] add a wait --- test/threads_exec.jl | 1 + 1 file changed, 1 insertion(+) diff --git a/test/threads_exec.jl b/test/threads_exec.jl index dfb4d67379d33..3e54b515683e8 100644 --- a/test/threads_exec.jl +++ b/test/threads_exec.jl @@ -1072,5 +1072,6 @@ end t = Threads.@spawn begin peakflops() end + wait(t) @test t.cpu_time_ns > 0 end From 0e2f7b01c7be167f0d6ec036e75ee07e5170faca Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Thu, 26 Jan 2023 20:35:17 -0500 Subject: [PATCH 10/14] import `LinearAlgebra` for `peakflops` --- test/threads_exec.jl | 1 + 1 file changed, 1 insertion(+) diff --git a/test/threads_exec.jl b/test/threads_exec.jl index 3e54b515683e8..9bfcf7fbcf80d 100644 --- a/test/threads_exec.jl +++ b/test/threads_exec.jl @@ -3,6 +3,7 @@ using Test using Base.Threads using Base.Threads: SpinLock, threadpoolsize +using LinearAlgebra: peakflops # for cfunction_closure include("testenv.jl") From c1bfce1bbe1961b2fe5603292bf0b35fc1c2713b Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Tue, 31 Jan 2023 10:05:35 -0500 Subject: [PATCH 11/14] update last scheduled on task finish as well --- src/task.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/task.c b/src/task.c index 5fa0a9ba7b1c4..464917fe80b2f 100644 --- a/src/task.c +++ b/src/task.c @@ -294,7 +294,9 @@ void JL_NORETURN jl_finish_task(jl_task_t *t) { jl_task_t *ct = jl_current_task; JL_PROBE_RT_FINISH_TASK(ct); - ct->cpu_time_ns += jl_hrtime() - ct->last_scheduled_ns; + uint64_t now = jl_hrtime(); + ct->cpu_time_ns += now - ct->last_scheduled_ns; + ct->last_scheduled_ns = now; JL_SIGATOMIC_BEGIN(); if (jl_atomic_load_relaxed(&t->_isexception)) jl_atomic_store_release(&t->_state, JL_TASK_STATE_FAILED); From f6c90a8499c9743a5b9b3604dff21fb5e0986f80 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Fri, 3 Feb 2023 10:06:55 -0600 Subject: [PATCH 12/14] no need to update last scheduled in finish --- src/task.c | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/task.c b/src/task.c index 464917fe80b2f..5fa0a9ba7b1c4 100644 --- a/src/task.c +++ b/src/task.c @@ -294,9 +294,7 @@ void JL_NORETURN jl_finish_task(jl_task_t *t) { jl_task_t *ct = jl_current_task; JL_PROBE_RT_FINISH_TASK(ct); - uint64_t now = jl_hrtime(); - ct->cpu_time_ns += now - ct->last_scheduled_ns; - ct->last_scheduled_ns = now; + ct->cpu_time_ns += jl_hrtime() - ct->last_scheduled_ns; JL_SIGATOMIC_BEGIN(); if (jl_atomic_load_relaxed(&t->_isexception)) jl_atomic_store_release(&t->_state, JL_TASK_STATE_FAILED); From edaebfb635f3513e864ed19e6c45665131fd49d5 Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Fri, 23 Jun 2023 12:11:29 -0400 Subject: [PATCH 13/14] add test --- test/threads_exec.jl | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/test/threads_exec.jl b/test/threads_exec.jl index 9bfcf7fbcf80d..2e65cd1ebe882 100644 --- a/test/threads_exec.jl +++ b/test/threads_exec.jl @@ -1076,3 +1076,24 @@ end wait(t) @test t.cpu_time_ns > 0 end + +@testset "CPU time counter: lots of spawns" begin + using Base.Threads, Dates + # create more tasks than we have cores + # the wall time each task gets should be less + @sync begin + for i in 1:1000 + start_time = now() + task = @spawn begin + peakflops() + end + @spawn begin + wait(task) + end_time = now() + time_delta = end_time - start_time + cpu_time = Nanosecond(task.cpu_time_ns) + @test cpu_time < time_delta + end + end + end +end From a909a7c38d97fef753b69febd5a0bfaabeaae4ba Mon Sep 17 00:00:00 2001 From: Pete Vilter Date: Fri, 23 Jun 2023 12:28:22 -0400 Subject: [PATCH 14/14] fix test --- test/threads_exec.jl | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/test/threads_exec.jl b/test/threads_exec.jl index 2e65cd1ebe882..8269443d05153 100644 --- a/test/threads_exec.jl +++ b/test/threads_exec.jl @@ -1080,9 +1080,10 @@ end @testset "CPU time counter: lots of spawns" begin using Base.Threads, Dates # create more tasks than we have cores - # the wall time each task gets should be less + # the CPU time each task gets should be less + # than the wall time @sync begin - for i in 1:1000 + for i in 1:100 start_time = now() task = @spawn begin peakflops() @@ -1090,9 +1091,9 @@ end @spawn begin wait(task) end_time = now() - time_delta = end_time - start_time + wall_time_delta = end_time - start_time cpu_time = Nanosecond(task.cpu_time_ns) - @test cpu_time < time_delta + @test cpu_time < wall_time_delta end end end