forked from cory/tildefriends
		
	Track and expose hitches in some suspect callbacks.
git-svn-id: https://www.unprompted.com/svn/projects/tildefriends/trunk@4261 ed5197a5-7fde-0310-b194-c3ffbd925b24
This commit is contained in:
		@@ -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, {
 | 
			
		||||
 
 | 
			
		||||
							
								
								
									
										36
									
								
								src/ssb.c
									
									
									
									
									
								
							
							
						
						
									
										36
									
								
								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;
 | 
			
		||||
}
 | 
			
		||||
 
 | 
			
		||||
@@ -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);
 | 
			
		||||
 
 | 
			
		||||
							
								
								
									
										48
									
								
								src/task.c
									
									
									
									
									
								
							
							
						
						
									
										48
									
								
								src/task.c
									
									
									
									
									
								
							@@ -34,6 +34,10 @@
 | 
			
		||||
#include <unistd.h>
 | 
			
		||||
#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));
 | 
			
		||||
	}
 | 
			
		||||
 
 | 
			
		||||
@@ -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];
 | 
			
		||||
 
 | 
			
		||||
@@ -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);
 | 
			
		||||
 
 | 
			
		||||
		Reference in New Issue
	
	Block a user