diff --git a/core/core.js b/core/core.js index 76299d8b..163772cd 100644 --- a/core/core.js +++ b/core/core.js @@ -861,6 +861,10 @@ loadSettings().then(function() { let data = JSON.stringify(getDebug(), null, 2); response.writeHead(200, {"Content-Type": "application/json; charset=utf-8", "Content-Length": data.length.toString()}); return response.end(data); + } else if (match = /^\/hitches$/.exec(request.uri)) { + let data = JSON.stringify(getHitches(), null, 2); + response.writeHead(200, {"Content-Type": "application/json; charset=utf-8", "Content-Length": data.length.toString()}); + return response.end(data); } else if (match = /^\/mem$/.exec(request.uri)) { let data = JSON.stringify(getAllocations(), null, 2); response.writeHead(200, { diff --git a/src/ssb.c b/src/ssb.c index b1fcf1be..2b7fa1c8 100644 --- a/src/ssb.c +++ b/src/ssb.c @@ -41,6 +41,9 @@ #define CYAN "\e[1;36m" #define RESET "\e[0m" +#define PRE_CALLBACK(ssb, cb) uint64_t pre_callback_hrtime_ns = _tf_ssb_callback_pre(ssb) +#define POST_CALLBACK(ssb, cb) _tf_ssb_callback_post(ssb, cb, pre_callback_hrtime_ns) + static_assert(k_id_base64_len == sodium_base64_ENCODED_LEN(9 + crypto_box_PUBLICKEYBYTES, sodium_base64_VARIANT_ORIGINAL), "k_id_base64_len"); static_assert(k_id_bin_len == crypto_box_PUBLICKEYBYTES, "k_id_bin_len"); static_assert(k_blob_id_len == (sodium_base64_ENCODED_LEN(crypto_hash_sha256_BYTES, sodium_base64_VARIANT_ORIGINAL) + 8), "k_blob_id_len"); @@ -229,6 +232,9 @@ typedef struct _tf_ssb_t tf_thread_work_time_t* thread_time; int thread_time_count; + + void (*hitch_callback)(const char* name, uint64_t duration, void* user_data); + void* hitch_user_data; } tf_ssb_t; typedef struct _tf_ssb_connection_message_request_t @@ -1008,6 +1014,22 @@ bool tf_ssb_id_str_to_bin(uint8_t* bin, const char* str) return tf_base64_decode(author_id, type - author_id, bin, crypto_box_PUBLICKEYBYTES) != 0; } +static uint64_t _tf_ssb_callback_pre(tf_ssb_t* ssb) +{ + return uv_hrtime(); +} + +static void _tf_ssb_callback_post(tf_ssb_t* ssb, void* callback, uint64_t pre) +{ + if (ssb->hitch_callback) + { + uint64_t post = uv_hrtime(); + const char* name = tf_util_function_to_string(callback); + ssb->hitch_callback(name, post - pre, ssb->hitch_user_data); + tf_free((void*)name); + } +} + static void _tf_ssb_notify_connections_changed(tf_ssb_t* ssb, tf_ssb_change_t change, tf_ssb_connection_t* connection) { tf_ssb_connections_changed_callback_node_t* next = NULL; @@ -1015,7 +1037,9 @@ static void _tf_ssb_notify_connections_changed(tf_ssb_t* ssb, tf_ssb_change_t ch { next = node->next; tf_trace_begin(ssb->trace, "connections_changed"); + PRE_CALLBACK(ssb, node->callback); node->callback(ssb, change, connection, node->user_data); + POST_CALLBACK(ssb, node->callback); tf_trace_end(ssb->trace); } } @@ -1451,7 +1475,9 @@ static void _tf_ssb_connection_rpc_recv(tf_ssb_connection_t* connection, uint8_t if (_tf_ssb_name_equals(context, val, it->name)) { tf_trace_begin(connection->ssb->trace, it->flattened_name); + PRE_CALLBACK(connection->ssb, it->callback); it->callback(connection, flags, request_number, val, message, size, it->user_data); + POST_CALLBACK(connection->ssb, it->callback); tf_trace_end(connection->ssb->trace); found = true; break; @@ -1469,7 +1495,9 @@ static void _tf_ssb_connection_rpc_recv(tf_ssb_connection_t* connection, uint8_t char buffer[64]; snprintf(buffer, sizeof(buffer), "request %d", request_number); tf_trace_begin(connection->ssb->trace, buffer); + PRE_CALLBACK(connection->ssb, callback); callback(connection, flags, request_number, val, message, size, user_data); + POST_CALLBACK(connection->ssb, callback); tf_trace_end(connection->ssb->trace); } } @@ -1501,7 +1529,9 @@ static void _tf_ssb_connection_rpc_recv(tf_ssb_connection_t* connection, uint8_t char buffer[64]; snprintf(buffer, sizeof(buffer), "request %d", request_number); tf_trace_begin(connection->ssb->trace, buffer); + PRE_CALLBACK(connection->ssb, callback); callback(connection, flags, request_number, JS_UNDEFINED, message, size, user_data); + POST_CALLBACK(connection->ssb, callback); tf_trace_end(connection->ssb->trace); } } @@ -3462,3 +3492,9 @@ uint64_t tf_ssb_get_average_thread_time(tf_ssb_t* ssb) } return ssb->thread_time_count ? total / ssb->thread_time_count : 0; } + +void tf_ssb_set_hitch_callback(tf_ssb_t* ssb, void (*callback)(const char* name, uint64_t duration_ns, void* user_data), void* user_data) +{ + ssb->hitch_callback = callback; + ssb->hitch_user_data = user_data; +} diff --git a/src/ssb.h b/src/ssb.h index 989576e2..305b33bf 100644 --- a/src/ssb.h +++ b/src/ssb.h @@ -189,3 +189,5 @@ 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); + +void tf_ssb_set_hitch_callback(tf_ssb_t* ssb, void (*callback)(const char* name, uint64_t duration_ns, void* user_data), void* user_data); diff --git a/src/task.c b/src/task.c index 8e97ab83..2779c746 100644 --- a/src/task.c +++ b/src/task.c @@ -34,6 +34,10 @@ #include #endif +#if !defined(_countof) +#define _countof(a) ((int)(sizeof((a)) / sizeof(*(a)))) +#endif + static const char* k_version = "1.0"; static JSClassID _import_class_id; @@ -71,6 +75,12 @@ typedef struct _promise_stack_t int count; } promise_stack_t; +typedef struct _hitch_t +{ + char name[256]; + uint64_t duration_ns; +} hitch_t; + typedef struct _tf_task_t { taskid_t _nextTask; @@ -130,6 +140,8 @@ typedef struct _tf_task_t promise_stack_t* _promise_stacks; int _promise_stack_count; + + hitch_t hitches[32]; } tf_task_t; typedef struct _export_record_t @@ -870,6 +882,22 @@ static JSValue _tf_task_getDebug(JSContext* context, JSValueConst this_val, int return result; } +static JSValue _tf_task_getHitches(JSContext* context, JSValueConst this_val, int argc, JSValueConst* argv) +{ + tf_task_t* task = JS_GetContextOpaque(context); + tf_trace_begin(task->_trace, __func__); + JSValue result = JS_NewObject(context); + for (int i = 0; i < _countof(task->hitches); i++) + { + if (*task->hitches[i].name) + { + JS_SetPropertyStr(context, result, task->hitches[i].name, JS_NewFloat64(context, task->hitches[i].duration_ns / 1e9f)); + } + } + tf_trace_end(task->_trace); + return result; +} + static JSValue _tf_task_getAllocations(JSContext* context, JSValueConst this_val, int argc, JSValueConst* argv) { tf_task_t* task = JS_GetContextOpaque(context); @@ -1576,6 +1604,24 @@ static void _tf_task_trace_to_parent(tf_trace_t* trace, const char* buffer, size tf_packetstream_send(tf_taskstub_get_stream(task->_parent), kTaskTrace, buffer, size); } +static void _tf_task_record_hitch(const char* name, uint64_t duration_ns, void* user_data) +{ + tf_task_t* task = user_data; + for (int i = 0; i < _countof(task->hitches); i++) + { + if (duration_ns > task->hitches[i].duration_ns) + { + if (i + 1 < _countof(task->hitches)) + { + memmove(task->hitches + i + 1, task->hitches + i, sizeof(hitch_t) * (_countof(task->hitches) - i - 1)); + } + snprintf(task->hitches[i].name, sizeof(task->hitches[i].name), "%s", name); + task->hitches[i].duration_ns = duration_ns; + break; + } + } +} + void tf_task_activate(tf_task_t* task) { assert(!task->_activated); @@ -1643,6 +1689,7 @@ void tf_task_activate(tf_task_t* task) task->_ssb = tf_ssb_create(&task->_loop, task->_context, task->_db_path); tf_ssb_set_trace(task->_ssb, task->_trace); tf_ssb_register(context, task->_ssb); + tf_ssb_set_hitch_callback(task->_ssb, _tf_task_record_hitch, task); if (task->_ssb_port) { @@ -1654,6 +1701,7 @@ void tf_task_activate(tf_task_t* task) JS_SetPropertyStr(context, global, "trace", JS_NewCFunction(context, _tf_task_trace, "trace", 1)); JS_SetPropertyStr(context, global, "getStats", JS_NewCFunction(context, _tf_task_getStats, "getStats", 0)); JS_SetPropertyStr(context, global, "getDebug", JS_NewCFunction(context, _tf_task_getDebug, "getDebug", 0)); + JS_SetPropertyStr(context, global, "getHitches", JS_NewCFunction(context, _tf_task_getHitches, "getHitches", 0)); JS_SetPropertyStr(context, global, "getAllocations", JS_NewCFunction(context, _tf_task_getAllocations, "getAllocations", 0)); JS_SetPropertyStr(context, global, "disconnectionsDebug", JS_NewCFunction(context, _tf_task_disconnectionsDebug, "disconnectionsDebug", 0)); } diff --git a/src/util.js.c b/src/util.js.c index 88a7b8eb..d69515f3 100644 --- a/src/util.js.c +++ b/src/util.js.c @@ -462,6 +462,30 @@ const char* tf_util_backtrace_to_string(void* const* buffer, int count) return string; } +static int _tf_util_backtrace_single_callback(void* data, uintptr_t pc, const char* filename, int line_number, const char* function) +{ + char** stack = data; + char line[256]; + int length = snprintf(line, sizeof(line), "%s", function); + int current = *stack ? strlen(*stack) : 0; + *stack = tf_resize_vec(*stack, current + length + 1); + memcpy(*stack + current, line, length + 1); + return 0; +} + +const char* tf_util_function_to_string(void* function) +{ + extern struct backtrace_state* g_backtrace_state; + char* string = NULL; + backtrace_pcinfo( + g_backtrace_state, + (uintptr_t)function, + _tf_util_backtrace_single_callback, + _tf_util_backtrace_error, + &string); + return string; +} + const char* tf_util_backtrace_string() { void* buffer[32]; diff --git a/src/util.js.h b/src/util.js.h index 515be399..d43169d1 100644 --- a/src/util.js.h +++ b/src/util.js.h @@ -19,3 +19,5 @@ size_t tf_base64_decode(const char* source, size_t source_length, uint8_t* out, int tf_util_backtrace(void** buffer, int count); const char* tf_util_backtrace_to_string(void* const* buffer, int count); const char* tf_util_backtrace_string(); + +const char* tf_util_function_to_string(void* function);