From c371fc2a8e26ed75f9b185398965194cdf488b25 Mon Sep 17 00:00:00 2001
From: Cory McWilliams <cory@unprompted.com>
Date: Thu, 20 Jul 2023 05:06:15 +0000
Subject: [PATCH] Fixed multiple trace problems.

git-svn-id: https://www.unprompted.com/svn/projects/tildefriends/trunk@4357 ed5197a5-7fde-0310-b194-c3ffbd925b24
---
 src/ssb.c       | 16 +++++++++++++++-
 src/ssb.db.c    |  8 ++++++++
 src/ssb.js.c    | 17 +++++++++++------
 src/ssb.rpc.c   | 16 ++++++++++++++++
 src/ssb.tests.c | 26 ++++++++++++++++++++++++--
 src/trace.c     | 37 ++++++++++++++++++++++++++-----------
 src/util.js.h   |  2 +-
 7 files changed, 101 insertions(+), 21 deletions(-)

diff --git a/src/ssb.c b/src/ssb.c
index c2d48889..6bcadb7d 100644
--- a/src/ssb.c
+++ b/src/ssb.c
@@ -2129,6 +2129,7 @@ tf_ssb_t* tf_ssb_create(uv_loop_t* loop, JSContext* context, const char* db_path
 
 sqlite3* tf_ssb_acquire_db_reader(tf_ssb_t* ssb)
 {
+	tf_trace_begin(ssb->trace, "db_reader");
 	sqlite3* db = NULL;
 	uv_mutex_lock(&ssb->db_readers_lock);
 	if (ssb->db_readers_count)
@@ -2139,8 +2140,8 @@ sqlite3* tf_ssb_acquire_db_reader(tf_ssb_t* ssb)
 	{
 		sqlite3_open_v2(ssb->db_path, &db, SQLITE_OPEN_READONLY | SQLITE_OPEN_URI, NULL);
 		tf_ssb_db_init_reader(db);
-		tf_trace_sqlite(ssb->trace, db);
 	}
+	tf_trace_sqlite(ssb->trace, db);
 	uv_mutex_unlock(&ssb->db_readers_lock);
 	return db;
 }
@@ -2151,10 +2152,12 @@ void tf_ssb_release_db_reader(tf_ssb_t* ssb, sqlite3* db)
 	ssb->db_readers = tf_resize_vec(ssb->db_readers, sizeof(sqlite3*) * (ssb->db_readers_count + 1));
 	ssb->db_readers[ssb->db_readers_count++] = db;
 	uv_mutex_unlock(&ssb->db_readers_lock);
+	tf_trace_end(ssb->trace);
 }
 
 sqlite3* tf_ssb_acquire_db_writer(tf_ssb_t* ssb)
 {
+	tf_trace_begin(ssb->trace, "db_writer");
 	uv_mutex_lock(&ssb->db_writer_lock);
 	sqlite3* writer = ssb->db_writer;
 	assert(writer);
@@ -2167,6 +2170,7 @@ void tf_ssb_release_db_writer(tf_ssb_t* ssb, sqlite3* db)
 	assert(ssb->db_writer == NULL);
 	ssb->db_writer = db;
 	uv_mutex_unlock(&ssb->db_writer_lock);
+	tf_trace_end(ssb->trace);
 }
 
 uv_loop_t* tf_ssb_get_loop(tf_ssb_t* ssb)
@@ -2207,6 +2211,16 @@ void tf_ssb_set_trace(tf_ssb_t* ssb, tf_trace_t* trace)
 		tf_trace_sqlite(trace, db);
 	}
 	tf_ssb_release_db_writer(ssb, db);
+
+	if (trace)
+	{
+		uv_mutex_lock(&ssb->db_readers_lock);
+		for (int i = 0; i < ssb->db_readers_count; i++)
+		{
+			tf_trace_sqlite(trace, ssb->db_readers[i]);
+		}
+		uv_mutex_unlock(&ssb->db_readers_lock);
+	}
 }
 
 tf_trace_t* tf_ssb_get_trace(tf_ssb_t* ssb)
diff --git a/src/ssb.db.c b/src/ssb.db.c
index 13c48711..74698456 100644
--- a/src/ssb.db.c
+++ b/src/ssb.db.c
@@ -346,6 +346,10 @@ static char* _tf_ssb_db_get_message_blob_wants(tf_ssb_t* ssb, int64_t rowid)
 				tf_printf("%s\n", sqlite3_errmsg(db));
 			}
 		}
+		else
+		{
+			tf_printf("bind failed: %s\n", sqlite3_errmsg(db));
+		}
 		sqlite3_finalize(statement);
 	}
 	else
