From 262b0e5e52067b40e8b8f6396927d3cc1b6ae680 Mon Sep 17 00:00:00 2001 From: Cory McWilliams Date: Wed, 1 Mar 2023 01:36:26 +0000 Subject: [PATCH] Attempt to track CPU usage of libuv worker threads. git-svn-id: https://www.unprompted.com/svn/projects/tildefriends/trunk@4198 ed5197a5-7fde-0310-b194-c3ffbd925b24 --- core/client.js | 3 +++ src/ssb.c | 42 ++++++++++++++++++++++++++++++++++++++++++ src/ssb.h | 3 +++ src/ssb.js.c | 7 +++++++ src/task.c | 10 +++++++++- 5 files changed, 64 insertions(+), 1 deletion(-) diff --git a/core/client.js b/core/client.js index fa3d2845..9c0bf4c6 100644 --- a/core/client.js +++ b/core/client.js @@ -544,6 +544,9 @@ function _receive_websocket_message(message) { rpc_in: {group: 'rpc', name: 'in'}, rpc_out: {group: 'rpc', name: 'out'}, + cpu_percent: {group: 'cpu', name: 'main'}, + thread_percent: {group: 'cpu', name: 'work'}, + arena_percent: {group: 'memory', name: 'm'}, js_malloc_percent: {group: 'memory', name: 'js'}, memory_percent: {group: 'memory', name: 'tot'}, diff --git a/src/ssb.c b/src/ssb.c index ee990710..7e9b428d 100644 --- a/src/ssb.c +++ b/src/ssb.c @@ -160,6 +160,12 @@ typedef struct _tf_ssb_broadcasts_changed_callback_node_t tf_ssb_broadcasts_changed_callback_node_t* next; } tf_ssb_broadcasts_changed_callback_node_t; +typedef struct _tf_thread_work_time_t +{ + int64_t thread_id; + uint64_t hrtime; +} tf_thread_work_time_t; + typedef struct _tf_ssb_t { bool own_context; @@ -219,6 +225,9 @@ typedef struct _tf_ssb_t int broadcasts_changed_count; tf_ssb_debug_close_t debug_close[k_debug_close_connection_count]; + + tf_thread_work_time_t* thread_time; + int thread_time_count; } tf_ssb_t; typedef struct _tf_ssb_connection_message_request_t @@ -3418,3 +3427,36 @@ JSValue tf_ssb_get_disconnection_debug(tf_ssb_t* ssb, JSContext* context) JS_SetPropertyStr(context, result, "disconnections", disconnections); return result; } + +void tf_ssb_record_thread_time(tf_ssb_t* ssb, int64_t thread_id, uint64_t hrtime) +{ + for (int i = 0; i < ssb->thread_time_count; i++) + { + if (ssb->thread_time[i].thread_id == thread_id) + { + ssb->thread_time[i].hrtime += hrtime; + return; + } + } + ssb->thread_time = tf_resize_vec(ssb->thread_time, sizeof(tf_thread_work_time_t) * (ssb->thread_time_count + 1)); + ssb->thread_time[ssb->thread_time_count++] = (tf_thread_work_time_t) + { + .thread_id = thread_id, + .hrtime = hrtime, + }; +} + +uint64_t tf_ssb_get_average_thread_time(tf_ssb_t* ssb) +{ + if (!ssb) + { + return 0; + } + + uint64_t total = 0; + for (int i = 0; i < ssb->thread_time_count; i++) + { + total += ssb->thread_time[i].hrtime; + } + return ssb->thread_time_count ? total / ssb->thread_time_count : 0; +} diff --git a/src/ssb.h b/src/ssb.h index 377c48d2..989576e2 100644 --- a/src/ssb.h +++ b/src/ssb.h @@ -186,3 +186,6 @@ void tf_ssb_get_stats(tf_ssb_t* ssb, tf_ssb_stats_t* out_stats); tf_ssb_blob_wants_t* tf_ssb_connection_get_blob_wants_state(tf_ssb_connection_t* connection); JSValue tf_ssb_get_disconnection_debug(tf_ssb_t* ssb, JSContext* context); + +void tf_ssb_record_thread_time(tf_ssb_t* ssb, int64_t thread_id, uint64_t hrtime); +uint64_t tf_ssb_get_average_thread_time(tf_ssb_t* ssb); diff --git a/src/ssb.js.c b/src/ssb.js.c index cf7f7ac9..1b1b1669 100644 --- a/src/ssb.js.c +++ b/src/ssb.js.c @@ -343,6 +343,9 @@ typedef struct _sql_work_t { uv_work_t request; tf_ssb_t* ssb; + uv_thread_t thread_id; + uint64_t start_time; + uint64_t end_time; const char* query; uint8_t* binds; size_t binds_count; @@ -364,6 +367,8 @@ static void _tf_ssb_sql_append(uint8_t** rows, size_t* rows_count, const void* d static void _tf_ssb_sqlAsync_work(uv_work_t* work) { sql_work_t* sql_work = work->data; + sql_work->start_time = uv_hrtime(); + sql_work->thread_id = uv_thread_self(); sqlite3* db = tf_ssb_acquire_db_reader(sql_work->ssb); sqlite3_stmt* statement = NULL; sql_work->result = sqlite3_prepare(db, sql_work->query, -1, &statement, NULL); @@ -459,11 +464,13 @@ static void _tf_ssb_sqlAsync_work(uv_work_t* work) sql_work->error = tf_strdup(sqlite3_errmsg(db)); } tf_ssb_release_db_reader(sql_work->ssb, db); + sql_work->end_time = uv_hrtime(); } static void _tf_ssb_sqlAsync_after_work(uv_work_t* work, int status) { sql_work_t* sql_work = work->data; + tf_ssb_record_thread_time(sql_work->ssb, (int64_t)sql_work->thread_id, sql_work->end_time - sql_work->start_time); JSContext* context = tf_ssb_get_context(sql_work->ssb); uint8_t* p = sql_work->rows; while (p < sql_work->rows + sql_work->rows_count) diff --git a/src/task.c b/src/task.c index 01b7d0ed..e306a75a 100644 --- a/src/task.c +++ b/src/task.c @@ -103,7 +103,9 @@ typedef struct _tf_task_t uv_timer_t trace_timer; uint64_t last_hrtime; uint64_t last_idle_time; + uint64_t last_thread_time; float idle_percent; + float thread_percent; uv_idle_t idle; uv_prepare_t prepare; @@ -720,7 +722,8 @@ static JSValue _tf_task_getStats(JSContext* context, JSValueConst this_val, int JS_SetPropertyStr(context, result, "export_count", JS_NewInt32(context, task->_export_count)); JS_SetPropertyStr(context, result, "promise_count", JS_NewInt32(context, task->_promise_count)); - JS_SetPropertyStr(context, result, "idle_percent", JS_NewFloat64(context, task->idle_percent)); + JS_SetPropertyStr(context, result, "cpu_percent", JS_NewFloat64(context, 100.0f - task->idle_percent)); + JS_SetPropertyStr(context, result, "thread_percent", JS_NewFloat64(context, task->thread_percent)); uint64_t total_memory = uv_get_total_memory(); size_t rss; @@ -1373,9 +1376,12 @@ static void _tf_task_trace_timer(uv_timer_t* timer) tf_task_t* task = timer->data; uint64_t hrtime = uv_hrtime(); uint64_t idle_time = uv_metrics_idle_time(&task->_loop); + uint64_t thread_time = tf_ssb_get_average_thread_time(task->_ssb); task->idle_percent = (hrtime - task->last_hrtime) ? 100.0f * (idle_time - task->last_idle_time) / (hrtime - task->last_hrtime) : 0.0f; + task->thread_percent = (hrtime - task->last_hrtime) ? 100.0f * (thread_time - task->last_thread_time) / (hrtime - task->last_hrtime) : 0.0f; task->last_hrtime = hrtime; task->last_idle_time = idle_time; + task->last_thread_time = thread_time; const char* k_names[] = { "child_tasks", @@ -1383,6 +1389,7 @@ static void _tf_task_trace_timer(uv_timer_t* timer) "exports", "promises", "idle_percent", + "thread_percent", }; int64_t values[] = { @@ -1391,6 +1398,7 @@ static void _tf_task_trace_timer(uv_timer_t* timer) task->_export_count, task->_promise_count, (int64_t)task->idle_percent, + (int64_t)task->thread_percent, }; tf_trace_counter(task->_trace, "task", sizeof(k_names) / sizeof(*k_names), k_names, values); }