cassandra: Warn if queries take too long (default 5 secs)

Can be changed with e.g. "connect = ... warn_timeout=30s"

src/lib-sql/driver-cassandra.c

@@ -25,6 +25,8 @@
 #define CASSANDRA_FALLBACK_FIRST_RETRY_MSECS 50
 #define CASSANDRA_FALLBACK_MAX_RETRY_MSECS (1000*60)
 
+#define CASS_QUERY_DEFAULT_WARN_TIMEOUT_SECS 5
+
 typedef void driver_cassandra_callback_t(CassFuture *future, void *context);
 
 enum cassandra_query_type {
@@ -56,6 +58,7 @@ struct cassandra_db {
 	unsigned int protocol_version;
 	unsigned int num_threads;
 	unsigned int connect_timeout_secs, request_timeout_secs;
+	unsigned int warn_timeout_secs;
 	in_port_t port;
 
 	CassCluster *cluster;
@@ -384,6 +387,7 @@ static void driver_cassandra_parse_connect_string(struct cassandra_db *db,
 	db->delete_consistency = CASS_CONSISTENCY_LOCAL_QUORUM;
 	db->connect_timeout_secs = SQL_CONNECT_TIMEOUT_SECS;
 	db->request_timeout_secs = SQL_QUERY_TIMEOUT_SECS;
+	db->warn_timeout_secs = CASS_QUERY_DEFAULT_WARN_TIMEOUT_SECS;
 
 	args = t_strsplit_spaces(connect_string, " ");
 	for (; *args != NULL; args++) {
@@ -447,6 +451,9 @@ static void driver_cassandra_parse_connect_string(struct cassandra_db *db,
 		} else if (strcmp(key, "request_timeout") == 0) {
 			if (settings_get_time(value, &db->request_timeout_secs, &error) < 0)
 				i_fatal("cassandra: Invalid request_timeout '%s': %s", value, error);
+		} else if (strcmp(key, "warn_timeout") == 0) {
+			if (settings_get_time(value, &db->warn_timeout_secs, &error) < 0)
+				i_fatal("cassandra: Invalid warn_timeout '%s': %s", value, error);
 		} else if (strcmp(key, "metrics") == 0) {
 			i_free(db->metrics_path);
 			db->metrics_path = i_strdup(value);
@@ -614,21 +621,30 @@ static void driver_cassandra_result_free(struct sql_result *_result)
 	struct cassandra_db *db = (struct cassandra_db *)_result->db;
         struct cassandra_result *result = (struct cassandra_result *)_result;
 	struct timeval now;
+	const char *str;
+	long long reply_usecs;
 
 	i_assert(!result->api.callback);
 	i_assert(result->callback == NULL);
 
 	if (_result == db->sync_result)
 		db->sync_result = NULL;
 
-	if (db->log_level >= CASS_LOG_DEBUG) {
+	reply_usecs = timeval_diff_usecs(&result->finish_time, &result->start_time);
+	if (db->log_level >= CASS_LOG_DEBUG ||
+	    reply_usecs/1000000 >= db->warn_timeout_secs) {
 		if (gettimeofday(&now, NULL) < 0)
 			i_fatal("gettimeofday() failed: %m");
-		i_debug("cassandra: Finished query '%s' (%u rows, %lld+%lld us): %s", result->query,
-			result->row_count,
-			timeval_diff_usecs(&result->finish_time, &result->start_time),
+		str = t_strdup_printf(
+			"cassandra: Finished query '%s' (%u rows, %lld+%lld us): %s",
+			result->query, result->row_count, reply_usecs,
 			timeval_diff_usecs(&now, &result->finish_time),
 			result->error != NULL ? result->error : "success");
+
+		if (reply_usecs/1000000 >= db->warn_timeout_secs)
+			i_warning("%s", str);
+		else
+			i_debug("%s", str);
 	}
 
 	if (result->result != NULL)