@@ -440,15 +444,19 @@ static void _tf_ssb_db_store_message_after_work(uv_work_t* work, int status)
 	tf_trace_begin(trace, "message_store_after_work");
 	if (store->out_stored)
 	{
+		tf_trace_begin(trace, "notify_message_added");
 		tf_ssb_notify_message_added(store->ssb, store->id);
+		tf_trace_end(trace);
 	}
 	if (store->out_blob_wants)
 	{
+		tf_trace_begin(trace, "notify_blob_wants_added");
 		for (char* p = store->out_blob_wants; *p; p = p + strlen(p))
 		{
 			tf_ssb_notify_blob_want_added(store->ssb, p);
 		}
 		tf_free(store->out_blob_wants);
+		tf_trace_end(trace);
 	}
 	_tf_ssb_db_store_message_work_finish(store);
 	tf_trace_end(trace);
diff --git a/src/ssb.js.c b/src/ssb.js.c
index 71a6d8a6..273b31c2 100644
--- a/src/ssb.js.c
+++ b/src/ssb.js.c
@@ -1108,6 +1108,7 @@ static bool _tf_ssb_get_private_key_curve25519(sqlite3* db, const char* user, co
 {
 	if (!user || !identity || !out_private_key)
 	{
+		tf_printf("user=%p identity=%p out_private_key=%p\n", user, identity, out_private_key);
 		return false;
 	}
 
@@ -1176,10 +1177,13 @@ static JSValue _tf_ssb_private_message_encrypt(JSContext* context, JSValueConst
 	if (JS_IsUndefined(result))
 	{
 		tf_ssb_t* ssb = JS_GetOpaque(this_val, _tf_ssb_classId);
-		sqlite3* db = tf_ssb_acquire_db_reader(ssb);
-
 		uint8_t private_key[crypto_sign_SECRETKEYBYTES] = { 0 };
-		if (_tf_ssb_get_private_key_curve25519(db, signer_user, signer_identity, private_key))
+
+		sqlite3* db = tf_ssb_acquire_db_reader(ssb);
+		bool found = _tf_ssb_get_private_key_curve25519(db, signer_user, signer_identity, private_key);
+		tf_ssb_release_db_reader(ssb, db);
+
+		if (found)
 		{
 			uint8_t public_key[crypto_box_PUBLICKEYBYTES] = { 0 };
 			uint8_t secret_key[crypto_box_SECRETKEYBYTES] = { 0 };
@@ -1252,7 +1256,6 @@ static JSValue _tf_ssb_private_message_encrypt(JSContext* context, JSValueConst
 		{
 			result = JS_ThrowInternalError(context, "Unable to get key for ID %s of user %s.", signer_identity, signer_user);
 		}
-		tf_ssb_release_db_reader(ssb, db);
 	}
 
 	JS_FreeCString(context, signer_user);
@@ -1274,7 +1277,10 @@ static JSValue _tf_ssb_private_message_decrypt(JSContext* context, JSValueConst
 
 	tf_ssb_t* ssb = JS_GetOpaque(this_val, _tf_ssb_classId);
 	sqlite3* db = tf_ssb_acquire_db_reader(ssb);
-	if (_tf_ssb_get_private_key_curve25519(db, user, identity, private_key))
+	bool found = _tf_ssb_get_private_key_curve25519(db, user, identity, private_key);
+	tf_ssb_release_db_reader(ssb, db);
+
+	if (found)
 	{
 		uint8_t* decoded = tf_malloc(message_size);
 		int decoded_length = tf_base64_decode(message, message_size - strlen(".box"), decoded, message_size);
@@ -1324,7 +1330,6 @@ static JSValue _tf_ssb_private_message_decrypt(JSContext* context, JSValueConst
 	{
 		result = JS_ThrowInternalError(context, "Private key not found for user %s with id %s.", user, identity);
 	}
-	tf_ssb_release_db_reader(ssb, db);
 
 	JS_FreeCString(context, user);
 	JS_FreeCString(context, identity);
diff --git a/src/ssb.rpc.c b/src/ssb.rpc.c
index ed5b2401..e692588f 100644
--- a/src/ssb.rpc.c
+++ b/src/ssb.rpc.c
@@ -162,6 +162,10 @@ static void _tf_ssb_rpc_request_more_blobs(tf_ssb_connection_t* connection)
 		}
 		sqlite3_finalize(statement);
 	}
+	else
+	{
+		tf_printf("prepare failed: %s\n", sqlite3_errmsg(db));
+	}
 	tf_ssb_release_db_reader(ssb, db);
 }
 
@@ -212,6 +216,10 @@ static bool _get_global_setting_bool(tf_ssb_t* ssb, const char* name, bool defau
 		}
 		sqlite3_finalize(statement);
 	}
+	else
+	{
+		tf_printf("prepare failed: %s\n", sqlite3_errmsg(db));
+	}
 	tf_ssb_release_db_reader(ssb, db);
 	return result;
 }
@@ -240,6 +248,10 @@ static bool _get_global_setting_string(tf_ssb_t* ssb, const char* name, char* ou
 		}
 		sqlite3_finalize(statement);
 	}
+	else
+	{
+		tf_printf("prepare failed: %s\n", sqlite3_errmsg(db));
+	}
 	tf_ssb_release_db_reader(ssb, db);
 	return result;
 }
@@ -764,6 +776,10 @@ static void _tf_ssb_connection_send_history_stream_internal(tf_ssb_connection_t*
 		}
 		sqlite3_finalize(statement);
 	}
