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

@@ -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'},

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;
+}

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);

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)

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);
 }