From 449f4eb65917d8939bf2e91cbf11684f475cee23 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Wed, 8 Jul 2020 16:39:33 +0200 Subject: [PATCH] Adding debug_filters --- doc/internal/debug_filters.md | 38 ++++++++++ include/proxysql.h | 3 + include/proxysql_admin.h | 12 ++- lib/ProxySQL_Admin.cpp | 136 +++++++++++++++++++++++++++++++--- lib/debug.cpp | 100 +++++++++++++++++++------ 5 files changed, 250 insertions(+), 39 deletions(-) create mode 100644 doc/internal/debug_filters.md diff --git a/doc/internal/debug_filters.md b/doc/internal/debug_filters.md new file mode 100644 index 000000000..781af204c --- /dev/null +++ b/doc/internal/debug_filters.md @@ -0,0 +1,38 @@ +# Debug Filters + +When ProxySQL is compiled with debug option, debugging information are dumped onto standard error. +Because debugging can be very verbose, in 2.0.13 we introduced debug filters. + +The new table created is `debug_filters` , present both in `main` and `disk`. +There is no equivalent `runtime_debug_filters`. + +The commands responsible for handling with `debug_levels` are also used for `debug_filters`: +* `(LOAD|SAVE) DEBUG (FROM|TO) (RUNTIME|MEMORY|DISK)` + + +Table definition: + +``` +Admin> SHOW CREATE TABLE debug_filters\G +*************************** 1. row *************************** + table: debug_filters +Create Table: CREATE TABLE debug_filters ( + filename VARCHAR NOT NULL, + line INT NOT NULL, + funct VARCHAR NOT NULL, + PRIMARY KEY (filename, line, funct) ) +1 row in set (0.00 sec) +``` + +Columns: +* `filename`: the source code filename, for example `MySQL_Thread.cpp` +* `line` : the line number in the source file, for example `1234` . `0` means any line. +* `funct` : the function name without parenthesis, for example `run` . Empty value is allowed. + +When debug is writing a new debugging entry, if first checks what was loaded at runtime from `debug_filters`. +The debugging information is filtered if: + +* an entry for `filename`+`line`+`funct` exists +* an entry for `filename`+`line` exists (empty `funct`) +* an entry for `filename`+`0`+`funct` exists (line `0` means any line in the given `funct`) +* an entry for `filename`+`0` exists (empty `funct`, any line) diff --git a/include/proxysql.h b/include/proxysql.h index 89645feb7..7950d8953 100644 --- a/include/proxysql.h +++ b/include/proxysql.h @@ -3,6 +3,7 @@ #include #include +#include #ifndef EZOPTION #define EZOPTION @@ -111,6 +112,8 @@ void proxy_info_(const char* msg, ...); void init_debug_struct(); void init_debug_struct_from_cmdline(); void proxy_debug_func(enum debug_module, int, int, const char *, int, const char *, const char *, ...); +void proxy_debug_get_filters(std::set&); +void proxy_debug_load_filters(std::set&); #endif #ifdef __cplusplus diff --git a/include/proxysql_admin.h b/include/proxysql_admin.h index 01b5a6198..a93ae0683 100644 --- a/include/proxysql_admin.h +++ b/include/proxysql_admin.h @@ -192,6 +192,8 @@ class ProxySQL_Admin { #ifdef DEBUG void flush_debug_levels_runtime_to_database(SQLite3DB *db, bool replace); int flush_debug_levels_database_to_runtime(SQLite3DB *db); + void flush_debug_filters_runtime_to_database(SQLite3DB *db); + void flush_debug_filters_database_to_runtime(SQLite3DB *db); #endif /* DEBUG */ void __insert_or_ignore_maintable_select_disktable(); @@ -284,9 +286,13 @@ class ProxySQL_Admin { void send_MySQL_OK(MySQL_Protocol *myprot, char *msg, int rows=0); void send_MySQL_ERR(MySQL_Protocol *myprot, char *msg); #ifdef DEBUG - int load_debug_to_runtime() { return flush_debug_levels_database_to_runtime(admindb); } - void save_debug_from_runtime() { return flush_debug_levels_runtime_to_database(admindb, true); } -#endif /* DEBUG */ + // these two following functions used to just call and return one function each + // this approach was replaced when we introduced debug filters + //int load_debug_to_runtime() { return flush_debug_levels_database_to_runtime(admindb); } + //void save_debug_from_runtime() { return flush_debug_levels_runtime_to_database(admindb, true); } + int load_debug_to_runtime(); + void save_debug_from_runtime(); +#endif // DEBUG void flush_mysql_users__from_memory_to_disk(); void flush_mysql_users__from_disk_to_memory(); void flush_mysql_servers__from_memory_to_disk(); diff --git a/lib/ProxySQL_Admin.cpp b/lib/ProxySQL_Admin.cpp index 84c2e86e4..975524370 100644 --- a/lib/ProxySQL_Admin.cpp +++ b/lib/ProxySQL_Admin.cpp @@ -444,6 +444,7 @@ static int http_handler(void *cls, struct MHD_Connection *connection, const char #ifdef DEBUG #define ADMIN_SQLITE_TABLE_DEBUG_LEVELS "CREATE TABLE debug_levels (module VARCHAR NOT NULL PRIMARY KEY , verbosity INT NOT NULL DEFAULT 0)" +#define ADMIN_SQLITE_TABLE_DEBUG_FILTERS "CREATE TABLE debug_filters (filename VARCHAR NOT NULL , line INT NOT NULL , funct VARCHAR NOT NULL , PRIMARY KEY (filename, line, funct) )" #endif /* DEBUG */ #define ADMIN_SQLITE_TABLE_MYSQL_GROUP_REPLICATION_HOSTGROUPS_V1_4 "CREATE TABLE mysql_group_replication_hostgroups (writer_hostgroup INT CHECK (writer_hostgroup>=0) NOT NULL PRIMARY KEY , backup_writer_hostgroup INT CHECK (backup_writer_hostgroup>=0 AND backup_writer_hostgroup<>writer_hostgroup) NOT NULL , reader_hostgroup INT NOT NULL CHECK (reader_hostgroup<>writer_hostgroup AND backup_writer_hostgroup<>reader_hostgroup AND reader_hostgroup>0) , offline_hostgroup INT NOT NULL CHECK (offline_hostgroup<>writer_hostgroup AND offline_hostgroup<>reader_hostgroup AND backup_writer_hostgroup<>offline_hostgroup AND offline_hostgroup>=0) , active INT CHECK (active IN (0,1)) NOT NULL DEFAULT 1 , max_writers INT NOT NULL CHECK (max_writers >= 0) DEFAULT 1 , writer_is_also_reader INT CHECK (writer_is_also_reader IN (0,1)) NOT NULL DEFAULT 0 , max_transactions_behind INT CHECK (max_transactions_behind>=0) NOT NULL DEFAULT 0 , comment VARCHAR , UNIQUE (reader_hostgroup) , UNIQUE (offline_hostgroup) , UNIQUE (backup_writer_hostgroup))" @@ -1456,10 +1457,20 @@ bool admin_handler_command_load_or_save(char *query_no_space, unsigned int query (query_no_space_length==strlen("LOAD DEBUG FROM DISK") && !strncasecmp("LOAD DEBUG FROM DISK",query_no_space, query_no_space_length)) ) { proxy_info("Received %s command\n", query_no_space); - l_free(*ql,*q); - *q=l_strdup("INSERT OR REPLACE INTO main.debug_levels SELECT * FROM disk.debug_levels"); - *ql=strlen(*q)+1; - return true; + // we are now copying the data from memory to disk + // tables involved are: + // * debug_levels + // * debug_filters + // We only delete from filters and not from levels because the + // levels are hardcoded and fixed in number, while filters can + // be arbitrary + ProxySQL_Admin *SPA=(ProxySQL_Admin *)pa; + SPA->admindb->execute("DELETE FROM main.debug_filters"); + SPA->admindb->execute("INSERT OR REPLACE INTO main.debug_levels SELECT * FROM disk.debug_levels"); + SPA->admindb->execute("INSERT INTO main.debug_filters SELECT * FROM disk.debug_filters"); + proxy_debug(PROXY_DEBUG_ADMIN, 4, "Loaded debug levels/filters to MEMORY\n"); + SPA->send_MySQL_OK(&sess->client_myds->myprot, NULL); + return false; } if ( @@ -1470,10 +1481,20 @@ bool admin_handler_command_load_or_save(char *query_no_space, unsigned int query (query_no_space_length==strlen("SAVE DEBUG TO DISK") && !strncasecmp("SAVE DEBUG TO DISK",query_no_space, query_no_space_length)) ) { proxy_info("Received %s command\n", query_no_space); - l_free(*ql,*q); - *q=l_strdup("INSERT OR REPLACE INTO disk.debug_levels SELECT * FROM main.debug_levels"); - *ql=strlen(*q)+1; - return true; + // we are now copying the data from disk to memory + // tables involved are: + // * debug_levels + // * debug_filters + // We only delete from filters and not from levels because the + // levels are hardcoded and fixed in number, while filters can + // be arbitrary + ProxySQL_Admin *SPA=(ProxySQL_Admin *)pa; + SPA->admindb->execute("DELETE FROM disk.debug_filters"); + SPA->admindb->execute("INSERT OR REPLACE INTO disk.debug_levels SELECT * FROM main.debug_levels"); + SPA->admindb->execute("INSERT INTO disk.debug_filters SELECT * FROM main.debug_filters"); + proxy_debug(PROXY_DEBUG_ADMIN, 4, "Saved debug levels/filters to DISK\n"); + SPA->send_MySQL_OK(&sess->client_myds->myprot, NULL); + return false; } if ( @@ -1489,11 +1510,11 @@ bool admin_handler_command_load_or_save(char *query_no_space, unsigned int query ProxySQL_Admin *SPA=(ProxySQL_Admin *)pa; int rc=SPA->load_debug_to_runtime(); if (rc) { - proxy_debug(PROXY_DEBUG_ADMIN, 4, "Loaded debug levels to RUNTIME\n"); + proxy_debug(PROXY_DEBUG_ADMIN, 4, "Loaded debug levels/filters to RUNTIME\n"); SPA->send_MySQL_OK(&sess->client_myds->myprot, NULL); } else { - proxy_debug(PROXY_DEBUG_ADMIN, 1, "Error while loading debug levels to RUNTIME\n"); - SPA->send_MySQL_ERR(&sess->client_myds->myprot, (char *)"Error while loading debug levels to RUNTIME"); + proxy_debug(PROXY_DEBUG_ADMIN, 1, "Error while loading debug levels/filters to RUNTIME\n"); + SPA->send_MySQL_ERR(&sess->client_myds->myprot, (char *)"Error while loading debug levels/filters to RUNTIME"); } return false; } @@ -1510,7 +1531,7 @@ bool admin_handler_command_load_or_save(char *query_no_space, unsigned int query proxy_info("Received %s command\n", query_no_space); ProxySQL_Admin *SPA=(ProxySQL_Admin *)pa; SPA->save_debug_from_runtime(); - proxy_debug(PROXY_DEBUG_ADMIN, 4, "Saved debug levels from RUNTIME\n"); + proxy_debug(PROXY_DEBUG_ADMIN, 4, "Saved debug levels/filters from RUNTIME\n"); SPA->send_MySQL_OK(&sess->client_myds->myprot, NULL); return false; } @@ -5241,6 +5262,7 @@ bool ProxySQL_Admin::init() { insert_into_tables_defs(tables_defs_admin, "runtime_restapi_routes", ADMIN_SQLITE_TABLE_RUNTIME_RESTAPI_ROUTES); #ifdef DEBUG insert_into_tables_defs(tables_defs_admin,"debug_levels", ADMIN_SQLITE_TABLE_DEBUG_LEVELS); + insert_into_tables_defs(tables_defs_admin,"debug_filters", ADMIN_SQLITE_TABLE_DEBUG_FILTERS); #endif /* DEBUG */ #ifdef PROXYSQLCLICKHOUSE // ClickHouse @@ -5268,6 +5290,7 @@ bool ProxySQL_Admin::init() { insert_into_tables_defs(tables_defs_config, "restapi_routes", ADMIN_SQLITE_TABLE_RESTAPI_ROUTES); #ifdef DEBUG insert_into_tables_defs(tables_defs_config,"debug_levels", ADMIN_SQLITE_TABLE_DEBUG_LEVELS); + insert_into_tables_defs(tables_defs_config,"debug_filters", ADMIN_SQLITE_TABLE_DEBUG_FILTERS); #endif /* DEBUG */ #ifdef PROXYSQLCLICKHOUSE // ClickHouse @@ -8959,6 +8982,91 @@ void ProxySQL_Admin::flush_debug_levels_runtime_to_database(SQLite3DB *db, bool #endif /* DEBUG */ #ifdef DEBUG + +int ProxySQL_Admin::load_debug_to_runtime() { + int numrows = flush_debug_levels_database_to_runtime(admindb); + if (numrows) { // so far so good + // we now load filters + flush_debug_filters_database_to_runtime(admindb); + } + return numrows; +} + +// because debug_mutex is static in debug.cpp +// we get a list of filters debug, where a copy constructor is called +// it is not optimal in term of performance, but this is not critical +void ProxySQL_Admin::flush_debug_filters_runtime_to_database(SQLite3DB *db) { + std::set filters; + proxy_debug_get_filters(filters); + admindb->execute((char *)"DELETE FROM debug_filters"); + for (std::set::iterator it = filters.begin(); it != filters.end(); ++it) { + // we are splitting each key in 3 parts, separated by : + // we call c_split_2 twice + char *a = NULL; + char *b = NULL; + char *c = NULL; + std::string s = *it; + char *key = strdup(s.c_str()); + c_split_2(key, (const char *)":", &a, &b); + assert(a); + assert(b); + free(b); + b = NULL; + c_split_2(index(key,':')+1, (const char *)":", &b, &c); + assert(b); + assert(c); + std::string query = "INSERT INTO debug_filters VALUES ('"; + query += a; + query += "',"; + query += b; // line + query += ",'"; + query += c; // funct + query += "')"; + admindb->execute(query.c_str()); + free(a); + free(b); + free(c); + free(key); + } +} + +void ProxySQL_Admin::save_debug_from_runtime() { + flush_debug_levels_runtime_to_database(admindb, true); + flush_debug_filters_runtime_to_database(admindb); +} + +// because debug_mutex is static in debug.cpp +// we generate a set and sent it to debug, where a copy constructor is called +// it is not optimal in term of performance, but this is not critical +void ProxySQL_Admin::flush_debug_filters_database_to_runtime(SQLite3DB *db) { + char *error=NULL; + int cols=0; + int affected_rows=0; + SQLite3_result *resultset=NULL; + std::string query = "SELECT filename, line, funct FROM debug_filters"; + admindb->execute_statement(query.c_str(), &error , &cols , &affected_rows , &resultset); + if (error) { + proxy_error("Error on %s : %s\n", query, error); + assert(0); + } else { + std::set filters; + for (std::vector::iterator it = resultset->rows.begin() ; it != resultset->rows.end(); ++it) { + SQLite3_row *r=*it; + std::string key; // we create a string with the row + // remember the format is filename:line:funct + // no column can be null + key = r->fields[0]; + key += ":"; + key += r->fields[1]; + key += ":"; + key += r->fields[2]; + filters.emplace(key); + } + proxy_debug_load_filters(filters); + } + if (resultset) delete resultset; +} + int ProxySQL_Admin::flush_debug_levels_database_to_runtime(SQLite3DB *db) { int i; char *query=(char *)"SELECT verbosity FROM debug_levels WHERE module=\"%s\""; @@ -9006,6 +9114,7 @@ void ProxySQL_Admin::__insert_or_ignore_maintable_select_disktable() { admindb->execute("INSERT OR IGNORE INTO main.proxysql_servers SELECT * FROM disk.proxysql_servers"); #ifdef DEBUG admindb->execute("INSERT OR IGNORE INTO main.debug_levels SELECT * FROM disk.debug_levels"); + admindb->execute("INSERT OR IGNORE INTO main.debug_filters SELECT * FROM disk.debug_filters"); #endif /* DEBUG */ #ifdef PROXYSQLCLICKHOUSE if ( GloVars.global.clickhouse_server == true ) { @@ -9037,6 +9146,7 @@ void ProxySQL_Admin::__insert_or_replace_maintable_select_disktable() { admindb->execute("INSERT OR REPLACE INTO main.proxysql_servers SELECT * FROM disk.proxysql_servers"); #ifdef DEBUG admindb->execute("INSERT OR REPLACE INTO main.debug_levels SELECT * FROM disk.debug_levels"); + admindb->execute("INSERT OR REPLACE INTO main.debug_filters SELECT * FROM disk.debug_filters"); #endif /* DEBUG */ #ifdef PROXYSQLCLICKHOUSE if ( GloVars.global.clickhouse_server == true ) { @@ -9066,6 +9176,7 @@ void ProxySQL_Admin::__delete_disktable() { admindb->execute("DELETE FROM disk.proxysql_servers"); #ifdef DEBUG admindb->execute("DELETE FROM disk.debug_levels"); + admindb->execute("DELETE FROM disk.debug_filters"); #endif /* DEBUG */ #ifdef PROXYSQLCLICKHOUSE if ( GloVars.global.clickhouse_server == true ) { @@ -9094,6 +9205,7 @@ void ProxySQL_Admin::__insert_or_replace_disktable_select_maintable() { admindb->execute("INSERT OR REPLACE INTO disk.proxysql_servers SELECT * FROM main.proxysql_servers"); #ifdef DEBUG admindb->execute("INSERT OR REPLACE INTO disk.debug_levels SELECT * FROM main.debug_levels"); + admindb->execute("INSERT OR REPLACE INTO disk.debug_filters SELECT * FROM main.debug_filters"); #endif /* DEBUG */ #ifdef PROXYSQLCLICKHOUSE if ( GloVars.global.clickhouse_server == true ) { diff --git a/lib/debug.cpp b/lib/debug.cpp index dd896aea4..f93d5e5ba 100644 --- a/lib/debug.cpp +++ b/lib/debug.cpp @@ -1,27 +1,21 @@ +#include #include "proxysql.h" #include "proxysql_atomic.h" #include - #ifdef DEBUG #ifdef DEBUG_EXTERN #undef DEBUG_EXTERN #endif /* DEBUG_EXTERN */ #endif /* DEBUG */ -#define PROXYSQL_DEBUG_PTHREAD_MUTEX - #ifndef CLOCK_MONOTONIC #define CLOCK_MONOTONIC SYSTEM_CLOCK #endif // CLOCK_MONOTONIC #ifdef DEBUG static unsigned long long pretime=0; -#ifdef PROXYSQL_DEBUG_PTHREAD_MUTEX static pthread_mutex_t debug_mutex; -#else -static spinlock debug_spinlock; -#endif #endif /* DEBUG */ static inline unsigned long long debug_monotonic_time() { @@ -35,9 +29,82 @@ static inline unsigned long long debug_monotonic_time() { #ifdef DEBUG + +// this set will have all the filters related to debug +// for convention, the key is: +// filename:line:function +// this key structure applies also if line is 0 or function is empty +// filename is mandatory +std::set debug_filters; + +static bool filter_debug_entry(const char *__file, int __line, const char *__func) { + pthread_mutex_lock(&debug_mutex); + bool to_filter = false; + if (debug_filters.size()) { // if the set is empty we aren't performing any filter, so we won't search + std::string key(__file); + key += ":" + std::to_string(__line); + key += ":"; + key += __func; + // we start with a full search + if (debug_filters.find(key) != debug_filters.end()) { + to_filter = true; + } else { + // we now search filename + line + key = __file; + key += ":" + std::to_string(__line); + // remember to add the final ":" + key += ":"; + if (debug_filters.find(key) != debug_filters.end()) { + to_filter = true; + } else { + // we now search filename + function + key = __file; + // no line = 0 + key += ":0:"; + key += __func; + if (debug_filters.find(key) != debug_filters.end()) { + to_filter = true; + } else { + // we now search filename only + key = __file; + // remember to add ":" even if no line + key += ":0:"; + if (debug_filters.find(key) != debug_filters.end()) { + to_filter = true; + } else { + // if we reached here, we couldn't find any filter + } + } + } + } + } + pthread_mutex_unlock(&debug_mutex); + return to_filter; +} + +// we use this function to sent the filters to Admin +// we hold here the mutex on debug_mutex +void proxy_debug_get_filters(std::set& f) { + pthread_mutex_lock(&debug_mutex); + f = debug_filters; + pthread_mutex_unlock(&debug_mutex); +} + +// we use this function to get the filters from Admin +// we hold here the mutex on debug_mutex +void proxy_debug_load_filters(std::set& f) { + pthread_mutex_lock(&debug_mutex); + debug_filters.erase(debug_filters.begin(), debug_filters.end()); + debug_filters = f; + pthread_mutex_unlock(&debug_mutex); +} + void proxy_debug_func(enum debug_module module, int verbosity, int thr, const char *__file, int __line, const char *__func, const char *fmt, ...) { assert(module