From: Timo Sirainen <timo.sirainen@dovecot.fi>
Date: Tue, 23 Aug 2016 09:55:24 +0000 (+0300)
Subject: dict-client: In slow query warnings, log time spent in ioloop and lock waits.
X-Git-Tag: 2.2.26~316
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=5b0597238b6a2856922d07fc63a56a5af49d53d3;p=thirdparty%2Fdovecot%2Fcore.git

dict-client: In slow query warnings, log time spent in ioloop and lock waits.

Possibly we want to remove the warnings entirely if most of the time has been
spent on lock waits (or alternatively: not spent in ioloop).
---

diff --git a/src/lib-dict/dict-client.c b/src/lib-dict/dict-client.c
index 78c2d153bb..5a8f7e347f 100644
--- a/src/lib-dict/dict-client.c
+++ b/src/lib-dict/dict-client.c
@@ -5,6 +5,7 @@
 #include "llist.h"
 #include "str.h"
 #include "strescape.h"
+#include "file-lock.h"
 #include "time-util.h"
 #include "connection.h"
 #include "ostream.h"
@@ -670,6 +671,17 @@ static bool client_dict_switch_ioloop(struct dict *_dict)
 	return array_count(&dict->cmds) > 0;
 }
 
+static const char *dict_warnings_sec(int msecs)
+{
+	int ioloop_msecs = (io_loop_get_wait_usecs(current_ioloop)+999) / 1000;
+	int lock_msecs = (file_lock_wait_get_total_usecs()+999) / 1000;
+
+	return t_strdup_printf(
+		"%u.%03u secs (%u.%03u in ioloop, %u.%03u in locks)",
+		msecs/1000, msecs%1000, ioloop_msecs/1000, ioloop_msecs%1000,
+		lock_msecs/1000, lock_msecs%1000);
+}
+
 static void
 client_dict_lookup_async_callback(struct client_dict_cmd *cmd, const char *line,
 				  const char *error, bool disconnected ATTR_UNUSED)
@@ -707,12 +719,12 @@ client_dict_lookup_async_callback(struct client_dict_cmd *cmd, const char *line,
 	int diff = timeval_diff_msecs(&ioloop_timeval, &cmd->start_time);
 	if (result.error != NULL) {
 		/* include timing info always in error messages */
-		result.error = t_strdup_printf("%s (reply took %u.%03u secs)",
-			result.error, diff/1000, diff%1000);
+		result.error = t_strdup_printf("%s (reply took %s)",
+			result.error, dict_warnings_sec(diff));
 	} else if (!cmd->background &&
 		   diff >= DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS) {
-		i_warning("read(%s): dict lookup took %u.%03u seconds: %s",
-			  dict->conn.conn.name, diff/1000, diff % 1000,
+		i_warning("read(%s): dict lookup took %s: %s",
+			  dict->conn.conn.name, dict_warnings_sec(diff),
 			  cmd->query);
 	}
 
@@ -804,15 +816,14 @@ client_dict_iter_api_callback(struct client_dict_iterate_context *ctx,
 		int diff = timeval_diff_msecs(&ioloop_timeval, &cmd->start_time);
 		if (ctx->error != NULL) {
 			/* include timing info always in error messages */
-			char *new_error = i_strdup_printf(
-				"%s (reply took %u.%03u secs)",
-				ctx->error, diff/1000, diff%1000);
+			char *new_error = i_strdup_printf("%s (reply took %s)",
+				ctx->error, dict_warnings_sec(diff));
 			i_free(ctx->error);
 			ctx->error = new_error;
 		} else if (!cmd->background &&
 			   diff >= DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS) {
-			i_warning("read(%s): dict iteration took %u.%03u seconds: %s",
-				  dict->conn.conn.name, diff/1000, diff % 1000,
+			i_warning("read(%s): dict iteration took %s: %s",
+				  dict->conn.conn.name, dict_warnings_sec(diff),
 				  cmd->query);
 		}
 	}
@@ -1047,9 +1058,9 @@ client_dict_transaction_commit_callback(struct client_dict_cmd *cmd,
 	if (ret >= 0 && !cmd->background &&
 	    !cmd->trans->ctx.no_slowness_warning &&
 	    diff >= DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS) {
-		i_warning("read(%s): dict commit took %u.%03u seconds: "
+		i_warning("read(%s): dict commit took %s: "
 			  "%s (%u commands, first: %s)",
-			  dict->conn.conn.name, diff/1000, diff % 1000,
+			  dict->conn.conn.name, dict_warnings_sec(diff),
 			  cmd->query, cmd->trans->query_count,
 			  cmd->trans->first_query);
 	}