dict-client: Improved logging for slow queries.

Especially commits now say what the first query within the commit was.

diff --git a/src/lib-dict/dict-client.c b/src/lib-dict/dict-client.c
index 1702d07b2c6e97a246eaa9ac01f8096b78661c90..926d025f17165e6319d78cfb8b761167d86b8e60 100644 (file)
--- a/src/lib-dict/dict-client.c
+++ b/src/lib-dict/dict-client.c
@@ -32,6 +32,7 @@ struct client_dict_cmd {
        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 client_dict_transaction_context {
        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 @@ static bool client_dict_cmd_unref(struct client_dict_cmd *cmd)
        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 @@ client_dict_send_transaction_query(struct client_dict_transaction_context *ctx,
                        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 @@ static int dict_conn_input_line(struct connection *_conn, const char *line)
        }
        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 @@ client_dict_transaction_commit_callback(struct client_dict_cmd *cmd,
        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 @@ client_dict_transaction_commit(struct dict_transaction_context *_ctx,
        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 @@ client_dict_transaction_commit(struct dict_transaction_context *_ctx,
                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 @@ client_dict_transaction_rollback(struct dict_transaction_context *_ctx)
        }
 
        DLLIST_REMOVE(&dict->transactions, ctx);
-       i_free(ctx);
-
+       client_dict_transaction_free(ctx);
        client_dict_add_timeout(dict);
 }