diff --git a/Makefile b/Makefile index 39d6026..973e852 100644 --- a/Makefile +++ b/Makefile @@ -44,6 +44,9 @@ LIBOUT := libpcloudcc_lib.so ifeq ($(BUILD), debug) CFLAGS += -g -O0 -DDEBUG -Wall -D_FILE_OFFSET_BITS=64 -DFUSE_USE_VERSION=26 -D_GNU_SOURCE -DPSYNC_SSL_DEBUG_LEVEL=$(SSLDBGLVL) CXXFLAGS += -g -O0 -DDEBUG -Wall -D_FILE_OFFSET_BITS=64 -DFUSE_USE_VERSION=26 -D_GNU_SOURCE -DPSYNC_SSL_DEBUG_LEVEL=$(SSLDBGLVL) + DEBUGSRC := $(wildcard $(LIBDIR)/debug/*.c) + DEBUGOBJ := $(notdir $(DEBUGSRC:%.c=%.o)) + COBJ += $(DEBUGOBJ) else ifeq ($(BUILD), release) CFLAGS += -O2 -DNDEBUG -D_FILE_OFFSET_BITS=64 -DFUSE_USE_VERSION=26 -D_GNU_SOURCE -DPSYNC_SSL_DEBUG_LEVEL=$(SSLDBGLVL) CXXFLAGS += -O2 -DNDEBUG -D_FILE_OFFSET_BITS=64 -DFUSE_USE_VERSION=26 -D_GNU_SOURCE -DPSYNC_SSL_DEBUG_LEVEL=$(SSLDBGLVL) @@ -91,7 +94,10 @@ $(EXECOUT): $(CPPOBJ) $(if $(filter 0,$(STATIC)),$(LIBOUT),$(COBJ)) $(CPPOBJ): %.o: $(SRCDIR)/%.cpp $(CXX) $(CXXFLAGS) -c -o $@ $< -$(COBJ): %.o: $(LIBDIR)/%.c +$(DEBUGOBJ): %.o: $(LIBDIR)/debug/%.c + $(CC) $(CFLAGS) -c -o $@ $< + +$(filter-out $(DEBUGOBJ),$(COBJ)): %.o: $(LIBDIR)/%.c $(CC) $(CFLAGS) -c -o $@ $< $(LIBOUT): $(COBJ) diff --git a/pclsync/debug/pfs_debug.c b/pclsync/debug/pfs_debug.c new file mode 100644 index 0000000..e5ead10 --- /dev/null +++ b/pclsync/debug/pfs_debug.c @@ -0,0 +1,47 @@ +// debug/pfs_debug.c - debug implementations for pfs debug helpers + +#include +#include +#include + +#include "pdbg.h" +#include "pfs.h" +#include "pfs_internal.h" +#include "pfstasks.h" +#include "prun.h" +#include "psql.h" + +void pfs_debug_init_file_mutex(pthread_mutex_t *m) { + pthread_mutexattr_t attr; + pthread_mutexattr_init(&attr); + pthread_mutexattr_settype(&attr, PTHREAD_MUTEX_ERRORCHECK); + pthread_mutex_init(m, &attr); + pthread_mutexattr_destroy(&attr); +} + +static void pfs_do_dump_internals() { + psync_openfile_t *of; + pdbg_logf(D_NOTICE, "dumping internal state"); + psql_rdlock(); + ptree_for_each_element(of, openfiles, psync_openfile_t, tree) + pdbg_logf(D_NOTICE, "open file %s fileid %ld folderid %ld", + of->currentname, (long)of->fileid, + (long)of->currentfolder->folderid); + pfs_task_dump_state(); + psql_rdunlock(); +} + +void pfs_debug_dump_internals() { pfs_do_dump_internals(); } + +static void pfs_usr1_handler(int sig) { + prun_thread("dump signal", pfs_do_dump_internals); +} + +void pfs_debug_register_signal_handlers() { + struct sigaction sa; + memset(&sa, 0, sizeof(struct sigaction)); + sigemptyset(&sa.sa_mask); + sa.sa_handler = pfs_usr1_handler; + sa.sa_flags = 0; + sigaction(SIGUSR1, &sa, NULL); +} diff --git a/pclsync/debug/pfstasks_debug.c b/pclsync/debug/pfstasks_debug.c new file mode 100644 index 0000000..e85041a --- /dev/null +++ b/pclsync/debug/pfstasks_debug.c @@ -0,0 +1,51 @@ +// debug/pfstasks_debug.c - debug implementations for pfstasks debug helpers + +#include "pdbg.h" +#include "pfstasks.h" +#include "pfstasks_internal.h" + +void pfstasks_debug_check_folder_consistency(psync_fstask_folder_t *folder) { + if ((!!folder->taskscnt) != + (folder->creats || folder->mkdirs || folder->rmdirs || folder->unlinks)) + pdbg_logf(D_ERROR, "taskcnt=%u, c=%p, m=%p, r=%p, u=%p", + (unsigned)folder->taskscnt, folder->creats, folder->mkdirs, + folder->rmdirs, folder->unlinks); +} + +void pfs_task_dump_state() { + psync_fstask_folder_t *folder; + psync_fstask_mkdir_t *mk; + psync_fstask_rmdir_t *rm; + psync_fstask_creat_t *cr; + psync_fstask_unlink_t *un; + uint32_t cnt; + ptree_for_each_element(folder, folders, psync_fstask_folder_t, tree) { + pdbg_logf(D_NOTICE, "open folderid %ld taskcnt %u refcnt %u", + (long)folder->folderid, (unsigned)folder->taskscnt, + (unsigned)folder->refcnt); + cnt = 0; + ptree_for_each_element(mk, folder->mkdirs, psync_fstask_mkdir_t, tree) { + pdbg_logf(D_NOTICE, " mkdir %s folderid %ld taskid %lu", mk->name, + (long)mk->folderid, (unsigned long)mk->taskid); + cnt++; + } + ptree_for_each_element(rm, folder->rmdirs, psync_fstask_rmdir_t, tree) { + pdbg_logf(D_NOTICE, " mkdir %s folderid %ld taskid %lu", rm->name, + (long)rm->folderid, (unsigned long)rm->taskid); + cnt++; + } + ptree_for_each_element(cr, folder->creats, psync_fstask_creat_t, tree) { + pdbg_logf(D_NOTICE, " creat %s fileid %ld taskid %lu", cr->name, + (long)cr->fileid, (unsigned long)cr->taskid); + cnt++; + } + ptree_for_each_element(un, folder->unlinks, psync_fstask_unlink_t, tree) { + pdbg_logf(D_NOTICE, " unlink %s fileid %ld taskid %lu", un->name, + (long)un->fileid, (unsigned long)un->taskid); + cnt++; + } + if (cnt != folder->taskscnt) + pdbg_logf(D_ERROR, "inconsistency found, counted taskcnt %u != taskcnt %u", + (unsigned)cnt, (unsigned)folder->taskscnt); + } +} diff --git a/pclsync/debug/pnetlibs_debug.c b/pclsync/debug/pnetlibs_debug.c new file mode 100644 index 0000000..976459d --- /dev/null +++ b/pclsync/debug/pnetlibs_debug.c @@ -0,0 +1,91 @@ +// debug/pnetlibs_debug.c - debug implementations for pnetlibs debug helpers + +#include + +#include "papi.h" +#include "pdbg.h" +#include "plibs.h" +#include "pnetlibs.h" +#include "psock.h" + +// -------------------------------------------------------------------------- +// Internal helpers (debug-only) +// -------------------------------------------------------------------------- + +void pident(int ident) { + VAR_ARRAY(b, char, ident + 1); + memset(b, '\t', ident); + b[ident] = 0; + fputs(b, stdout); +} + +static void print_tree(const binresult *tree, int ident) { + int i; + if (tree->type == PARAM_STR) + printf("string(%u)\"%s\"", tree->length, tree->str); + else if (tree->type == PARAM_NUM) + printf("number %llu", (unsigned long long)tree->num); + else if (tree->type == PARAM_DATA) + printf("data %llu", (unsigned long long)tree->num); + else if (tree->type == PARAM_BOOL) + printf("bool %s", tree->num ? "true" : "false"); + else if (tree->type == PARAM_HASH) { + printf("hash (%u){\n", tree->length); + if (tree->length) { + pident(ident + 1); + printf("\"%s\" = ", tree->hash[0].key); + print_tree(tree->hash[0].value, ident + 1); + for (i = 1; i < tree->length; i++) { + printf(",\n"); + pident(ident + 1); + printf("\"%s\" = ", tree->hash[i].key); + print_tree(tree->hash[i].value, ident + 1); + } + } + printf("\n"); + pident(ident); + printf("}"); + } else if (tree->type == PARAM_ARRAY) { + printf("array (%u)[\n", tree->length); + if (tree->length) { + pident(ident + 1); + print_tree(tree->array[0], ident + 1); + for (i = 1; i < tree->length; i++) { + printf(",\n"); + pident(ident + 1); + print_tree(tree->array[i], ident + 1); + } + } + printf("\n"); + pident(ident); + printf("]"); + } +} + +static void psync_apipool_dump_socket(psock_t *api) { + binresult *res; + res = papi_result(api); + psync_apipool_release_bad(api); + if (!res) { + pdbg_logf(D_NOTICE, "could not read result from socket, it is probably broken"); + return; + } + pdbg_logf(D_WARNING, "read result from released socket, dumping and aborting"); + print_tree(res, 0); + free(res); + abort(); +} + +// -------------------------------------------------------------------------- +// Strong override +// -------------------------------------------------------------------------- + +// Returns 1 if the release was handled (caller should return), 0 to proceed normally. +int pnetlibs_debug_check_apipool_release(psock_t *api) { + if (unlikely(psock_readable(api))) { + pdbg_logf(D_WARNING, "released socket with pending data to read"); + psync_apipool_dump_socket(api); + return 1; + } + return 0; +} diff --git a/pclsync/debug/psock_debug.c b/pclsync/debug/psock_debug.c new file mode 100644 index 0000000..45f3d5f --- /dev/null +++ b/pclsync/debug/psock_debug.c @@ -0,0 +1,18 @@ +// debug/psock_debug.c - debug implementations for psock debug helpers + +#include + +#include "pdbg.h" +#include "psock.h" + +void psock_debug_log_wait_latency(const struct timespec *start) { + struct timespec end; + unsigned long msec; + clock_gettime(CLOCK_REALTIME, &end); + msec = (end.tv_sec - start->tv_sec) * 1000 + end.tv_nsec / 1000000 - + start->tv_nsec / 1000000; + if (msec >= 30000) + pdbg_logf(D_WARNING, "got response from socket after %lu milliseconds", msec); + else if (msec >= 5000) + pdbg_logf(D_NOTICE, "got response from socket after %lu milliseconds", msec); +} diff --git a/pclsync/debug/psql_debug.c b/pclsync/debug/psql_debug.c new file mode 100644 index 0000000..509bb1e --- /dev/null +++ b/pclsync/debug/psql_debug.c @@ -0,0 +1,521 @@ +// debug/psql_debug.c - debug-build strong overrides for psql lock/query functions. +// Compiled only when BUILD=debug. Strong symbols here override the weak stubs in psql.c. + +#include +#include + +#include "pcache.h" +#include "pdbg.h" +#include "plocks.h" +#include "pnetlibs.h" +#include "psettings.h" +#include "psql.h" +#include "psql_internal.h" +#include "putil.h" + +#undef psql_trylock +#undef psql_lock +#undef psql_rdlock +#undef psql_statement +#undef psql_start +#undef psql_query_nocache +#undef psql_query +#undef psql_rdlock_nocache +#undef psql_query_rdlock +#undef psql_query_nolock_nocache +#undef psql_query_nolock +#undef psql_prepare_nocache +#undef psql_prepare + +#define SQL_NO_LOCK 0 +#define SQL_READ_LOCK 1 +#define SQL_WRITE_LOCK 2 + +#define PSYNC_TNUMBER 1 +#define PSYNC_TSTRING 2 +#define PSYNC_TREAL 3 +#define PSYNC_TNULL 4 + +extern PSYNC_THREAD const char *psync_thread_name; + +// -------------------------------------------------------------------------- +// Debug-only state +// -------------------------------------------------------------------------- + +typedef struct { + psync_list list; + const char *file; + const char *thread; + struct timespec tm; + unsigned line; +} rd_lock_data; + +static PSYNC_THREAD rd_lock_data *rdlock = NULL; +static PSYNC_THREAD unsigned long rdlockctr = 0; +static PSYNC_THREAD struct timespec rdlockstart; +unsigned long lockctr = 0; +static struct timespec lockstart; +static const char *wrlockfile = "none"; +static const char *wrlockthread = ""; +static unsigned wrlockline = 0; +static unsigned wrlocked = 0; +static pthread_t wrlocker; +static psync_list rdlocks = PSYNC_LIST_STATIC_INIT(rdlocks); +static pthread_mutex_t rdmutex = PTHREAD_MUTEX_INITIALIZER; + +// -------------------------------------------------------------------------- +// Internal helpers +// -------------------------------------------------------------------------- + +static void record_wrlock(const char *file, unsigned line) { + if (unlikely(rdlock)) { + pdbg_logf(D_BUG, + "trying to get write lock at %s:%u, but read lock is already taken " + "at %s:%u, aborting", + file, line, rdlock->file, rdlock->line); + sendpdbg_logf("trying to get write lock at %s:%u, but read lock is already " + "taken at %s:%u, aborting", + file, line, rdlock->file, rdlock->line); + abort(); + } + sendpdbg_assert(!wrlocked); + pdbg_assert(!wrlocked); + wrlockfile = file; + wrlockline = line; + wrlockthread = psync_thread_name; + wrlocked = 1; + wrlocker = pthread_self(); +} + +static void record_wrunlock() { + sendpdbg_assert(pthread_equal(pthread_self(), wrlocker)); + sendpdbg_assert(wrlocked); + pdbg_assert(pthread_equal(pthread_self(), wrlocker)); + pdbg_assert(wrlocked); + wrlocked = 0; +} + +static void record_rdlock(const char *file, unsigned line, + struct timespec *tm) { + rd_lock_data *lock; + lock = malloc(sizeof(rd_lock_data)); + lock->file = file; + lock->thread = psync_thread_name; + lock->line = line; + memcpy(&lock->tm, tm, sizeof(struct timespec)); + pthread_mutex_lock(&rdmutex); + psync_list_add_tail(&rdlocks, &lock->list); + pthread_mutex_unlock(&rdmutex); + rdlock = lock; +} + +static rd_lock_data *record_rdunlock() { + rd_lock_data *lock; + pdbg_assert(rdlock); + lock = rdlock; + rdlock = NULL; + pthread_mutex_lock(&rdmutex); + psync_list_del(&lock->list); + pthread_mutex_unlock(&rdmutex); + return lock; +} + +// -------------------------------------------------------------------------- +// Public debug functions +// -------------------------------------------------------------------------- + +void psql_dump_locks() { + rd_lock_data *lock; + char dttime[36]; + if (wrlocked) { + putil_time_format(lockstart.tv_sec, lockstart.tv_nsec, dttime); + pdbg_logf(D_ERROR, "write lock taken by thread %s from %s:%u at %s", + wrlockthread, wrlockfile, wrlockline, dttime); + sendpdbg_logf("write lock taken by thread %s from %s:%u at %s", wrlockthread, + wrlockfile, wrlockline, dttime); + } + pthread_mutex_lock(&rdmutex); + psync_list_for_each_element(lock, &rdlocks, rd_lock_data, list) { + putil_time_format(lock->tm.tv_sec, lock->tm.tv_nsec, dttime); + pdbg_logf(D_ERROR, "read lock taken by thread %s from %s:%u at %s", + lock->thread, lock->file, lock->line, dttime); + sendpdbg_logf("read lock taken by thread %s from %s:%u at %s", lock->thread, + lock->file, lock->line, dttime); + } + pthread_mutex_unlock(&rdmutex); +} + +int psql_do_trylock(const char *file, unsigned line) { + if (plocks_trywrlock(&dblock)) + return -1; + if (++lockctr == 1) { + clock_gettime(CLOCK_REALTIME, &lockstart); + record_wrlock(file, line); + } + return 0; +} + +void psql_do_lock(const char *file, unsigned line) { + if (plocks_trywrlock(&dblock)) { + struct timespec start, end; + unsigned long msec; + clock_gettime(CLOCK_REALTIME, &start); + memcpy(&end, &start, sizeof(end)); + end.tv_sec += PSYNC_DEBUG_LOCK_TIMEOUT; + if (plocks_timedwrlock(&dblock, &end)) { + pdbg_logf(D_BUG, "sql write lock timed out called from %s:%u", file, line); + sendpdbg_logf("sql write lock timed out called from %s:%u", file, line); + psql_dump_locks(); + abort(); + } + clock_gettime(CLOCK_REALTIME, &end); + msec = (end.tv_sec - start.tv_sec) * 1000 + end.tv_nsec / 1000000 - + start.tv_nsec / 1000000; + if (msec >= 1000) + pdbg_logf(D_ERROR, "waited %lu milliseconds for database write lock", msec); + else if (msec >= 250) + pdbg_logf(D_WARNING, "waited %lu milliseconds for database write lock", msec); + else if (msec >= 5) + pdbg_logf(D_BUG, "waited %lu milliseconds for database write lock", msec); + pdbg_assert(lockctr == 0); + lockctr++; + memcpy(&lockstart, &end, sizeof(struct timespec)); + record_wrlock(file, line); + } else if (++lockctr == 1) { + clock_gettime(CLOCK_REALTIME, &lockstart); + record_wrlock(file, line); + } +} + +void psql_do_rdlock(const char *file, unsigned line) { + if (plocks_tryrdlock(&dblock)) { + struct timespec start, end; + unsigned long msec; + clock_gettime(CLOCK_REALTIME, &start); + memcpy(&end, &start, sizeof(end)); + end.tv_sec += PSYNC_DEBUG_LOCK_TIMEOUT; + if (plocks_timedrdlock(&dblock, &end)) { + pdbg_logf(D_BUG, "sql read lock timed out, called from %s:%u", file, line); + sendpdbg_logf("sql read lock timed out, called from %s:%u", file, line); + psql_dump_locks(); + abort(); + } + clock_gettime(CLOCK_REALTIME, &end); + msec = (end.tv_sec - start.tv_sec) * 1000 + end.tv_nsec / 1000000 - + start.tv_nsec / 1000000; + if (msec >= 1000) + pdbg_logf(D_ERROR, "waited %lu milliseconds for database read lock", msec); + else if (msec >= 250) + pdbg_logf(D_WARNING, "waited %lu milliseconds for database read lock", msec); + else if (msec >= 5) + pdbg_logf(D_BUG, "waited %lu milliseconds for database read lock", msec); + rdlockctr++; + memcpy(&rdlockstart, &end, sizeof(struct timespec)); + record_rdlock(file, line, &rdlockstart); + } else if (++rdlockctr == 1) { + clock_gettime(CLOCK_REALTIME, &rdlockstart); + record_rdlock(file, line, &rdlockstart); + } +} + +// -------------------------------------------------------------------------- +// Strong overrides for same-named functions (weak in psql.c) +// -------------------------------------------------------------------------- + +void psql_lock() { + psql_do_lock(__FILE__, __LINE__); +} + +void psql_rdlock() { + psql_do_rdlock(__FILE__, __LINE__); +} + +void psql_unlock() { + pdbg_assert(lockctr > 0); + if (--lockctr == 0) { + struct timespec end; + unsigned long msec; + clock_gettime(CLOCK_REALTIME, &end); + msec = (end.tv_sec - lockstart.tv_sec) * 1000 + end.tv_nsec / 1000000 - + lockstart.tv_nsec / 1000000; + if (msec >= 2000) + pdbg_logf(D_ERROR, + "held database write lock for %lu milliseconds taken from %s:%u", + msec, wrlockfile, wrlockline); + else if (msec >= 500) + pdbg_logf(D_WARNING, + "held database write lock for %lu milliseconds taken from %s:%u", + msec, wrlockfile, wrlockline); + else if (msec >= 10) + pdbg_logf(D_BUG, + "held database write lock for %lu milliseconds taken from %s:%u", + msec, wrlockfile, wrlockline); + record_wrunlock(); + plocks_unlock(&dblock); + } else + plocks_unlock(&dblock); +} + +void psql_rdunlock() { + if (unlikely(rdlockctr == 0)) { + psql_unlock(); + return; + } + if (--rdlockctr == 0) { + struct timespec end; + unsigned long msec; + rd_lock_data *lock; + plocks_unlock(&dblock); + clock_gettime(CLOCK_REALTIME, &end); + lock = record_rdunlock(); + msec = (end.tv_sec - rdlockstart.tv_sec) * 1000 + end.tv_nsec / 1000000 - + rdlockstart.tv_nsec / 1000000; + if (msec >= 2000) + pdbg_logf(D_ERROR, + "held database read lock for %lu milliseconds taken at %s:%u", msec, + lock->file, lock->line); + else if (msec >= 500) + pdbg_logf(D_WARNING, + "held database read lock for %lu milliseconds taken at %s:%u", msec, + lock->file, lock->line); + else if (msec >= 20) + pdbg_logf(D_BUG, + "held database read lock for %lu milliseconds taken at %s:%u", msec, + lock->file, lock->line); + free(lock); + } else + plocks_unlock(&dblock); +} + +int psql_tryupgradeLock() { + if (plocks_holding_wrlock(&dblock)) + return 0; + pdbg_assert(plocks_holding_rdlock(&dblock)); + if (plocks_towrlock(&dblock)) + return -1; + else { + rd_lock_data *lock = record_rdunlock(); + lockctr = rdlockctr; + rdlockctr = 0; + pdbg_assert(lockctr == 1); + lockstart = rdlockstart; + record_wrlock(lock->file, lock->line); + free(lock); + return 0; + } +} + +// -------------------------------------------------------------------------- +// Debug variants of query/prepare functions (called via psql.h macros) +// -------------------------------------------------------------------------- + +int psql_statement(const char *sql) { + char *errmsg; + int code; + psql_do_lock(__FILE__, __LINE__); + code = sqlite3_exec(psync_db, sql, NULL, NULL, &errmsg); + psql_unlock(); + if (likely(code == SQLITE_OK)) + return 0; + else { + pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, errmsg); + sqlite3_free(errmsg); + return -1; + } +} + +int psql_do_statement(const char *sql, const char *file, unsigned line) { + char *errmsg; + int code; + psql_do_lock(file, line); + code = sqlite3_exec(psync_db, sql, NULL, NULL, &errmsg); + psql_unlock(); + if (likely(code == SQLITE_OK)) + return 0; + else { + pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", + sql, errmsg, file, line); + sqlite3_free(errmsg); + return -1; + } +} + +int psql_do_start_transaction(const char *file, unsigned line) { + psync_sql_res *res; + psql_do_lock(file, line); + res = psql_do_prepare("BEGIN", file, line); + pdbg_assert(!in_transaction); + if (unlikely(!res || psql_run_free(res))) + return -1; + in_transaction = 1; + transaction_failed = 0; + psync_list_init(&commitcbs); + return 0; +} + +psync_sql_res *psql_do_query_nocache(const char *sql, const char *file, + unsigned line) { + sqlite3_stmt *stmt; + psync_sql_res *res; + int code, cnt; + psql_do_lock(file, line); + code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); + if (unlikely(code != SQLITE_OK)) { + psql_unlock(); + pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", + sql, sqlite3_errmsg(psync_db), file, line); + sendpdbg_logf("error running sql statement: %s: %s called from %s:%u", + sql, sqlite3_errmsg(psync_db), file, line); + return NULL; + } + cnt = sqlite3_column_count(stmt); + res = (psync_sql_res *)malloc(sizeof(psync_sql_res) + + cnt * sizeof(psync_variant)); + res->stmt = stmt; + res->sql = sql; + res->column_count = cnt; + res->locked = SQL_WRITE_LOCK; + return res; +} + +psync_sql_res *psql_do_query(const char *sql, const char *file, + unsigned line) { + psync_sql_res *ret; + ret = (psync_sql_res *)pcache_get(sql); + if (ret) { + ret->locked = SQL_WRITE_LOCK; + ret->sql = sql; + psql_do_lock(file, line); + return ret; + } else + return psql_do_query_nocache(sql, file, line); +} + +psync_sql_res *psql_do_query_rdlock_nocache(const char *sql, + const char *file, + unsigned line) { + sqlite3_stmt *stmt; + psync_sql_res *res; + int code, cnt; + psql_do_rdlock(file, line); + code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); + if (unlikely(code != SQLITE_OK)) { + psql_rdunlock(); + pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", + sql, sqlite3_errmsg(psync_db), file, line); + sendpdbg_logf("error running sql statement: %s: %s called from %s:%u", + sql, sqlite3_errmsg(psync_db), file, line); + return NULL; + } + cnt = sqlite3_column_count(stmt); + res = (psync_sql_res *)malloc(sizeof(psync_sql_res) + + cnt * sizeof(psync_variant)); + res->stmt = stmt; + res->sql = sql; + res->column_count = cnt; + res->locked = SQL_READ_LOCK; + return res; +} + +psync_sql_res *psql_do_query_rdlock(const char *sql, const char *file, + unsigned line) { + psync_sql_res *ret; + ret = (psync_sql_res *)pcache_get(sql); + if (ret) { + ret->locked = SQL_READ_LOCK; + ret->sql = sql; + psql_do_rdlock(file, line); + return ret; + } else + return psql_do_query_rdlock_nocache(sql, file, line); +} + +psync_sql_res *psql_do_query_nolock_nocache(const char *sql, const char *file, + unsigned line) { + sqlite3_stmt *stmt; + psync_sql_res *res; + int code, cnt; + if (!psql_locked()) { + pdbg_logf(D_BUG, + "illegal use of psync_sql_query_nolock, can only be used while " + "holding lock, invoked from %s:%u, sql: %s", + file, line, sql); + sendpdbg_logf("illegal use of psync_sql_query_nolock, can only be used while " + "holding lock, invoked from %s:%u, sql: %s", + file, line, sql); + abort(); + } + code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); + if (unlikely(code != SQLITE_OK)) { + pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, + sqlite3_errmsg(psync_db)); + sendpdbg_logf("error running sql statement: %s: %s", sql, + sqlite3_errmsg(psync_db)); + return NULL; + } + cnt = sqlite3_column_count(stmt); + res = (psync_sql_res *)malloc(sizeof(psync_sql_res) + + cnt * sizeof(psync_variant)); + res->stmt = stmt; + res->sql = sql; + res->column_count = cnt; + res->locked = SQL_NO_LOCK; + return res; +} + +psync_sql_res *psql_do_query_nolock(const char *sql, const char *file, + unsigned line) { + psync_sql_res *ret; + if (!psql_locked()) { + pdbg_logf(D_BUG, + "illegal use of psync_sql_query_nolock, can only be used while " + "holding lock, invoked from %s:%u, sql: %s", + file, line, sql); + sendpdbg_logf("illegal use of psync_sql_query_nolock, can only be used while " + "holding lock, invoked from %s:%u, sql: %s", + file, line, sql); + abort(); + } + ret = (psync_sql_res *)pcache_get(sql); + if (ret) { + ret->locked = SQL_NO_LOCK; + ret->sql = sql; + return ret; + } else + return psql_do_query_nolock_nocache(sql, file, line); +} + +psync_sql_res *psql_do_prepare_nocache(const char *sql, const char *file, + unsigned line) { + sqlite3_stmt *stmt; + psync_sql_res *res; + int code; + psql_do_lock(file, line); + code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); + if (unlikely(code != SQLITE_OK)) { + psql_unlock(); + pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", + sql, sqlite3_errmsg(psync_db), file, line); + sendpdbg_logf("error running sql statement: %s: %s called from %s:%u", + sql, sqlite3_errmsg(psync_db), file, line); + return NULL; + } + res = malloc(sizeof(psync_sql_res)); + res->stmt = stmt; + res->sql = sql; + res->column_count = 0; + res->locked = SQL_WRITE_LOCK; + return res; +} + +psync_sql_res *psql_do_prepare(const char *sql, const char *file, + unsigned line) { + psync_sql_res *ret; + ret = pcache_get(sql); + if (ret) { + ret->locked = SQL_WRITE_LOCK; + psql_do_lock(file, line); + return ret; + } else + return psql_do_prepare_nocache(sql, file, line); +} diff --git a/pclsync/debug/psys_debug.c b/pclsync/debug/psys_debug.c new file mode 100644 index 0000000..339f6ed --- /dev/null +++ b/pclsync/debug/psys_debug.c @@ -0,0 +1,27 @@ +// debug/psys_debug.c - debug implementations for psys debug helpers + +#include +#include + +#include "pdbg.h" +#include "psql.h" +#include "psys.h" + +void psys_debug_abort_on_sqllock(uint64_t millisec) { + if (psql_locked()) { + pdbg_logf(D_CRITICAL, "trying to sleep while holding sql lock, aborting"); + psql_dump_locks(); + abort(); + } +} + +void psys_debug_configure_core_dump() { + struct rlimit limit; + if (getrlimit(RLIMIT_CORE, &limit)) + pdbg_logf(D_ERROR, "getrlimit failed errno=%d", errno); + else { + limit.rlim_cur = limit.rlim_max; + if (setrlimit(RLIMIT_CORE, &limit)) + pdbg_logf(D_ERROR, "setrlimit failed errno=%d", errno); + } +} diff --git a/pclsync/papi.c b/pclsync/papi.c index 8b3277c..80cacc9 100644 --- a/pclsync/papi.c +++ b/pclsync/papi.c @@ -629,9 +629,8 @@ const binresult *papi_find_result(const binresult *res, const char *name, if (D_CRITICAL <= DEBUG_LEVEL) pdbg_printf(file, function, line, D_CRITICAL, "could not find key %s", name); -#if IS_DEBUG - papi_dump(res, file, function, line); -#endif + if (IS_DEBUG) + papi_dump(res, file, function, line); return empty_types[type]; } diff --git a/pclsync/pfs.c b/pclsync/pfs.c index b5a72ad..ef8b352 100644 --- a/pclsync/pfs.c +++ b/pclsync/pfs.c @@ -75,16 +75,10 @@ typedef off_t fuse_off_t; #include -#if IS_DEBUG #define pfs_set_thread_name() \ do { \ - psync_thread_name = __FUNCTION__; \ + if (IS_DEBUG) psync_thread_name = __FUNCTION__; \ } while (0) -#else -#define pfs_set_thread_name() \ - do { \ - } while (0) -#endif #define fh_to_openfile(x) ((psync_openfile_t *)((uintptr_t)x)) #define openfile_to_fh(x) ((uintptr_t)x) @@ -115,7 +109,13 @@ static gid_t mygid = 0; extern int errno; -static psync_tree *openfiles = PSYNC_TREE_EMPTY; +psync_tree *openfiles = PSYNC_TREE_EMPTY; + +__attribute__((weak)) void pfs_debug_init_file_mutex(pthread_mutex_t *m) { + pthread_mutex_init(m, NULL); +} +__attribute__((weak)) void pfs_debug_dump_internals() {} +__attribute__((weak)) void pfs_debug_register_signal_handlers() {} static int pfs_ftruncate_of_locked(psync_openfile_t *of, fuse_off_t size); @@ -1022,17 +1022,7 @@ pfs_create_file(psync_fsfileid_t fileid, psync_fsfileid_t remotefileid, ptree_add_before(&openfiles, tr, &fl->tree); else ptree_add_after(&openfiles, tr, &fl->tree); -#if IS_DEBUG - { - pthread_mutexattr_t mattr; - pthread_mutexattr_init(&mattr); - pthread_mutexattr_settype(&mattr, PTHREAD_MUTEX_ERRORCHECK); - pthread_mutex_init(&fl->mutex, &mattr); - pthread_mutexattr_destroy(&mattr); - } -#else - pthread_mutex_init(&fl->mutex, NULL); -#endif + pfs_debug_init_file_mutex(&fl->mutex); fl->currentfolder = folder; fl->currentname = putil_strdup(name); fl->fileid = fileid; @@ -3490,21 +3480,6 @@ char *pfs_get_path_by_fileid(psync_fileid_t fileid) { return ret; } -#if IS_DEBUG - -static void pfs_dump_internals() { - psync_openfile_t *of; - pdbg_logf(D_NOTICE, "dumping internal state"); - psql_rdlock(); - ptree_for_each_element(of, openfiles, psync_openfile_t, tree) - pdbg_logf(D_NOTICE, "open file %s fileid %ld folderid %ld", of->currentname, - (long)of->fileid, (long)of->currentfolder->folderid); - pfs_task_dump_state(); - psql_rdunlock(); -} - -#endif - static void pfs_do_stop(void) { if (!__sync_bool_compare_and_swap(&shutdown_in_progress, 0, 1)) { // prevent multiple executions @@ -3561,9 +3536,7 @@ static void pfs_do_stop(void) { pdbg_logf(D_NOTICE, "waited for fuse to exit"); } -#if IS_DEBUG - pfs_dump_internals(); -#endif + pfs_debug_dump_internals(); free(mp); } pthread_mutex_unlock(&start_mutex); @@ -3576,13 +3549,6 @@ static void psync_signal_handler(int sig) { exit(1); // invoke psync_do_stop via atexit() } -#if IS_DEBUG -static void psync_usr1_handler(int sig) { - // pdbg_logf(D_NOTICE, "got signal %d", sig); - prun_thread("dump signal", pfs_dump_internals); -} -#endif - static void psync_usr2_handler(int sig) { /* Signal handler must be signal-safe - just set flag, don't log here */ pdbg_reopen_log(); @@ -3607,9 +3573,7 @@ static void psync_setup_signals() { psync_set_signal(SIGTERM, psync_signal_handler); psync_set_signal(SIGINT, psync_signal_handler); psync_set_signal(SIGHUP, psync_signal_handler); -#if IS_DEBUG - psync_set_signal(SIGUSR1, psync_usr1_handler); -#endif + pfs_debug_register_signal_handlers(); psync_set_signal(SIGUSR2, psync_usr2_handler); } diff --git a/pclsync/pfs.h b/pclsync/pfs.h index 61975d5..a7c9ac0 100644 --- a/pclsync/pfs.h +++ b/pclsync/pfs.h @@ -191,4 +191,8 @@ void pfs_refresh_folder(psync_folderid_t folderid); void pfs_pause_until_login(); void pfs_clean_tasks(); +void pfs_debug_init_file_mutex(pthread_mutex_t *m); +void pfs_debug_dump_internals(); +void pfs_debug_register_signal_handlers(); + #endif diff --git a/pclsync/pfs_internal.h b/pclsync/pfs_internal.h new file mode 100644 index 0000000..d3702a8 --- /dev/null +++ b/pclsync/pfs_internal.h @@ -0,0 +1,11 @@ +// pfs_internal.h - internal state shared between pfs.c and debug/pfs_debug.c +// Do NOT include this header from any file other than pfs.c and debug/pfs_debug.c. + +#ifndef PFS_INTERNAL_H +#define PFS_INTERNAL_H + +#include "ptree.h" + +extern psync_tree *openfiles; + +#endif diff --git a/pclsync/pfscrypto.c b/pclsync/pfscrypto.c index f819d58..b6c2c40 100644 --- a/pclsync/pfscrypto.c +++ b/pclsync/pfscrypto.c @@ -44,9 +44,6 @@ #include "psql.h" // this is only for debug, adds needless checks of tree for local files -#if IS_DEBUG -#define PSYNC_DO_LOCAL_FULL_TREE_CHECK 1 -#endif #define PSYNC_CRYPTO_LOG_DATA 1 #define PSYNC_CRYPTO_LOG_INT 2 @@ -270,7 +267,6 @@ static psync_crypto_sectorid_t get_last_sectorid_by_size(uint64_t size) { return (size - 1) / PSYNC_CRYPTO_SECTOR_SIZE; } -#if defined(PSYNC_DO_LOCAL_FULL_TREE_CHECK) static int pfs_crypto_do_local_tree_check(psync_openfile_t *of, psync_crypto_sectorid_t sectorid, @@ -328,7 +324,6 @@ pfs_crypto_do_local_tree_check(psync_openfile_t *of, } return 0; } -#endif static int pfs_crypto_wait_no_extender_locked(psync_openfile_t *of) { int ret; @@ -421,10 +416,8 @@ static int pfs_crypto_read_newfile_full_sector_from_datafile( if (pdbg_unlikely(pcrypto_decode_sec( of->encoder, buff, ssize, (unsigned char *)buf, auth, sectorid))) return -EIO; -#if defined(PSYNC_DO_LOCAL_FULL_TREE_CHECK) - else if (pfs_crypto_do_local_tree_check(of, sectorid, &offsets)) + else if (IS_DEBUG && pfs_crypto_do_local_tree_check(of, sectorid, &offsets)) return -EIO; -#endif else return ssize; } @@ -780,14 +773,14 @@ pfs_crypto_check_log_hash(int lfd, pcrc32c_fast_hash256_final(chash, &ctx); if (memcmp(chash, mr->hash, PSYNC_FAST_HASH256_LEN)) { pdbg_logf(D_WARNING, "calculated hash does not match"); -#if IS_DEBUG - psync_binhex(buff, chash, PSYNC_FAST_HASH256_LEN); - buff[PSYNC_FAST_HASH256_LEN * 2] = 0; - pdbg_logf(D_NOTICE, "calculated: %s", buff); - psync_binhex(buff, mr->hash, PSYNC_FAST_HASH256_LEN); - buff[PSYNC_FAST_HASH256_LEN * 2] = 0; - pdbg_logf(D_NOTICE, "expected: %s", buff); -#endif + if (IS_DEBUG) { + psync_binhex(buff, chash, PSYNC_FAST_HASH256_LEN); + buff[PSYNC_FAST_HASH256_LEN * 2] = 0; + pdbg_logf(D_NOTICE, "calculated: %s", buff); + psync_binhex(buff, mr->hash, PSYNC_FAST_HASH256_LEN); + buff[PSYNC_FAST_HASH256_LEN * 2] = 0; + pdbg_logf(D_NOTICE, "expected: %s", buff); + } return -1; } else { pdbg_logf(D_NOTICE, "successfully checked log hash"); diff --git a/pclsync/pfstasks.c b/pclsync/pfstasks.c index ae4f532..1ff8d19 100644 --- a/pclsync/pfstasks.c +++ b/pclsync/pfstasks.c @@ -54,7 +54,7 @@ typedef struct { char name[]; } file_history_record; -static psync_tree *folders = PSYNC_TREE_EMPTY; +psync_tree *folders = PSYNC_TREE_EMPTY; static uint64_t psync_local_taskid = UINT64_MAX; static inline int psync_crypto_is_error(const void *ptr) { @@ -177,14 +177,11 @@ pfs_task_get_folder_tasks_rdlocked(psync_fsfolderid_t folderid) { return NULL; } +__attribute__((weak)) void pfstasks_debug_check_folder_consistency(psync_fstask_folder_t *folder) {} +__attribute__((weak)) void pfs_task_dump_state() {} + void pfs_task_release_folder_tasks_locked(psync_fstask_folder_t *folder) { -#if IS_DEBUG - if ((!!folder->taskscnt) != - (folder->creats || folder->mkdirs || folder->rmdirs || folder->unlinks)) - pdbg_logf(D_ERROR, "taskcnt=%u, c=%p, m=%p, r=%p, u=%p", - (unsigned)folder->taskscnt, folder->creats, folder->mkdirs, - folder->rmdirs, folder->unlinks); -#endif + pfstasks_debug_check_folder_consistency(folder); if (--folder->refcnt == 0 && !folder->taskscnt) { pdbg_logf(D_NOTICE, "releasing folder id %ld", (long int)folder->folderid); ptree_del(&folders, &folder->tree); @@ -2166,48 +2163,3 @@ void pfs_task_init() { pfs_upld_init(); } -#if IS_DEBUG - -void pfs_task_dump_state() { - psync_fstask_folder_t *folder; - psync_fstask_mkdir_t *mk; - psync_fstask_rmdir_t *rm; - psync_fstask_creat_t *cr; - psync_fstask_unlink_t *un; - uint32_t cnt; - ptree_for_each_element(folder, folders, psync_fstask_folder_t, tree) { - pdbg_logf(D_NOTICE, "open folderid %ld taskcnt %u refcnt %u", - (long)folder->folderid, (unsigned)folder->taskscnt, - (unsigned)folder->refcnt); - cnt = 0; - ptree_for_each_element(mk, folder->mkdirs, psync_fstask_mkdir_t, - tree) { - pdbg_logf(D_NOTICE, " mkdir %s folderid %ld taskid %lu", mk->name, - (long)mk->folderid, (unsigned long)mk->taskid); - cnt++; - } - ptree_for_each_element(rm, folder->rmdirs, psync_fstask_rmdir_t, - tree) { - pdbg_logf(D_NOTICE, " mkdir %s folderid %ld taskid %lu", rm->name, - (long)rm->folderid, (unsigned long)rm->taskid); - cnt++; - } - ptree_for_each_element(cr, folder->creats, psync_fstask_creat_t, - tree) { - pdbg_logf(D_NOTICE, " creat %s fileid %ld taskid %lu", cr->name, - (long)cr->fileid, (unsigned long)cr->taskid); - cnt++; - } - ptree_for_each_element(un, folder->unlinks, psync_fstask_unlink_t, - tree) { - pdbg_logf(D_NOTICE, " unlink %s fileid %ld taskid %lu", un->name, - (long)un->fileid, (unsigned long)un->taskid); - cnt++; - } - if (cnt != folder->taskscnt) - pdbg_logf(D_ERROR, "inconsistency found, counted taskcnt %u != taskcnt %u", - (unsigned)cnt, (unsigned)folder->taskscnt); - } -} - -#endif diff --git a/pclsync/pfstasks.h b/pclsync/pfstasks.h index 0faf8eb..f28edc6 100644 --- a/pclsync/pfstasks.h +++ b/pclsync/pfstasks.h @@ -221,8 +221,7 @@ void pfs_task_clean(); void pfs_task_add_banned_folders(); -#if IS_DEBUG void pfs_task_dump_state(); -#endif +void pfstasks_debug_check_folder_consistency(psync_fstask_folder_t *folder); #endif diff --git a/pclsync/pfstasks_internal.h b/pclsync/pfstasks_internal.h new file mode 100644 index 0000000..c275d2a --- /dev/null +++ b/pclsync/pfstasks_internal.h @@ -0,0 +1,11 @@ +// pfstasks_internal.h - internal state shared between pfstasks.c and debug/pfstasks_debug.c +// Do NOT include this header from any file other than pfstasks.c and debug/pfstasks_debug.c. + +#ifndef PFSTASKS_INTERNAL_H +#define PFSTASKS_INTERNAL_H + +#include "ptree.h" + +extern psync_tree *folders; + +#endif diff --git a/pclsync/pfsxattr.c b/pclsync/pfsxattr.c index 1756239..f294bae 100644 --- a/pclsync/pfsxattr.c +++ b/pclsync/pfsxattr.c @@ -44,16 +44,10 @@ // needed by pfs_xatr_set_thread_name extern PSYNC_THREAD const char *psync_thread_name; -#if IS_DEBUG #define pfs_xatr_set_thread_name() \ do { \ - psync_thread_name = __FUNCTION__; \ + if (IS_DEBUG) psync_thread_name = __FUNCTION__; \ } while (0) -#else -#define pfs_xatr_set_thread_name() \ - do { \ - } while (0) -#endif // Value get from standard xattr.h enum { diff --git a/pclsync/pnetlibs.c b/pclsync/pnetlibs.c index d055afa..fa1b241 100644 --- a/pclsync/pnetlibs.c +++ b/pclsync/pnetlibs.c @@ -255,82 +255,11 @@ binresult *psync_do_api_run_command(const char *command, size_t cmdlen, return NULL; } -#if IS_DEBUG - -void pident(int ident) { - VAR_ARRAY(b, char, ident + 1); - memset(b, '\t', ident); - b[ident] = 0; - fputs(b, stdout); -} - -static void print_tree(const binresult *tree, int ident) { - int i; - if (tree->type == PARAM_STR) - printf("string(%u)\"%s\"", tree->length, tree->str); - else if (tree->type == PARAM_NUM) - printf("number %llu", (unsigned long long)tree->num); - else if (tree->type == PARAM_DATA) - printf("data %llu", (unsigned long long)tree->num); - else if (tree->type == PARAM_BOOL) - printf("bool %s", tree->num ? "true" : "false"); - else if (tree->type == PARAM_HASH) { - printf("hash (%u){\n", tree->length); - if (tree->length) { - pident(ident + 1); - printf("\"%s\" = ", tree->hash[0].key); - print_tree(tree->hash[0].value, ident + 1); - for (i = 1; i < tree->length; i++) { - printf(",\n"); - pident(ident + 1); - printf("\"%s\" = ", tree->hash[i].key); - print_tree(tree->hash[i].value, ident + 1); - } - } - printf("\n"); - pident(ident); - printf("}"); - } else if (tree->type == PARAM_ARRAY) { - printf("array (%u)[\n", tree->length); - if (tree->length) { - pident(ident + 1); - print_tree(tree->array[0], ident + 1); - for (i = 1; i < tree->length; i++) { - printf(",\n"); - pident(ident + 1); - print_tree(tree->array[i], ident + 1); - } - } - printf("\n"); - pident(ident); - printf("]"); - } -} - -PSYNC_NOINLINE static void psync_apipool_dump_socket(psock_t *api) { - binresult *res; - res = papi_result(api); - psync_apipool_release_bad(api); - if (!res) { - pdbg_logf(D_NOTICE, "could not read result from socket, it is probably broken"); - return; - } - pdbg_logf(D_WARNING, "read result from released socket, dumping and aborting"); - print_tree(res, 0); - free(res); - abort(); -} - -#endif +__attribute__((weak)) int pnetlibs_debug_check_apipool_release(psock_t *api) { return 0; } void psync_apipool_release(psock_t *api) { -#if IS_DEBUG - if (unlikely(psock_readable(api))) { - pdbg_logf(D_WARNING, "released socket with pending data to read"); - psync_apipool_dump_socket(api); + if (pnetlibs_debug_check_apipool_release(api)) return; - } -#endif if (hash_func(apiserver) == api->misc) pcache_add(apikey, api, PSYNC_APIPOOL_MAXIDLESEC, psync_ret_api, PSYNC_APIPOOL_MAXIDLE); diff --git a/pclsync/ppagecache.c b/pclsync/ppagecache.c index dd79029..e2e4c37 100644 --- a/pclsync/ppagecache.c +++ b/pclsync/ppagecache.c @@ -2267,17 +2267,11 @@ static void psync_pagecache_send_error(psync_request_t *request, int err) { if (request->needkey) psync_pagecache_set_bad_encoder(request->of); pfs_dec_of_refcnt_and_readers(request->of); + if (IS_DEBUG) + pdbg_logf(D_NOTICE, "sending request error %d", err); psync_pagecache_free_request(request); } -#if IS_DEBUG -#define psync_pagecache_send_error(r, e) \ - do { \ - psync_pagecache_send_error(r, e); \ - pdbg_logf(D_NOTICE, "sending request error %d", e); \ - } while (0) -#endif - static int psync_pagecache_read_range_from_sock(psync_request_t *request, psync_request_range_t *range, psync_http_socket *sock) { @@ -3226,22 +3220,22 @@ int ppagecache_read_unmod_enc_locked(psync_openfile_t *of, } if (ap->parent && !ret) { #ifdef P_NO_CHECKSUM_CHECK -#if IS_DEBUG - pdbg_logf(D_NOTICE, - "NOT checking chain checksums for pages %lu-%lu tree level %d", - (unsigned long)ap->firstpageid, - (unsigned long)ap->firstpageid + ap->size / PSYNC_CRYPTO_AUTH_SIZE, - (int)offsets.treelevels); - pfs_lock_file(of); - if (likely(of->hash == hash)) - psync_interval_tree_add( - &of->authenticatedints, ap->firstpageid * PSYNC_FS_PAGE_SIZE, - (ap->firstpageid + ap->size / PSYNC_CRYPTO_AUTH_SIZE) * - PSYNC_FS_PAGE_SIZE); - pthread_mutex_unlock(&of->mutex); -#else - abort(); -#endif + if (IS_DEBUG) { + pdbg_logf(D_NOTICE, + "NOT checking chain checksums for pages %lu-%lu tree level %d", + (unsigned long)ap->firstpageid, + (unsigned long)ap->firstpageid + ap->size / PSYNC_CRYPTO_AUTH_SIZE, + (int)offsets.treelevels); + pfs_lock_file(of); + if (likely(of->hash == hash)) + psync_interval_tree_add( + &of->authenticatedints, ap->firstpageid * PSYNC_FS_PAGE_SIZE, + (ap->firstpageid + ap->size / PSYNC_CRYPTO_AUTH_SIZE) * + PSYNC_FS_PAGE_SIZE); + pthread_mutex_unlock(&of->mutex); + } else { + abort(); + } #else pcrypto_sector_auth_t sa; psync_crypto_auth_page *p; diff --git a/pclsync/psock.c b/pclsync/psock.c index 7ee97ce..1272ad2 100644 --- a/pclsync/psock.c +++ b/pclsync/psock.c @@ -53,33 +53,22 @@ typedef struct { static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER; +__attribute__((weak)) void psock_debug_log_wait_latency(const struct timespec *start) {} + static int wait_readable(int sock, long sec, long usec) { fd_set rfds; struct timeval tv; -#if IS_DEBUG - struct timespec start, end; - unsigned long msec; -#endif + struct timespec start; int res; tv.tv_sec = sec; tv.tv_usec = usec; FD_ZERO(&rfds); FD_SET(sock, &rfds); -#if IS_DEBUG clock_gettime(CLOCK_REALTIME, &start); -#endif res = select(sock + 1, &rfds, NULL, NULL, &tv); if (res == 1) { -#if IS_DEBUG - clock_gettime(CLOCK_REALTIME, &end); - msec = (end.tv_sec - start.tv_sec) * 1000 + end.tv_nsec / 1000000 - - start.tv_nsec / 1000000; - if (msec >= 30000) - pdbg_logf(D_WARNING, "got response from socket after %lu milliseconds", msec); - else if (msec >= 5000) - pdbg_logf(D_NOTICE, "got response from socket after %lu milliseconds", msec); -#endif + psock_debug_log_wait_latency(&start); return 0; } if (res == 0) { diff --git a/pclsync/psql.c b/pclsync/psql.c index 5cc738c..57c06e5 100644 --- a/pclsync/psql.c +++ b/pclsync/psql.c @@ -10,8 +10,41 @@ #include "prun.h" #include "psettings.h" #include "psql.h" +#include "psql_internal.h" #include "psys.h" +// psql.h defines function-like macros (e.g. psql_lock() -> psql_do_lock()) +// that would interfere with this file's own function definitions. +// Undefine them here so we can define the actual implementations. +#undef psql_trylock +#undef psql_lock +#undef psql_rdlock +#undef psql_statement +#undef psql_start +#undef psql_query_nocache +#undef psql_query +#undef psql_rdlock_nocache +#undef psql_query_rdlock +#undef psql_query_nolock_nocache +#undef psql_query_nolock +#undef psql_prepare_nocache +#undef psql_prepare + +// Forward declarations for internal use within this translation unit. +int psql_trylock(void); +void psql_lock(void); +void psql_rdlock(void); +int psql_statement(const char *sql); +int psql_start(void); +psync_sql_res *psql_query_nocache(const char *sql); +psync_sql_res *psql_query(const char *sql); +psync_sql_res *psql_rdlock_nocache(const char *sql); +psync_sql_res *psql_query_rdlock(const char *sql); +psync_sql_res *psql_query_nolock_nocache(const char *sql); +psync_sql_res *psql_query_nolock(const char *sql); +psync_sql_res *psql_prepare_nocache(const char *sql); +psync_sql_res *psql_prepare(const char *sql); + #define SQL_NO_LOCK 0 #define SQL_READ_LOCK 1 #define SQL_WRITE_LOCK 2 @@ -22,7 +55,7 @@ #define PSYNC_TNULL 4 #define PSYNC_TBOOL 5 -extern PSYNC_THREAD const char *psync_thread_name; +extern PSYNC_THREAD const char *psync_thread_name; const static char *psync_typenames[] = {"[invalid type]", "[number]", "[string]", "[float]", "[null]", "[bool]"}; @@ -37,35 +70,12 @@ typedef struct { int psync_do_run = 1; // FIXME: app state. papp.c? PSYNC_THREAD uint32_t psync_error = 0; // FIXME: app state. papp.c? -static psync_rwlock_t dblock; -static sqlite3 *psync_db; +psync_rwlock_t dblock; +sqlite3 *psync_db; static pthread_mutex_t cpmutex; -static int in_transaction = 0; -static int transaction_failed = 0; -static psync_list commitcbs; - -#if IS_DEBUG -typedef struct { - psync_list list; - const char *file; - const char *thread; - struct timespec tm; - unsigned line; -} rd_lock_data; - -static PSYNC_THREAD rd_lock_data *rdlock = NULL; -static PSYNC_THREAD unsigned long rdlockctr = 0; -static PSYNC_THREAD struct timespec rdlockstart; -unsigned long lockctr = 0; -static struct timespec lockstart; -static const char *wrlockfile = "none"; -static const char *wrlockthread = ""; -static unsigned wrlockline = 0; -static unsigned wrlocked = 0; -static pthread_t wrlocker; -static psync_list rdlocks = PSYNC_LIST_STATIC_INIT(rdlocks); -static pthread_mutex_t rdmutex = PTHREAD_MUTEX_INITIALIZER; -#endif +int in_transaction = 0; +int transaction_failed = 0; +psync_list commitcbs; static void on_error(void *ptr, int code, const char *msg) { pdbg_logf(D_WARNING, "database warning %d: %s", code, msg); @@ -74,9 +84,8 @@ static void on_error(void *ptr, int code, const char *msg) { static void psync_sql_free_cache(void *ptr) { psync_sql_res *res = (psync_sql_res *)ptr; sqlite3_finalize(res->stmt); -#if IS_DEBUG - memset(res, 0xff, sizeof(psync_sql_res)); -#endif + if (IS_DEBUG) + memset(res, 0xff, sizeof(psync_sql_res)); free(res); } @@ -90,11 +99,12 @@ static void psync_sql_res_unlock(psync_sql_res *res) { case SQL_WRITE_LOCK: psql_unlock(); break; -#if IS_DEBUG default: - pdbg_logf(D_ERROR, "unknown value for locked %d", res->locked); - abort(); -#endif + if (IS_DEBUG) { + pdbg_logf(D_ERROR, "unknown value for locked %d", res->locked); + abort(); + } + break; } } @@ -140,163 +150,25 @@ static void commit(int success) { } } -#if IS_DEBUG +__attribute__((weak)) int psql_trylock() { return plocks_trywrlock(&dblock); } +__attribute__((weak)) void psql_lock() { plocks_wrlock(&dblock); } +__attribute__((weak)) void psql_unlock() { plocks_unlock(&dblock); } +__attribute__((weak)) void psql_rdlock() { plocks_rdlock(&dblock); } +__attribute__((weak)) void psql_rdunlock() { plocks_unlock(&dblock); } -static void record_wrlock(const char *file, unsigned line) { - if (unlikely(rdlock)) { - pdbg_logf(D_BUG, - "trying to get write lock at %s:%u, but read lock is already taken " - "at %s:%u, aborting", - file, line, rdlock->file, rdlock->line); - sendpdbg_logf("trying to get write lock at %s:%u, but read lock is already " - "taken at %s:%u, aborting", - file, line, rdlock->file, rdlock->line); - abort(); - } - sendpdbg_assert(!wrlocked); - pdbg_assert(!wrlocked); - wrlockfile = file; - wrlockline = line; - wrlockthread = psync_thread_name; - wrlocked = 1; - wrlocker = pthread_self(); +// psql_do_* weak stubs: release-mode forwarding wrappers. +// Callers always use the psql_do_* names (via psql.h macro expansion). +// debug/psql_debug.c provides strong overrides with lock tracking. +__attribute__((weak)) int psql_do_trylock(const char *file, unsigned line) { + return psql_trylock(); } - -static void record_wrunlock() { - sendpdbg_assert(pthread_equal(pthread_self(), wrlocker)); - sendpdbg_assert(wrlocked); - pdbg_assert(pthread_equal(pthread_self(), wrlocker)); - pdbg_assert(wrlocked); - wrlocked = 0; +__attribute__((weak)) void psql_do_lock(const char *file, unsigned line) { + psql_lock(); } - -static void record_rdlock(const char *file, unsigned line, - struct timespec *tm) { - rd_lock_data *lock; - lock = malloc(sizeof(rd_lock_data)); - lock->file = file; - lock->thread = psync_thread_name; - lock->line = line; - memcpy(&lock->tm, tm, sizeof(struct timespec)); - pthread_mutex_lock(&rdmutex); - psync_list_add_tail(&rdlocks, &lock->list); - pthread_mutex_unlock(&rdmutex); - rdlock = lock; +__attribute__((weak)) void psql_do_rdlock(const char *file, unsigned line) { + psql_rdlock(); } -static rd_lock_data *record_rdunlock() { - rd_lock_data *lock; - pdbg_assert(rdlock); - lock = rdlock; - rdlock = NULL; - pthread_mutex_lock(&rdmutex); - psync_list_del(&lock->list); - pthread_mutex_unlock(&rdmutex); - return lock; -} - -void psql_dump_locks() { - rd_lock_data *lock; - char dttime[36]; - if (wrlocked) { - putil_time_format(lockstart.tv_sec, lockstart.tv_nsec, dttime); - pdbg_logf(D_ERROR, "write lock taken by thread %s from %s:%u at %s", - wrlockthread, wrlockfile, wrlockline, dttime); - sendpdbg_logf("write lock taken by thread %s from %s:%u at %s", wrlockthread, - wrlockfile, wrlockline, dttime); - } - pthread_mutex_lock(&rdmutex); - psync_list_for_each_element(lock, &rdlocks, rd_lock_data, list) { - putil_time_format(lock->tm.tv_sec, lock->tm.tv_nsec, dttime); - pdbg_logf(D_ERROR, "read lock taken by thread %s from %s:%u at %s", - lock->thread, lock->file, lock->line, dttime); - sendpdbg_logf("read lock taken by thread %s from %s:%u at %s", lock->thread, - lock->file, lock->line, dttime); - } - pthread_mutex_unlock(&rdmutex); -} - -int psql_do_trylock(const char *file, unsigned line) { - if (plocks_trywrlock(&dblock)) - return -1; - if (++lockctr == 1) { - clock_gettime(CLOCK_REALTIME, &lockstart); - record_wrlock(file, line); - } - return 0; -} - -void psql_do_lock(const char *file, unsigned line) { - if (plocks_trywrlock(&dblock)) { - struct timespec start, end; - unsigned long msec; - clock_gettime(CLOCK_REALTIME, &start); - memcpy(&end, &start, sizeof(end)); - end.tv_sec += PSYNC_DEBUG_LOCK_TIMEOUT; - if (plocks_timedwrlock(&dblock, &end)) { - pdbg_logf(D_BUG, "sql write lock timed out called from %s:%u", file, line); - sendpdbg_logf("sql write lock timed out called from %s:%u", file, line); - psql_dump_locks(); - abort(); - } - clock_gettime(CLOCK_REALTIME, &end); - msec = (end.tv_sec - start.tv_sec) * 1000 + end.tv_nsec / 1000000 - - start.tv_nsec / 1000000; - if (msec >= 1000) - pdbg_logf(D_ERROR, "waited %lu milliseconds for database write lock", msec); - else if (msec >= 250) - pdbg_logf(D_WARNING, "waited %lu milliseconds for database write lock", msec); - else if (msec >= 5) - pdbg_logf(D_BUG, "waited %lu milliseconds for database write lock", msec); - pdbg_assert(lockctr == 0); - lockctr++; - memcpy(&lockstart, &end, sizeof(struct timespec)); - record_wrlock(file, line); - } else if (++lockctr == 1) { - clock_gettime(CLOCK_REALTIME, &lockstart); - record_wrlock(file, line); - } -} - -void psql_do_rdlock(const char *file, unsigned line) { - if (plocks_tryrdlock(&dblock)) { - struct timespec start, end; - unsigned long msec; - clock_gettime(CLOCK_REALTIME, &start); - memcpy(&end, &start, sizeof(end)); - end.tv_sec += PSYNC_DEBUG_LOCK_TIMEOUT; - if (plocks_timedrdlock(&dblock, &end)) { - pdbg_logf(D_BUG, "sql read lock timed out, called from %s:%u", file, line); - sendpdbg_logf("sql read lock timed out, called from %s:%u", file, line); - psql_dump_locks(); - abort(); - } - clock_gettime(CLOCK_REALTIME, &end); - msec = (end.tv_sec - start.tv_sec) * 1000 + end.tv_nsec / 1000000 - - start.tv_nsec / 1000000; - if (msec >= 1000) - pdbg_logf(D_ERROR, "waited %lu milliseconds for database read lock", msec); - else if (msec >= 250) - pdbg_logf(D_WARNING, "waited %lu milliseconds for database read lock", msec); - else if (msec >= 5) - pdbg_logf(D_BUG, "waited %lu milliseconds for database read lock", msec); - rdlockctr++; - memcpy(&rdlockstart, &end, sizeof(struct timespec)); - record_rdlock(file, line, &rdlockstart); - } else if (++rdlockctr == 1) { - clock_gettime(CLOCK_REALTIME, &rdlockstart); - record_rdlock(file, line, &rdlockstart); - } -} - -#else - -int psql_trylock() { return plocks_trywrlock(&dblock); } -void psql_lock() { plocks_wrlock(&dblock); } -void psql_rdlock() { plocks_rdlock(&dblock); } - -#endif - int psql_connect(const char *db) { static int initmutex = 1; pthread_mutexattr_t mattr; @@ -354,7 +226,7 @@ int psql_connect(const char *db) { psync_db_upgrade[i], sqlite3_libversion()); if (IS_DEBUG) { psync_error = PERROR_DATABASE_OPEN; - return -1; + return -1; } } } @@ -429,36 +301,6 @@ void psql_checkpt_unlock() { pthread_mutex_unlock(&cpmutex); } -void psql_unlock() { -#if IS_DEBUG - pdbg_assert(lockctr > 0); - if (--lockctr == 0) { - struct timespec end; - unsigned long msec; - clock_gettime(CLOCK_REALTIME, &end); - msec = (end.tv_sec - lockstart.tv_sec) * 1000 + end.tv_nsec / 1000000 - - lockstart.tv_nsec / 1000000; - if (msec >= 2000) - pdbg_logf(D_ERROR, - "held database write lock for %lu milliseconds taken from %s:%u", - msec, wrlockfile, wrlockline); - else if (msec >= 500) - pdbg_logf(D_WARNING, - "held database write lock for %lu milliseconds taken from %s:%u", - msec, wrlockfile, wrlockline); - else if (msec >= 10) - pdbg_logf(D_BUG, - "held database write lock for %lu milliseconds taken from %s:%u", - msec, wrlockfile, wrlockline); - record_wrunlock(); - plocks_unlock(&dblock); - } else - plocks_unlock(&dblock); -#else - plocks_unlock(&dblock); -#endif -} - void psql_list_add(psync_list_builder_t *builder, psync_sql_res *res, psync_list_builder_sql_callback callback) { psync_variant_row row; while ((row = psql_fetch(res))) { @@ -488,41 +330,6 @@ void psql_list_add(psync_list_builder_t *builder, psync_sql_res *res, psync_list psql_free(res); } -void psql_rdunlock() { -#if IS_DEBUG - if (unlikely(rdlockctr == 0)) { - psql_unlock(); - return; - } - if (--rdlockctr == 0) { - struct timespec end; - unsigned long msec; - rd_lock_data *lock; - plocks_unlock(&dblock); - clock_gettime(CLOCK_REALTIME, &end); - lock = record_rdunlock(); - msec = (end.tv_sec - rdlockstart.tv_sec) * 1000 + end.tv_nsec / 1000000 - - rdlockstart.tv_nsec / 1000000; - if (msec >= 2000) - pdbg_logf(D_ERROR, - "held database read lock for %lu milliseconds taken at %s:%u", msec, - lock->file, lock->line); - else if (msec >= 500) - pdbg_logf(D_WARNING, - "held database read lock for %lu milliseconds taken at %s:%u", msec, - lock->file, lock->line); - else if (msec >= 20) - pdbg_logf(D_BUG, - "held database read lock for %lu milliseconds taken at %s:%u", msec, - lock->file, lock->line); - free(lock); - } else - plocks_unlock(&dblock); -#else - plocks_unlock(&dblock); -#endif -} - int psql_waiting() { return plocks_num_waiters(&dblock) > 0; } @@ -531,30 +338,12 @@ int psql_rdlocked() { return plocks_holding_rdlock(&dblock); } -int psql_locked() { - return plocks_holding_lock(&dblock); +int psql_locked() { + return plocks_holding_lock(&dblock); } -int psql_tryupgradeLock() { -#if IS_DEBUG - if (plocks_holding_wrlock(&dblock)) - return 0; - pdbg_assert(plocks_holding_rdlock(&dblock)); - if (plocks_towrlock(&dblock)) - return -1; - else { - rd_lock_data *lock = record_rdunlock(); - lockctr = rdlockctr; - rdlockctr = 0; - pdbg_assert(lockctr == 1); - lockstart = rdlockstart; - record_wrlock(lock->file, lock->line); - free(lock); - return 0; - } -#else +__attribute__((weak)) int psql_tryupgradeLock() { return plocks_towrlock(&dblock); -#endif } int psql_sync() { @@ -1009,12 +798,12 @@ psync_full_result_int *psql_fetchall_int(psync_sql_res *res) { return ret; } -uint32_t psql_affected() { - return sqlite3_changes(psync_db); +uint32_t psql_affected() { + return sqlite3_changes(psync_db); } -uint64_t psql_insertid() { - return sqlite3_last_insert_rowid(psync_db); +uint64_t psql_insertid() { + return sqlite3_last_insert_rowid(psync_db); } static const char *PSYNC_CONST get_type_name(uint32_t t) { @@ -1072,83 +861,46 @@ void psql_try_free() { pcache_clean(); } - -#if IS_DEBUG -int psql_do_statement(const char *sql, const char *file, unsigned line) { - char *errmsg; - int code; - psql_do_lock(file, line); -#else -int psql_statement(const char *sql) { +__attribute__((weak)) int psql_statement(const char *sql) { char *errmsg; int code; psql_lock(); -#endif code = sqlite3_exec(psync_db, sql, NULL, NULL, &errmsg); psql_unlock(); if (likely(code == SQLITE_OK)) return 0; else { -#if IS_DEBUG - pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", sql, - errmsg, file, line); -#else pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, errmsg); -#endif sqlite3_free(errmsg); return -1; } } -#if IS_DEBUG -int psql_do_start_transaction(const char *file, unsigned line) { - psync_sql_res *res; - psql_do_lock(file, line); - res = psql_do_prepare("BEGIN", file, line); -#else -int psql_start() { +__attribute__((weak)) int psql_start() { psync_sql_res *res; psql_lock(); res = psql_prepare("BEGIN"); -#endif pdbg_assert(!in_transaction); if (unlikely(!res || psql_run_free(res))) return -1; in_transaction = 1; transaction_failed = 0; psync_list_init(&commitcbs); - -return 0; + return 0; } -#if IS_DEBUG -psync_sql_res *psql_do_query_nocache(const char *sql, const char *file, - unsigned line) { -#else -psync_sql_res *psql_query_nocache(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_query_nocache(const char *sql) { sqlite3_stmt *stmt; psync_sql_res *res; int code, cnt; -#if IS_DEBUG - psql_do_lock(file, line); -#else psql_lock(); -#endif code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); if (unlikely(code != SQLITE_OK)) { psql_unlock(); -#if IS_DEBUG - pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", sql, - sqlite3_errmsg(psync_db), file, line); - sendpdbg_logf("error running sql statement: %s: %s called from %s:%u", sql, - sqlite3_errmsg(psync_db), file, line); -#else pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, sqlite3_errmsg(psync_db)); sendpdbg_logf("error running sql statement: %s: %s", sql, sqlite3_errmsg(psync_db)); -#endif return NULL; } cnt = sqlite3_column_count(stmt); @@ -1161,61 +913,30 @@ psync_sql_res *psql_query_nocache(const char *sql) { return res; } -#if IS_DEBUG -psync_sql_res *psql_do_query(const char *sql, const char *file, - unsigned line) { -#else -psync_sql_res *psql_query(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_query(const char *sql) { psync_sql_res *ret; ret = (psync_sql_res *)pcache_get(sql); if (ret) { - // pdbg_logf(D_NOTICE, "got query %s from cache", sql); ret->locked = SQL_WRITE_LOCK; ret->sql = sql; -#if IS_DEBUG - psql_do_lock(file, line); -#else psql_lock(); -#endif return ret; } else -#if IS_DEBUG - return psql_do_query_nocache(sql, file, line); -#else return psql_query_nocache(sql); -#endif } -#if IS_DEBUG -psync_sql_res *psql_do_query_rdlock_nocache(const char *sql, - const char *file, - unsigned line) { -#else -psync_sql_res *psql_rdlock_nocache(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_rdlock_nocache(const char *sql) { sqlite3_stmt *stmt; psync_sql_res *res; int code, cnt; -#if IS_DEBUG - psql_do_rdlock(file, line); -#else psql_rdlock(); -#endif code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); if (unlikely(code != SQLITE_OK)) { psql_rdunlock(); -#if IS_DEBUG - pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", sql, - sqlite3_errmsg(psync_db), file, line); - sendpdbg_logf("error running sql statement: %s: %s called from %s:%u", sql, - sqlite3_errmsg(psync_db), file, line); -#else pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, sqlite3_errmsg(psync_db)); sendpdbg_logf("error running sql statement: %s: %s", sql, sqlite3_errmsg(psync_db)); -#endif return NULL; } cnt = sqlite3_column_count(stmt); @@ -1228,52 +949,22 @@ psync_sql_res *psql_rdlock_nocache(const char *sql) { return res; } -#if IS_DEBUG -psync_sql_res *psql_do_query_rdlock(const char *sql, const char *file, - unsigned line) { -#else -psync_sql_res *psql_query_rdlock(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_query_rdlock(const char *sql) { psync_sql_res *ret; ret = (psync_sql_res *)pcache_get(sql); if (ret) { - // pdbg_logf(D_NOTICE, "got query %s from cache", sql); ret->locked = SQL_READ_LOCK; ret->sql = sql; -#if IS_DEBUG - psql_do_rdlock(file, line); -#else psql_rdlock(); -#endif return ret; } else -#if IS_DEBUG - return psql_do_query_rdlock_nocache(sql, file, line); -#else return psql_rdlock_nocache(sql); -#endif } -#if IS_DEBUG -psync_sql_res *psql_do_query_nolock_nocache(const char *sql, const char *file, unsigned line) { -#else -psync_sql_res *psql_query_nolock_nocache(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_query_nolock_nocache(const char *sql) { sqlite3_stmt *stmt; psync_sql_res *res; int code, cnt; -#if IS_DEBUG - if (!psql_locked()) { - pdbg_logf(D_BUG, - "illegal use of psync_sql_query_nolock, can only be used while " - "holding lock, invoked from %s:%u, sql: %s", - file, line, sql); - sendpdbg_logf("illegal use of psync_sql_query_nolock, can only be used while " - "holding lock, invoked from %s:%u, sql: %s", - file, line, sql); - abort(); - } -#endif code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); if (unlikely(code != SQLITE_OK)) { pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, @@ -1292,44 +983,22 @@ psync_sql_res *psql_query_nolock_nocache(const char *sql) { return res; } -#if IS_DEBUG -psync_sql_res *psql_do_query_nolock(const char *sql, const char *file, unsigned line) { -#else -psync_sql_res *psql_query_nolock(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_query_nolock(const char *sql) { psync_sql_res *ret; -#if IS_DEBUG - if (!psql_locked()) { - pdbg_logf(D_BUG, - "illegal use of psync_sql_query_nolock, can only be used while " - "holding lock, invoked from %s:%u, sql: %s", - file, line, sql); - sendpdbg_logf("illegal use of psync_sql_query_nolock, can only be used while " - "holding lock, invoked from %s:%u, sql: %s", - file, line, sql); - abort(); - } -#endif ret = (psync_sql_res *)pcache_get(sql); if (ret) { - // pdbg_logf(D_NOTICE, "got query %s from cache", sql); ret->locked = SQL_NO_LOCK; ret->sql = sql; return ret; } else -#if IS_DEBUG - return psql_do_query_nolock_nocache(sql, file, line); -#else return psql_query_nolock_nocache(sql); -#endif } void psql_free(psync_sql_res *res) { int code = sqlite3_reset(res->stmt); psync_sql_res_unlock(res); -#if IS_DEBUG - memset(res->row, 0xff, res->column_count * sizeof(psync_variant)); -#endif + if (IS_DEBUG) + memset(res->row, 0xff, res->column_count * sizeof(psync_variant)); if (code == SQLITE_OK) pcache_add(res->sql, res, PSYNC_QUERY_CACHE_SEC, psync_sql_free_cache, PSYNC_QUERY_MAX_CNT); @@ -1340,71 +1009,90 @@ void psql_free(psync_sql_res *res) { void psql_free_nocache(psync_sql_res *res) { sqlite3_finalize(res->stmt); psync_sql_res_unlock(res); -#if IS_DEBUG - memset(res, 0xff, sizeof(psync_sql_res)); -#endif + if (IS_DEBUG) + memset(res, 0xff, sizeof(psync_sql_res)); free(res); } -#if IS_DEBUG -psync_sql_res *psql_do_prepare_nocache(const char *sql, const char *file, unsigned line) { -#else -psync_sql_res *psql_prepare_nocache(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_prepare_nocache(const char *sql) { sqlite3_stmt *stmt; psync_sql_res *res; int code; -#if IS_DEBUG - psql_do_lock(file, line); -#else psql_lock(); -#endif code = sqlite3_prepare_v2(psync_db, sql, -1, &stmt, NULL); if (unlikely(code != SQLITE_OK)) { psql_unlock(); -#if IS_DEBUG - pdbg_logf(D_ERROR, "error running sql statement: %s: %s called from %s:%u", sql, - sqlite3_errmsg(psync_db), file, line); - sendpdbg_logf("error running sql statement: %s: %s called from %s:%u", sql, - sqlite3_errmsg(psync_db), file, line); -#else pdbg_logf(D_ERROR, "error running sql statement: %s: %s", sql, sqlite3_errmsg(psync_db)); sendpdbg_logf("error running sql statement: %s: %s", sql, sqlite3_errmsg(psync_db)); -#endif return NULL; } res = malloc(sizeof(psync_sql_res)); res->stmt = stmt; res->sql = sql; -#if IS_DEBUG res->column_count = 0; -#endif res->locked = SQL_WRITE_LOCK; return res; } -#if IS_DEBUG -psync_sql_res *psql_do_prepare(const char *sql, const char *file, unsigned line) { -#else -psync_sql_res *psql_prepare(const char *sql) { -#endif +__attribute__((weak)) psync_sql_res *psql_prepare(const char *sql) { psync_sql_res *ret; ret = pcache_get(sql); if (ret) { - // pdbg_logf(D_NOTICE, "got statement %s from cache", sql); ret->locked = SQL_WRITE_LOCK; -#if IS_DEBUG - psql_do_lock(file, line); -#else psql_lock(); -#endif return ret; } else -#if IS_DEBUG - return psql_do_prepare_nocache(sql, file, line); -#else return psql_prepare_nocache(sql); -#endif +} + +// psql_do_* weak stubs for query/statement/prepare variants. +// In release builds these forward directly to the non-do implementations. +// debug/psql_debug.c provides strong overrides with SQL tracing. +__attribute__((weak)) int psql_do_statement(const char *sql, const char *file, + unsigned line) { + return psql_statement(sql); +} +__attribute__((weak)) int psql_do_start_transaction(const char *file, + unsigned line) { + return psql_start(); +} +__attribute__((weak)) psync_sql_res *psql_do_query_nocache(const char *sql, + const char *file, + unsigned line) { + return psql_query_nocache(sql); +} +__attribute__((weak)) psync_sql_res *psql_do_query(const char *sql, + const char *file, + unsigned line) { + return psql_query(sql); +} +__attribute__((weak)) psync_sql_res * +psql_do_query_rdlock_nocache(const char *sql, const char *file, unsigned line) { + return psql_rdlock_nocache(sql); +} +__attribute__((weak)) psync_sql_res *psql_do_query_rdlock(const char *sql, + const char *file, + unsigned line) { + return psql_query_rdlock(sql); +} +__attribute__((weak)) psync_sql_res * +psql_do_query_nolock_nocache(const char *sql, const char *file, unsigned line) { + return psql_query_nolock_nocache(sql); +} +__attribute__((weak)) psync_sql_res *psql_do_query_nolock(const char *sql, + const char *file, + unsigned line) { + return psql_query_nolock(sql); +} +__attribute__((weak)) psync_sql_res *psql_do_prepare_nocache(const char *sql, + const char *file, + unsigned line) { + return psql_prepare_nocache(sql); +} +__attribute__((weak)) psync_sql_res *psql_do_prepare(const char *sql, + const char *file, + unsigned line) { + return psql_prepare(sql); } diff --git a/pclsync/psql_internal.h b/pclsync/psql_internal.h new file mode 100644 index 0000000..bee849d --- /dev/null +++ b/pclsync/psql_internal.h @@ -0,0 +1,19 @@ +// psql_internal.h - internal state shared between psql.c and debug/psql_debug.c +// Do NOT include this header from any file other than psql.c and debug/psql_debug.c. + +#ifndef PSQL_INTERNAL_H +#define PSQL_INTERNAL_H + +#include +#include + +#include "plocks.h" +#include "plist.h" + +extern sqlite3 *psync_db; +extern psync_rwlock_t dblock; +extern int in_transaction; +extern int transaction_failed; +extern psync_list commitcbs; + +#endif diff --git a/pclsync/psys.c b/pclsync/psys.c index 75128a0..7319c15 100644 --- a/pclsync/psys.c +++ b/pclsync/psys.c @@ -13,14 +13,11 @@ static gid_t psync_gid; static gid_t *psync_gids; static int psync_gids_cnt; +__attribute__((weak)) void psys_debug_abort_on_sqllock(uint64_t millisec) {} +__attribute__((weak)) void psys_debug_configure_core_dump() {} + static void abort_on_sqllock(uint64_t millisec) { -#if IS_DEBUG - if (psql_locked()) { - pdbg_logf(D_CRITICAL, "trying to sleep while holding sql lock, aborting"); - psql_dump_locks(); - abort(); - } -#endif + psys_debug_abort_on_sqllock(millisec); } uid_t psys_get_uid() { return psync_uid; } @@ -36,15 +33,7 @@ void psys_init() { limit.rlim_cur = limit.rlim_max = 2048; if (setrlimit(RLIMIT_NOFILE, &limit)) pdbg_logf(D_ERROR, "setrlimit failed errno=%d", errno); -#if IS_DEBUG - if (getrlimit(RLIMIT_CORE, &limit)) - pdbg_logf(D_ERROR, "getrlimit failed errno=%d", errno); - else { - limit.rlim_cur = limit.rlim_max; - if (setrlimit(RLIMIT_CORE, &limit)) - pdbg_logf(D_ERROR, "setrlimit failed errno=%d", errno); - } -#endif + psys_debug_configure_core_dump(); signal(SIGPIPE, SIG_IGN); psync_uid = getuid(); psync_gid = getgid(); diff --git a/pclsync/psys.h b/pclsync/psys.h index 217d3aa..b1b36c3 100644 --- a/pclsync/psys.h +++ b/pclsync/psys.h @@ -13,6 +13,8 @@ gid_t *psys_get_gids(); int psys_get_gids_cnt(); void psys_init(); +void psys_debug_abort_on_sqllock(uint64_t millisec); +void psys_debug_configure_core_dump(); time_t psys_time_seconds(); uint64_t psys_time_milliseconds(); void psys_sleep_milliseconds(uint64_t millisec);