Export MySQL_Logger metrics for v3.0

Port of #4802

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<unsigned long long> totalDiskCopyTimeMicros;
 		/** @brief Total time spent in `get_all_events` (microseconds). */
-		std::atomic<unsigned long long> totalGetAllEventsDiskCopyTimeMicros;
+		std::atomic<unsigned long long> totalGetAllEventsTimeMicros;
 		/** @brief Total number of events copied to the in-memory database. */
 		std::atomic<unsigned long long> totalEventsCopiedToMemory;
 		/** @brief Total number of events copied to the on-disk database. */
@@ -336,6 +366,14 @@ private:
 		std::atomic<unsigned long long> eventsCurrentlyInBufferCount; ///< Number of events currently in the buffer.
 	} metrics;
 
+	/**
+	 * @brief Structure holding the exposed Prometheus metrics for MySQL event logger.
+	 */
+	struct {
+		std::array<prometheus::Counter*, p_ml_counter::__size> p_counter_array {};
+		std::array<prometheus::Gauge*, p_ml_gauge::__size> 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<std::string, unsigned long long> 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();
 };
 
 

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<std::string, std::string>;
+
+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<ml_counter_tuple>;
+using qc_gauge_vector = std::vector<ml_gauge_tuple>;
+
+const std::tuple<qc_counter_vector, qc_gauge_vector>
+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_idx, p_ml_counter>(
+		ml_metrics_map, this->prom_metrics.p_counter_array
+	);
+	init_prometheus_gauge_array<ml_metrics_map_idx, p_ml_gauge>(
+		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<std::string, unsigned long long> 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());
+}

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

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<std::string, unsigned long long> metrics = GloMyLogger->getAllMetrics();
+		for (std::unordered_map<std::string, unsigned long long>::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");
 }
 

test/tap/tests/mysql_query_logging_memory-t.cpp

@@ -159,7 +159,20 @@ bool checkQueryResult(MYSQL* conn, const std::string& query, const std::map<int,
     }
     mysql_free_result(result);
 
-    return actualResults == expectedResults;
+	bool ret = false;
+	ret = (actualResults == expectedResults);
+	if (ret == false) {
+		diag("Query: %s", query.c_str());
+		diag("ExpectedResult:");
+		for (std::map<int, int>::const_iterator it = expectedResults.begin() ; it != expectedResults.end() ; it++) {
+			diag("  %d : %d", it->first, it->second);
+		}
+		diag("ActualResult:");
+		for (std::map<int, int>::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 {

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