+	else
+	{
+		tf_printf("prepare failed: %s\n", sqlite3_errmsg(db));
+	}
 	tf_ssb_release_db_reader(ssb, db);
 
 	if (max_sequence_seen == sequence + k_max - 1)
diff --git a/src/ssb.tests.c b/src/ssb.tests.c
index 21304e12..e2f64b4a 100644
--- a/src/ssb.tests.c
+++ b/src/ssb.tests.c
@@ -5,6 +5,7 @@
 #include "ssb.db.h"
 #include "ssb.js.h"
 #include "tests.h"
+#include "trace.h"
 #include "util.js.h"
 
 #include "sqlite3.h"
@@ -596,8 +597,11 @@ void tf_ssb_test_bench(const tf_test_options_t* options)
 	uv_loop_t loop = { 0 };
 	uv_loop_init(&loop);
 
+	tf_trace_t* trace = tf_trace_create();
+
 	unlink("out/test_db0.sqlite");
 	tf_ssb_t* ssb0 = tf_ssb_create(&loop, NULL, "file:out/test_db0.sqlite");
+	tf_ssb_set_trace(ssb0, trace);
 	tf_ssb_generate_keys(ssb0);
 
 	char id0[k_id_base64_len] = { 0 };
@@ -627,6 +631,7 @@ void tf_ssb_test_bench(const tf_test_options_t* options)
 
 	unlink("out/test_db1.sqlite");
 	tf_ssb_t* ssb1 = tf_ssb_create(&loop, NULL, "file:out/test_db1.sqlite");
+	tf_ssb_set_trace(ssb1, trace);
 	tf_ssb_generate_keys(ssb1);
 	uint8_t id0bin[k_id_bin_len];
 	tf_ssb_id_str_to_bin(id0bin, id0);
@@ -648,13 +653,19 @@ void tf_ssb_test_bench(const tf_test_options_t* options)
 	tf_printf("Waiting for messages.\n");
 	clock_gettime(CLOCK_REALTIME, &start_time);
 	int count = 0;
+	tf_ssb_add_message_added_callback(ssb1, _message_added, NULL, &count);
 	while (count < k_messages)
 	{
-		//tf_printf("%d / %d\n", count, k_messages);
 		uv_run(&loop, UV_RUN_ONCE);
-		count = _ssb_test_count_messages(ssb1);
 	}
+	tf_ssb_remove_message_added_callback(ssb1, _message_added, &count);
 	clock_gettime(CLOCK_REALTIME, &end_time);
+
+	count = _ssb_test_count_messages(ssb1);
+	if (count < k_messages)
+	{
+		abort();
+	}
 	tf_printf("Done.\n");
 	tf_printf("replicate = %f seconds\n", (end_time.tv_sec - start_time.tv_sec) + (end_time.tv_nsec - start_time.tv_nsec) / 1e9);
 
@@ -666,8 +677,19 @@ void tf_ssb_test_bench(const tf_test_options_t* options)
 
 	uv_run(&loop, UV_RUN_DEFAULT);
 
+	char* trace_data = tf_trace_export(trace);
+	FILE* file = fopen("out/trace.json", "wb");
+	if (file)
+	{
+		fwrite(trace_data, 1, strlen(trace_data), file);
+		fclose(file);
+	}
+	tf_free(trace_data);
+
 	tf_ssb_destroy(ssb1);
 	tf_ssb_destroy(ssb0);
 
+	tf_trace_destroy(trace);
+
 	uv_loop_close(&loop);
 }
diff --git a/src/trace.c b/src/trace.c
index f424dd54..9edb7284 100644
--- a/src/trace.c
+++ b/src/trace.c
@@ -30,6 +30,7 @@ typedef struct _tf_trace_stack_t tf_trace_stack_t;
 typedef struct _tf_trace_stack_t
 {
 	const char* names[256];
+	const char* tags[256];
 	int count;
 	tf_trace_stack_t* next;
 } tf_trace_stack_t;
@@ -225,7 +226,7 @@ static tf_trace_thread_t* _tf_trace_get_thread(tf_trace_t* trace, pthread_t self
 	return found;
 }
 
