From cb53db81caaced25c85a384c2d05a05dc44eae7d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Fri, 14 Mar 2025 01:10:57 +0000 Subject: [PATCH] Export MySQL_Logger metrics for v3.0 Port of #4802 --- include/MySQL_Logger.hpp | 48 +++++- lib/MySQL_Logger.cpp | 143 +++++++++++++++++- lib/ProxySQL_Admin.cpp | 4 + lib/ProxySQL_Admin_Stats.cpp | 13 ++ .../tests/mysql_query_logging_memory-t.cpp | 17 ++- test/tap/tests/set_character_set-t.cpp | 2 +- 6 files changed, 218 insertions(+), 9 deletions(-) diff --git a/include/MySQL_Logger.hpp b/include/MySQL_Logger.hpp index 3e3c7cc9c..29b1e607b 100644 --- a/include/MySQL_Logger.hpp +++ b/include/MySQL_Logger.hpp @@ -8,6 +8,36 @@ class MySQL_Logger; +struct p_ml_counter { + enum metric { + memory_copy_count = 0, + disk_copy_count, + get_all_events_calls_count, + get_all_events_events_count, + total_memory_copy_time_us, + total_disk_copy_time_us, + total_get_all_events_time_us, + total_events_copied_to_memory, + total_events_copied_to_disk, + circular_buffer_events_added_count, + circular_buffer_events_dropped_count, + __size + }; +}; + +struct p_ml_gauge { + enum metric { + circular_buffer_events_size, + __size + }; +}; + +struct ml_metrics_map_idx { + enum index { + counters = 0, + gauges + }; +}; /** * @class MySQL_Event @@ -327,7 +357,7 @@ private: /** @brief Total time spent copying events to the on-disk database (microseconds). */ std::atomic totalDiskCopyTimeMicros; /** @brief Total time spent in `get_all_events` (microseconds). */ - std::atomic totalGetAllEventsDiskCopyTimeMicros; + std::atomic totalGetAllEventsTimeMicros; /** @brief Total number of events copied to the in-memory database. */ std::atomic totalEventsCopiedToMemory; /** @brief Total number of events copied to the on-disk database. */ @@ -336,6 +366,14 @@ private: std::atomic eventsCurrentlyInBufferCount; ///< Number of events currently in the buffer. } metrics; + /** + * @brief Structure holding the exposed Prometheus metrics for MySQL event logger. + */ + struct { + std::array p_counter_array {}; + std::array p_gauge_array {}; + } prom_metrics; + // Mutex or rwlock for thread safety #ifdef PROXYSQL_LOGGER_PTHREAD_MUTEX pthread_mutex_t wmutex; ///< Pthread mutex for thread safety. @@ -513,6 +551,14 @@ public: * The function ensures thread safety by acquiring a lock on the circular buffer's mutex before accessing its internal metrics. */ std::unordered_map getAllMetrics() const; + + /** + * @brief Implements the prometheus metrics update hook for the module. + * @details Every module exporting prometheus metrics exposes this function, which is meant to be called + * from `ProxySQL_Admin` registered serial exposer. This way the metrics update is performed lazily every + * time the `serial_exposer` requires it. + */ + void p_update_metrics(); }; diff --git a/lib/MySQL_Logger.cpp b/lib/MySQL_Logger.cpp index 6612eed4c..e2e2f53cd 100644 --- a/lib/MySQL_Logger.cpp +++ b/lib/MySQL_Logger.cpp @@ -24,6 +24,109 @@ using json = nlohmann::json; extern MySQL_Logger *GloMyLogger; +using metric_name = std::string; +using metric_help = std::string; +using metric_tags = std::map; + +using ml_counter_tuple = + std::tuple< + p_ml_counter::metric, + metric_name, + metric_help, + metric_tags + >; + +using ml_gauge_tuple = + std::tuple< + p_ml_gauge::metric, + metric_name, + metric_help, + metric_tags + >; + +using qc_counter_vector = std::vector; +using qc_gauge_vector = std::vector; + +const std::tuple +ml_metrics_map = std::make_tuple( + qc_counter_vector { + std::make_tuple ( + p_ml_counter::memory_copy_count, + "proxysql_mysql_logger_copy_total", + "Number of times events were copied to the in-memory/on-disk databases.", + metric_tags { { "target", "memory" } } + ), + std::make_tuple ( + p_ml_counter::disk_copy_count, + "proxysql_mysql_logger_copy_total", + "Number of times events were copied to the in-memory/on-disk databases.", + metric_tags { { "target", "disk" } } + ), + std::make_tuple ( + p_ml_counter::get_all_events_calls_count, + "proxysql_mysql_logger_get_all_events_calls_total", + "Number of times the 'get_all_events' method was called.", + metric_tags {} + ), + std::make_tuple ( + p_ml_counter::get_all_events_events_count, + "proxysql_mysql_logger_get_all_events_events_total", + "Number of events retrieved by the `get_all_events` method.", + metric_tags {} + ), + std::make_tuple ( + p_ml_counter::total_memory_copy_time_us, + "proxysql_mysql_logger_copy_seconds_total", + "Total time spent copying events to the in-memory/on-disk databases.", + metric_tags { { "target", "memory" } } + ), + std::make_tuple ( + p_ml_counter::total_disk_copy_time_us, + "proxysql_mysql_logger_copy_seconds_total", + "Total time spent copying events to the in-memory/on-disk databases.", + metric_tags { { "target", "disk" } } + ), + std::make_tuple ( + p_ml_counter::total_get_all_events_time_us, + "proxysql_mysql_logger_get_all_events_seconds_total", + "Total time spent in `get_all_events` method.", + metric_tags {} + ), + std::make_tuple ( + p_ml_counter::total_events_copied_to_memory, + "proxysql_mysql_logger_events_copied_total", + "Total number of events copied to the in-memory/on-disk databases.", + metric_tags { { "target", "memory" } } + ), + std::make_tuple ( + p_ml_counter::total_events_copied_to_disk, + "proxysql_mysql_logger_events_copied_total", + "Total number of events copied to the in-memory/on-disk databases.", + metric_tags { { "target", "disk" } } + ), + std::make_tuple ( + p_ml_counter::circular_buffer_events_added_count, + "proxysql_mysql_logger_circular_buffer_events_total", + "The total number of events added/dropped to/from the circular buffer.", + metric_tags { { "type", "added" } } + ), + std::make_tuple ( + p_ml_counter::circular_buffer_events_dropped_count, + "proxysql_mysql_logger_circular_buffer_events_total", + "The total number of events added/dropped to/from the circular buffer.", + metric_tags { { "type", "dropped" } } + ), + }, + qc_gauge_vector { + std::make_tuple ( + p_ml_gauge::circular_buffer_events_size, + "proxysql_mysql_logger_circular_buffer_events", + "Number of events currently present in the circular buffer.", + metric_tags {} + ), + } +); + static uint8_t mysql_encode_length(uint64_t len, unsigned char *hd) { if (len < 251) return 1; if (len < 65536) { if (hd) { *hd=0xfc; }; return 3; } @@ -578,6 +681,14 @@ MySQL_Logger::MySQL_Logger() : metrics{0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0} { audit.log_file_id=0; audit.max_log_file_size=100*1024*1024; MyLogCB = new MySQL_Logger_CircularBuffer(0); + + // Initialize prometheus metrics + init_prometheus_counter_array( + ml_metrics_map, this->prom_metrics.p_counter_array + ); + init_prometheus_gauge_array( + ml_metrics_map, this->prom_metrics.p_gauge_array + ); }; MySQL_Logger::~MySQL_Logger() { @@ -1326,7 +1437,7 @@ int MySQL_Logger::processEvents(SQLite3DB * statsdb , SQLite3DB * statsdb_disk) unsigned long long afterGetAllEventsTimeMicros = monotonic_time(); metrics.getAllEventsEventsCount += events.size(); - metrics.totalGetAllEventsDiskCopyTimeMicros += (afterGetAllEventsTimeMicros-startTimeMicros); + metrics.totalGetAllEventsTimeMicros += (afterGetAllEventsTimeMicros-startTimeMicros); if (statsdb_disk != nullptr) { // Write to on-disk database first @@ -1370,14 +1481,14 @@ int MySQL_Logger::processEvents(SQLite3DB * statsdb , SQLite3DB * statsdb_disk) delete event; } size_t ret = events.size(); -#if 1 // FIXME: TEMPORARY , TO REMOVE +#if 0 std::cerr << "Circular:" << endl; std::cerr << " EventsAddedCount: " << MyLogCB->getEventsAddedCount() << endl; std::cerr << " EventsDroppedCount: " << MyLogCB->getEventsDroppedCount() << endl; std::cerr << " Size: " << MyLogCB->size() << endl; std::cerr << "memoryCopy: Count: " << metrics.memoryCopyCount << " , TimeUs: " << metrics.totalMemoryCopyTimeMicros << endl; std::cerr << "diskCopy: Count: " << metrics.diskCopyCount << " , TimeUs: " << metrics.totalDiskCopyTimeMicros << endl; -#endif // 1 , FIXME: TEMPORARY , TO REMOVE +#endif // 0 return ret; } @@ -1391,14 +1502,36 @@ std::unordered_map MySQL_Logger::getAllMetrics( allMetrics["getAllEventsEventsCount"] = metrics.getAllEventsEventsCount; allMetrics["totalMemoryCopyTimeMicros"] = metrics.totalMemoryCopyTimeMicros; allMetrics["totalDiskCopyTimeMicros"] = metrics.totalDiskCopyTimeMicros; - allMetrics["totalGetAllEventsDiskCopyTimeMicros"] = metrics.totalGetAllEventsDiskCopyTimeMicros; + allMetrics["totalGetAllEventsTimeMicros"] = metrics.totalGetAllEventsTimeMicros; allMetrics["totalEventsCopiedToMemory"] = metrics.totalEventsCopiedToMemory; allMetrics["totalEventsCopiedToDisk"] = metrics.totalEventsCopiedToDisk; //allMetrics["eventsAddedToBufferCount"] = metrics.eventsAddedToBufferCount; //allMetrics["eventsDroppedFromBufferCount"] = metrics.eventsDroppedFromBufferCount; - allMetrics["circularBuffereventsAddedCount"] = MyLogCB->getEventsAddedCount(); + allMetrics["circularBufferEventsAddedCount"] = MyLogCB->getEventsAddedCount(); allMetrics["circularBufferEventsDroppedCount"] = MyLogCB->getEventsDroppedCount(); allMetrics["circularBufferEventsSize"] = MyLogCB->size(); return allMetrics; } + +void MySQL_Logger::p_update_metrics() { + using ml_c = p_ml_counter; + const auto& counters { this->prom_metrics.p_counter_array }; + + p_update_counter(counters[ml_c::memory_copy_count], metrics.memoryCopyCount); + p_update_counter(counters[ml_c::disk_copy_count], metrics.diskCopyCount); + p_update_counter(counters[ml_c::get_all_events_calls_count], metrics.getAllEventsCallsCount); + p_update_counter(counters[ml_c::get_all_events_events_count], metrics.getAllEventsEventsCount); + p_update_counter(counters[ml_c::total_memory_copy_time_us], metrics.totalMemoryCopyTimeMicros / (1000.0 * 1000)); + p_update_counter(counters[ml_c::total_disk_copy_time_us], metrics.totalDiskCopyTimeMicros / (1000.0 * 1000)); + p_update_counter(counters[ml_c::total_get_all_events_time_us], metrics.totalGetAllEventsTimeMicros / (1000.0 * 1000)); + p_update_counter(counters[ml_c::total_events_copied_to_memory], metrics.totalEventsCopiedToMemory); + p_update_counter(counters[ml_c::total_events_copied_to_disk], metrics.totalEventsCopiedToDisk); + + p_update_counter(counters[ml_c::circular_buffer_events_added_count], MyLogCB->getEventsAddedCount()); + p_update_counter(counters[ml_c::circular_buffer_events_dropped_count], MyLogCB->getEventsDroppedCount()); + + using ml_g = p_ml_gauge; + const auto& gauges { this->prom_metrics.p_gauge_array }; + gauges[ml_g::circular_buffer_events_size]->Set(MyLogCB->size()); +} diff --git a/lib/ProxySQL_Admin.cpp b/lib/ProxySQL_Admin.cpp index 5ec62c4df..8155bd349 100644 --- a/lib/ProxySQL_Admin.cpp +++ b/lib/ProxySQL_Admin.cpp @@ -2522,6 +2522,10 @@ void update_modules_metrics() { if (GloProxyCluster) { GloProxyCluster->p_update_metrics(); } + // Update Logger metrics + if (GloMyLogger) { + GloMyLogger->p_update_metrics(); + } // Update admin metrics GloAdmin->p_update_metrics(); diff --git a/lib/ProxySQL_Admin_Stats.cpp b/lib/ProxySQL_Admin_Stats.cpp index c6b477f93..2f1c4c442 100644 --- a/lib/ProxySQL_Admin_Stats.cpp +++ b/lib/ProxySQL_Admin_Stats.cpp @@ -592,6 +592,19 @@ void ProxySQL_Admin::stats___mysql_global() { sqlite3_global_stats_row_step(statsdb, row_stmt, "mysql_listener_paused", admin_proxysql_mysql_paused); + + if (GloMyLogger != nullptr) { + const string prefix = "MySQL_Logger-"; + std::unordered_map metrics = GloMyLogger->getAllMetrics(); + for (std::unordered_map::iterator it = metrics.begin(); it != metrics.end(); it++) { + unsigned int l = strlen(a) + prefix.length() + it->first.length() + 32; + char *query = (char *)malloc(l); + sprintf(query, a, string(prefix + it->first).c_str(),std::to_string(it->second).c_str()); + statsdb->execute(query); + free(query); + } + } + statsdb->execute("COMMIT"); } diff --git a/test/tap/tests/mysql_query_logging_memory-t.cpp b/test/tap/tests/mysql_query_logging_memory-t.cpp index 9d160d9eb..c260d3547 100644 --- a/test/tap/tests/mysql_query_logging_memory-t.cpp +++ b/test/tap/tests/mysql_query_logging_memory-t.cpp @@ -159,7 +159,20 @@ bool checkQueryResult(MYSQL* conn, const std::string& query, const std::map::const_iterator it = expectedResults.begin() ; it != expectedResults.end() ; it++) { + diag(" %d : %d", it->first, it->second); + } + diag("ActualResult:"); + for (std::map::const_iterator it = actualResults.begin() ; it != actualResults.end() ; it++) { + diag(" %d : %d", it->first, it->second); + } + } + return ret; } @@ -278,7 +291,7 @@ int main() { return -1; } - if (mysql_query(nonExistentSchemaConn, "SELECT 1")) { + if (mysql_query(nonExistentSchemaConn, "SELECT /* create_new_connection=1 */ 1")) { int error_code = mysql_errno(nonExistentSchemaConn); ok(error_code == 1044, "Query on non-existent schema returned expected error (1044): %d", error_code); } else { diff --git a/test/tap/tests/set_character_set-t.cpp b/test/tap/tests/set_character_set-t.cpp index f208e532f..97eed412a 100644 --- a/test/tap/tests/set_character_set-t.cpp +++ b/test/tap/tests/set_character_set-t.cpp @@ -48,7 +48,7 @@ int main(int argc, char** argv) { if(cl.getEnv()) return exit_status(); - plan(11); + plan(8); diag("Testing SET CHARACTER SET"); MYSQL* mysql = mysql_init(NULL);