From d4d2298a6f2cf564bda8ba33b279175035dd13fb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Mon, 13 Mar 2023 07:11:43 +0000 Subject: [PATCH] Debug logging to disk Introduced new schema debugdb_disk (on disk) and table debug_log . Debug entries will now go to this new table based on the value of variable admin-debug_output . If: 1) default behavior: write to stderr 2) write only to debugdb_disk.debug_log 3) 3 = 1+2 = write to stderr and to debugdb_disk.debug_log All these functionalities exist only on debug build. Table debugdb_disk.debug_log has also a column named "note" that can be used to write user notes during debugging. --- include/proxysql_admin.h | 4 ++ include/proxysql_debug.h | 6 ++ include/sqlite3db.h | 10 +++ lib/ClickHouse_Server.cpp | 9 --- lib/MySQL_HostGroups_Manager.cpp | 9 --- lib/MySQL_Monitor.cpp | 9 --- lib/ProxySQL_Admin.cpp | 47 +++++++++++--- lib/ProxySQL_Cluster.cpp | 9 --- lib/ProxySQL_Statistics.cpp | 10 --- lib/debug.cpp | 101 +++++++++++++++++++++++++++---- 10 files changed, 146 insertions(+), 68 deletions(-) diff --git a/include/proxysql_admin.h b/include/proxysql_admin.h index ce15efa67..53004f20f 100644 --- a/include/proxysql_admin.h +++ b/include/proxysql_admin.h @@ -332,6 +332,10 @@ class ProxySQL_Admin { SQLite3DB *configdb; // on disk SQLite3DB *monitordb; // in memory SQLite3DB *statsdb_disk; // on disk +#ifdef DEBUG + SQLite3DB *debugdb_disk; // on disk for debug + int debug_output; +#endif int pipefd[2]; void print_version(); bool init(); diff --git a/include/proxysql_debug.h b/include/proxysql_debug.h index c34d1897b..a95c0c562 100644 --- a/include/proxysql_debug.h +++ b/include/proxysql_debug.h @@ -211,4 +211,10 @@ SQLite3_result* proxysql_get_message_stats(bool reset=false); */ void proxysql_init_debug_prometheus_metrics(); + +/** + * @brief Set or unset if Admin has debugdb_disk fully initialized + */ +void proxysql_set_status_admin_debugdb_disk(bool status); + #endif diff --git a/include/sqlite3db.h b/include/sqlite3db.h index 36e22149f..b4d3c52f3 100644 --- a/include/sqlite3db.h +++ b/include/sqlite3db.h @@ -7,6 +7,16 @@ #include #define PROXYSQL_SQLITE3DB_PTHREAD_MUTEX +#ifndef SAFE_SQLITE3_STEP2 +#define SAFE_SQLITE3_STEP2(_stmt) do {\ + do {\ + rc=(*proxy_sqlite3_step)(_stmt);\ + if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ + usleep(100);\ + }\ + } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ +} while (0) +#endif // SAFE_SQLITE3_STEP2 #ifndef MAIN_PROXY_SQLITE3 extern int (*proxy_sqlite3_bind_double)(sqlite3_stmt*, int, double); diff --git a/lib/ClickHouse_Server.cpp b/lib/ClickHouse_Server.cpp index ca71746cf..fecfab268 100644 --- a/lib/ClickHouse_Server.cpp +++ b/lib/ClickHouse_Server.cpp @@ -58,15 +58,6 @@ } while (rc!=SQLITE_DONE);\ } while (0) -#define SAFE_SQLITE3_STEP2(_stmt) do {\ - do {\ - rc=(*proxy_sqlite3_step)(_stmt);\ - if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ - usleep(100);\ - }\ - } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ -} while (0) - #include "clickhouse/client.h" using namespace clickhouse; diff --git a/lib/MySQL_HostGroups_Manager.cpp b/lib/MySQL_HostGroups_Manager.cpp index 2a83f6283..09e86503d 100644 --- a/lib/MySQL_HostGroups_Manager.cpp +++ b/lib/MySQL_HostGroups_Manager.cpp @@ -42,15 +42,6 @@ static unsigned long long array_mysrvc_cands = 0; } while (rc!=SQLITE_DONE);\ } while (0) -#define SAFE_SQLITE3_STEP2(_stmt) do {\ - do {\ - rc=(*proxy_sqlite3_step)(_stmt);\ - if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ - usleep(100);\ - }\ - } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ -} while (0) - extern ProxySQL_Admin *GloAdmin; extern MySQL_Threads_Handler *GloMTH; diff --git a/lib/MySQL_Monitor.cpp b/lib/MySQL_Monitor.cpp index f258a6fe7..e5e1356e1 100644 --- a/lib/MySQL_Monitor.cpp +++ b/lib/MySQL_Monitor.cpp @@ -50,15 +50,6 @@ static MySQL_Monitor *GloMyMon; } while (rc!=SQLITE_DONE);\ } while (0) -#define SAFE_SQLITE3_STEP2(_stmt) do {\ - do {\ - rc=(*proxy_sqlite3_step)(_stmt);\ - if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ - usleep(100);\ - }\ - } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ -} while (0) - using std::string; using std::set; using std::vector; diff --git a/lib/ProxySQL_Admin.cpp b/lib/ProxySQL_Admin.cpp index feafdcefd..95435b1b8 100644 --- a/lib/ProxySQL_Admin.cpp +++ b/lib/ProxySQL_Admin.cpp @@ -235,14 +235,6 @@ int sqlite3_json_init( } while (rc!=SQLITE_DONE);\ } while (0) -#define SAFE_SQLITE3_STEP2(_stmt) do {\ - do {\ - rc=(*proxy_sqlite3_step)(_stmt);\ - if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ - usleep(100);\ - }\ - } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ -} while (0) typedef struct _arg_mysql_adm_t { struct sockaddr * addr; @@ -671,7 +663,8 @@ static char * admin_variables_names[]= { (char *)"web_verbosity", (char *)"prometheus_memory_metrics_interval", #ifdef DEBUG - (char *)"debug", + (char *)"debug", + (char *)"debug_output", #endif /* DEBUG */ NULL }; @@ -5689,6 +5682,7 @@ ProxySQL_Admin::ProxySQL_Admin() : serial_exposer(std::function { update_modules_metrics }) { #ifdef DEBUG + debugdb_disk = NULL; if (glovars.has_debug==false) { #else if (glovars.has_debug==true) { @@ -5803,6 +5797,7 @@ ProxySQL_Admin::ProxySQL_Admin() : variables.p_memory_metrics_interval = 61; #ifdef DEBUG variables.debug=GloVars.global.gdbg; + debug_output = 1; #endif /* DEBUG */ last_p_memory_metrics_ts = 0; @@ -6091,6 +6086,22 @@ bool ProxySQL_Admin::init() { #ifdef DEBUG admindb->execute("ATTACH DATABASE 'file:mem_mydb?mode=memory&cache=shared' AS myhgm"); admindb->execute("ATTACH DATABASE 'file:mem_monitor_internal_db?mode=memory&cache=shared' AS 'monitor_internal'"); + { + string debugdb_disk_path = string(GloVars.datadir) + "/" + "proxysql_debug.db"; + debugdb_disk = new SQLite3DB(); + debugdb_disk->open((char *)debugdb_disk_path.c_str(), SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE | SQLITE_OPEN_FULLMUTEX); + debugdb_disk->execute("CREATE TABLE IF NOT EXISTS debug_log (id INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL , time INT NOT NULL , lapse INT NOT NULL , thread INT NOT NULL , file VARCHAR NOT NULL , line INT NOT NULL , funct VARCHAR NOT NULL , modnum INT NOT NULL , modname VARCHAR NOT NULL , verbosity INT NOT NULL , message VARCHAR , note VARCHAR , backtrace VARCHAR)"); + debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_time ON debug_log (time)"); + debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_thread ON debug_log (thread)"); + debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_file ON debug_log (file)"); + debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_file_line ON debug_log (file,line)"); + debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_funct ON debug_log (funct)"); + debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_modnum ON debug_log (modnum)"); + debugdb_disk->execute("PRAGMA synchronous=0"); + string cmd = "ATTACH DATABASE '" + debugdb_disk_path + "' AS debugdb_disk"; + admindb->execute(cmd.c_str()); + proxysql_set_status_admin_debugdb_disk(true); + } #endif /* DEBUG */ #ifdef DEBUG @@ -6230,6 +6241,10 @@ void ProxySQL_Admin::admin_shutdown() { delete configdb; delete monitordb; delete statsdb_disk; +#ifdef DEBUG + proxysql_set_status_admin_debugdb_disk(false); + delete debugdb_disk; +#endif (*proxy_sqlite3_shutdown)(); if (main_poll_fds) { for (i=0;i 0 && fval <= 3) { + debug_output = fval; + return true; + } else { + return false; + } + return false; + } #endif /* DEBUG */ return false; } diff --git a/lib/ProxySQL_Cluster.cpp b/lib/ProxySQL_Cluster.cpp index c70c3b895..fa70fef90 100644 --- a/lib/ProxySQL_Cluster.cpp +++ b/lib/ProxySQL_Cluster.cpp @@ -33,15 +33,6 @@ } while (rc!=SQLITE_DONE);\ } while (0) -#define SAFE_SQLITE3_STEP2(_stmt) do {\ - do {\ - rc=(*proxy_sqlite3_step)(_stmt);\ - if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ - usleep(100);\ - }\ - } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ -} while (0) - using std::vector; using std::pair; using std::string; diff --git a/lib/ProxySQL_Statistics.cpp b/lib/ProxySQL_Statistics.cpp index e0afeaeb8..523623109 100644 --- a/lib/ProxySQL_Statistics.cpp +++ b/lib/ProxySQL_Statistics.cpp @@ -32,16 +32,6 @@ extern MySQL_Threads_Handler *GloMTH; } while (rc!=SQLITE_DONE );\ } while (0) -#define SAFE_SQLITE3_STEP2(_stmt) do {\ - do {\ - rc=(*proxy_sqlite3_step)(_stmt);\ - if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\ - usleep(100);\ - }\ - } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\ -} while (0) - - ProxySQL_Statistics::ProxySQL_Statistics() { statsdb_mem = new SQLite3DB(); statsdb_mem->open((char *)"file:statsdb_mem?mode=memory&cache=shared", SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE | SQLITE_OPEN_FULLMUTEX); diff --git a/lib/debug.cpp b/lib/debug.cpp index 54007fd92..36b3c7609 100644 --- a/lib/debug.cpp +++ b/lib/debug.cpp @@ -1,6 +1,8 @@ #include "proxysql.h" #include "proxysql_atomic.h" +#include "proxysql_admin.h" + #include "sqlite3db.h" #include "prometheus_helpers.h" @@ -24,16 +26,20 @@ using std::unordered_map; #endif // CLOCK_MONOTONIC #ifdef DEBUG -static unsigned long long pretime=0; +__thread unsigned long long pretime=0; static pthread_mutex_t debug_mutex; +static bool debugdb_disk_init = false; +sqlite3_stmt *statement1=NULL; +extern ProxySQL_Admin *GloAdmin; #endif /* DEBUG */ +/* static inline unsigned long long debug_monotonic_time() { struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); return (((unsigned long long) ts.tv_sec) * 1000000) + (ts.tv_nsec / 1000); } - +*/ #define DEBUG_MSG_MAXSIZE 1024 @@ -111,26 +117,43 @@ void proxy_debug_load_filters(std::set& f) { void proxy_debug_func(enum debug_module module, int verbosity, int thr, const char *__file, int __line, const char *__func, const char *fmt, ...) { assert(moduledebug_output == 2 || GloAdmin->debug_output == 3)) { + write_to_disk = true; + } + if ( + GloVars.global.foreground + || + write_to_disk == true + ) { va_list ap; va_start(ap, fmt); - vsnprintf(debugbuff, DEBUG_MSG_MAXSIZE,fmt,ap); + vsnprintf(origdebugbuff, DEBUG_MSG_MAXSIZE,fmt,ap); va_end(ap); - pthread_mutex_lock(&debug_mutex); - unsigned long long curtime=debug_monotonic_time(); //fprintf(stderr, "%d:%s:%d:%s(): MOD#%d LVL#%d : %s" , thr, __file, __line, __func, module, verbosity, debugbuff); - sprintf(longdebugbuff, "%llu(%llu): %d:%s:%d:%s(): MOD#%d#%s LVL#%d : %s" , curtime, curtime-pretime, thr, __file, __line, __func, module, GloVars.global.gdbg_lvl[module].name, verbosity, debugbuff); - pretime=curtime; + sprintf(longdebugbuff, "%llu(%llu): %d:%s:%d:%s(): MOD#%d#%s LVL#%d : %s" , curtime, curtime-pretime, thr, __file, __line, __func, module, GloVars.global.gdbg_lvl[module].name, verbosity, origdebugbuff); } #ifdef __GLIBC__ - if (GloVars.global.gdbg_lvl[module].verbosity>=10) { + if ( + (GloVars.global.gdbg_lvl[module].verbosity>=10) + || + write_to_disk == true + ) { void *arr[20]; char **strings; int s; @@ -150,18 +173,66 @@ void proxy_debug_func(enum debug_module module, int verbosity, int thr, const ch realname=abi::__cxa_demangle(debugbuff, 0, 0, &status); if (realname) { sprintf(debugbuff," ---- %s : %s\n", strings[i], realname); - strcat(longdebugbuff,debugbuff); + strcat(longdebugbuff2,debugbuff); } } //printf("\n"); - strcat(longdebugbuff,"\n"); + //strcat(longdebugbuff2,"\n"); free(strings); // } else { // fprintf(stderr, "%s", longdebugbuff); } #endif - if (strlen(longdebugbuff)) fprintf(stderr, "%s", longdebugbuff); + if (debugdb_disk_init == false) { + // default behavior + if (longdebugbuff[0] != 0) { + fprintf(stderr, "%s", longdebugbuff); + } + if (longdebugbuff2[0] != 0) { + if (GloVars.global.gdbg_lvl[module].verbosity>=10) { + fprintf(stderr, "%s\n", longdebugbuff2); + } + } + } else { + assert (GloAdmin != NULL); + SQLite3DB *db = GloAdmin->debugdb_disk; + assert(db != NULL); + int rc = 0; + if (statement1==NULL) { + const char *a = "INSERT INTO debug_log (id, time, lapse, thread, file, line, funct, modnum, modname, verbosity, message, note, backtrace) VALUES (NULL, ?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, NULL, ?11)"; + rc=db->prepare_v2(a, &statement1); + ASSERT_SQLITE_OK(rc, db); + } + if (GloAdmin->debug_output == 1 || GloAdmin->debug_output == 3) { + // to stderr + if (longdebugbuff[0] != 0) { + fprintf(stderr, "%s", longdebugbuff); + } + if (longdebugbuff2[0] != 0) { + fprintf(stderr, "%s", longdebugbuff2); + } + } + if (write_to_disk == true) { + rc=(*proxy_sqlite3_bind_int64)(statement1, 1, curtime); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_int64)(statement1, 2, curtime-pretime); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_int64)(statement1, 3, thr); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_text)(statement1, 4, __file, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_int64)(statement1, 5, __line); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_text)(statement1, 6, __func, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_int64)(statement1, 7, module); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_text)(statement1, 8, GloVars.global.gdbg_lvl[module].name, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_int64)(statement1, 9, verbosity); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_text)(statement1, 10, origdebugbuff, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_bind_text)(statement1, 11, longdebugbuff2, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); + SAFE_SQLITE3_STEP2(statement1); + rc=(*proxy_sqlite3_clear_bindings)(statement1); ASSERT_SQLITE_OK(rc, db); + rc=(*proxy_sqlite3_reset)(statement1); ASSERT_SQLITE_OK(rc, db); + //(*proxy_sqlite3_finalize)(statement1); + } + } pthread_mutex_unlock(&debug_mutex); + if (curtime != 0) + pretime=curtime; }; #endif @@ -376,7 +447,6 @@ void print_backtrace(void) void init_debug_struct() { int i; pthread_mutex_init(&debug_mutex,NULL); - pretime=debug_monotonic_time(); GloVars.global.gdbg_lvl= (debug_level *) malloc(PROXY_DEBUG_UNKNOWN*sizeof(debug_level)); for (i=0;i