-static void _tf_push_stack(tf_trace_t* trace, pthread_t self, const char* name)
+static void _tf_push_stack(tf_trace_t* trace, pthread_t self, const char* name, void* tag)
 {
 	tf_trace_thread_t* thread = _tf_trace_get_thread(trace, self);
 	if (!thread->stack || thread->stack->count + 1 > (int)_countof(thread->stack->names))
@@ -240,11 +241,13 @@ static void _tf_push_stack(tf_trace_t* trace, pthread_t self, const char* name)
 	{
 		stack = stack->next;
 	}
-	stack->names[stack->count++] = name;
+	stack->names[stack->count] = name;
+	stack->tags[stack->count] = tag;
+	stack->count++;
 
 }
 
-static const char* _tf_pop_stack(tf_trace_t* trace, pthread_t self)
+static const char* _tf_pop_stack(tf_trace_t* trace, pthread_t self, void* tag)
 {
 	tf_trace_thread_t* thread = _tf_trace_get_thread(trace, self);
 	tf_trace_stack_t* stack = thread->stack;
@@ -253,7 +256,9 @@ static const char* _tf_pop_stack(tf_trace_t* trace, pthread_t self)
 		stack = stack->next;
 	}
 	const char* name = NULL;
-	if (stack && stack->count > 0)
+	if (stack &&
+		stack->count > 0 &&
+		stack->tags[stack->count - 1] == tag)
 	{
 		name = stack->names[stack->count - 1];
 		stack->count--;
@@ -261,15 +266,15 @@ static const char* _tf_pop_stack(tf_trace_t* trace, pthread_t self)
 	return name;
 }
 
-void tf_trace_begin(tf_trace_t* trace, const char* name)
+static void _tf_trace_begin_tagged(tf_trace_t* trace, const char* name, void* tag)
 {
-	if (!trace)
+	if (!trace || !name)
 	{
 		return;
 	}
 
 	pthread_t self = pthread_self();
-	_tf_push_stack(trace, self, name);
+	_tf_push_stack(trace, self, name, tag);
 
 	char line[1024];
 	int p = snprintf(line, sizeof(line), "{\"ph\": \"B\", \"pid\": %d, \"tid\": \"0x%" PRIx64 "\", \"ts\": %" PRId64 ", \"name\": \"", getpid(), (int64_t)self, _trace_ts());
@@ -278,7 +283,12 @@ void tf_trace_begin(tf_trace_t* trace, const char* name)
 	trace->callback(trace, line, p, trace->user_data);
 }
 
-void tf_trace_end(tf_trace_t* trace)
+void tf_trace_begin(tf_trace_t* trace, const char* name)
+{
+	_tf_trace_begin_tagged(trace, name, NULL);
+}
+
+static void _tf_trace_end_tagged(tf_trace_t* trace, void* tag)
 {
 	if (!trace)
 	{
@@ -286,7 +296,7 @@ void tf_trace_end(tf_trace_t* trace)
 	}
 
 	pthread_t self = pthread_self();
-	const char* name = _tf_pop_stack(trace, self);
+	const char* name = _tf_pop_stack(trace, self, tag);
 	if (!name)
 	{
 		return;
@@ -299,6 +309,11 @@ void tf_trace_end(tf_trace_t* trace)
 	trace->callback(trace, line, p, trace->user_data);
 }
 
+void tf_trace_end(tf_trace_t* trace)
+{
+	_tf_trace_end_tagged(trace, NULL);
+}
+
 char* tf_trace_export(tf_trace_t* trace)
 {
 	if (!trace)
@@ -361,12 +376,12 @@ static int _tf_trace_sqlite_callback(unsigned int t, void* c, void* p, void* x)
 			const char* statement = x;
 			if (statement[0] != '-' || statement[1] != '-')
 			{
-				tf_trace_begin(trace, statement);
+				_tf_trace_begin_tagged(trace, statement, p);
 			}
 		}
 		break;
 	case SQLITE_TRACE_PROFILE:
-		tf_trace_end(trace);
+		_tf_trace_end_tagged(trace, p);
 		break;
 	}
 	return 0;
diff --git a/src/util.js.h b/src/util.js.h
index 7349e283..d616fea9 100644
--- a/src/util.js.h
+++ b/src/util.js.h
@@ -22,4 +22,4 @@ const char* tf_util_backtrace_string();
 
 const char* tf_util_function_to_string(void* function);
 
- #define tf_min(a, b) ({ __typeof__ (a) _a = (a); __typeof__ (b) _b = (b);  _a > _b ? _a : _b; })
+#define tf_min(a, b) ({ __typeof__ (a) _a = (a); __typeof__ (b) _b = (b);  _a > _b ? _a : _b; })