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