Mercurial > dovecot > core-2.2

changeset 20524:46d7324c8246

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
dict-client: Improved logging for slow queries. Especially commits now say what the first query within the commit was.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Thu, 14 Jul 2016 07:22:04 -0500
parents 7838bc17ed04
children 49ab9d8293ba
files src/lib-dict/dict-client.c
diffstat 1 files changed, 32 insertions(+), 7 deletions(-) [+]
line wrap: on
line diff
--- a/src/lib-dict/dict-client.c	Thu Jul 14 06:53:54 2016 -0500
+++ b/src/lib-dict/dict-client.c	Thu Jul 14 07:22:04 2016 -0500
@@ -32,6 +32,7 @@
 	struct client_dict *dict;
 	struct timeval start_time;
 	char *query;
+	char *commit_query_human;
 
 	bool retry_errors;
 	bool no_replies;
@@ -97,9 +98,11 @@
 	struct dict_transaction_context ctx;
 	struct client_dict_transaction_context *prev, *next;
 
+	char *first_query;
 	char *error;
 
 	unsigned int id;
+	unsigned int query_count;
 
 	bool sent_begin:1;
 };
@@ -136,6 +139,7 @@
 	if (--cmd->refcount > 0)
 		return TRUE;
 
+	i_free(cmd->commit_query_human);
 	i_free(cmd->query);
 	i_free(cmd);
 	return FALSE;
@@ -303,6 +307,10 @@
 			return;
 	}
 
+	ctx->query_count++;
+	if (ctx->first_query == NULL)
+		ctx->first_query = i_strdup(query);
+
 	cmd = client_dict_cmd_init(dict, query);
 	cmd->no_replies = TRUE;
 	if (!client_dict_cmd_send(dict, &cmd, &error))
@@ -366,9 +374,17 @@
 	}
 	diff = cmds[0]->background ? 0 :
 		timeval_diff_msecs(&ioloop_timeval, &cmds[0]->start_time);
-	if (diff >= DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS) {
-		i_warning("read(%s): dict lookup took %u.%03u seconds: %s",
+	if (diff < DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS)
+		;
+	else if (cmds[0]->commit_query_human != NULL) {
+		i_warning("read(%s): dict commit took %u.%03u seconds: %s",
 			  dict->conn.conn.name, diff/1000, diff % 1000,
+			  cmds[0]->commit_query_human);
+	} else {
+		const char *type = cmds[0]->iter != NULL ?
+			"iteration" : "lookup";
+		i_warning("read(%s): dict %s took %u.%03u seconds: %s",
+			  dict->conn.conn.name, type, diff/1000, diff % 1000,
 			  cmds[0]->query);
 	}
 	client_dict_cmd_unref(cmds[0]);
@@ -906,6 +922,14 @@
 	dict_post_api_callback(dict);
 }
 
+static void
+client_dict_transaction_free(struct client_dict_transaction_context *ctx)
+{
+	i_free(ctx->first_query);
+	i_free(ctx->error);
+	i_free(ctx);
+}
+
 static void commit_sync_callback(int ret, void *context)
 {
 	int *ret_p = context;
@@ -930,6 +954,10 @@
 	if (ctx->sent_begin && ctx->error == NULL) {
 		query = t_strdup_printf("%c%u", DICT_PROTOCOL_CMD_COMMIT, ctx->id);
 		cmd = client_dict_cmd_init(dict, query);
+		cmd->commit_query_human = i_strdup_printf(
+			"%s (%u commands, first: %s)", query,
+			ctx->query_count, ctx->first_query);
+
 		cmd->callback = client_dict_transaction_commit_callback;
 		if (callback != NULL) {
 			cmd->api_callback.commit = callback;
@@ -956,9 +984,7 @@
 		ret = 1;
 	}
 
-	i_free(ctx->error);
-	i_free(ctx);
-
+	client_dict_transaction_free(ctx);
 	client_dict_add_timeout(dict);
 	return ret;
 }
@@ -979,8 +1005,7 @@
 	}
 
 	DLLIST_REMOVE(&dict->transactions, ctx);
-	i_free(ctx);
-
+	client_dict_transaction_free(ctx);
 	client_dict_add_timeout(dict);
 }