dict-client: Add time spent in dict-server to "slow dict lookup" messages.

This way you can see if the slowness was due to some communication problem
between dict-client/server or internally in dict server.

This change keeps backwards compatibility in the dict protocol for both
client and server.

diff --git a/src/dict/dict-commands.c b/src/dict/dict-commands.c
index 329347bed492365c582bddae408db632925c2bb6..e5dc691ab9d36cbb7fd935647b80e93534a4c2f6 100644 (file)
--- a/src/dict/dict-commands.c
+++ b/src/dict/dict-commands.c
@@ -13,6 +13,7 @@
 #include "dict-commands.h"
 #include "main.h"
 
+#define DICT_CLIENT_PROTOCOL_TIMINGS_MIN_VERSION 1
 #define DICT_OUTPUT_OPTIMAL_SIZE 1024
 
 struct dict_cmd_func {
@@ -97,7 +98,6 @@ cmd_stats_update(struct dict_connection_cmd *cmd, struct timing *timing)
        if (!dict_settings->verbose_proctitle)
                return;
 
-       io_loop_time_refresh();
        diff = timeval_diff_usecs(&ioloop_timeval, &cmd->start_timeval);
        if (diff < 0)
                diff = 0;
@@ -105,22 +105,42 @@ cmd_stats_update(struct dict_connection_cmd *cmd, struct timing *timing)
        dict_proctitle_update_later();
 }
 
+static void
+dict_cmd_reply_handle_timings(struct dict_connection_cmd *cmd,
+                             string_t *str, struct timing *timing)
+{
+       io_loop_time_refresh();
+       cmd_stats_update(cmd, timing);
+
+       if (cmd->conn->minor_version < DICT_CLIENT_PROTOCOL_TIMINGS_MIN_VERSION)
+               return;
+       str_printfa(str, "\t%ld\t%u\t%ld\t%u",
+                   (long)cmd->start_timeval.tv_sec,
+                   (unsigned int)cmd->start_timeval.tv_usec,
+                   (long)ioloop_timeval.tv_sec,
+                   (unsigned int)ioloop_timeval.tv_usec);
+}
+
 static void
 cmd_lookup_callback(const struct dict_lookup_result *result, void *context)
 {
        struct dict_connection_cmd *cmd = context;
-
-       cmd_stats_update(cmd, cmd_stats.lookups);
+       string_t *str = t_str_new(128);
 
        if (result->ret > 0) {
-               cmd->reply = i_strdup_printf("%c%s\n",
-                       DICT_PROTOCOL_REPLY_OK, str_tabescape(result->value));
+               str_append_c(str, DICT_PROTOCOL_REPLY_OK);
+               str_append_tabescaped(str, result->value);
        } else if (result->ret == 0) {
-               cmd->reply = i_strdup_printf("%c\n", DICT_PROTOCOL_REPLY_NOTFOUND);
+               str_append_c(str, DICT_PROTOCOL_REPLY_NOTFOUND);
        } else {
                i_error("%s", result->error);
-               cmd->reply = i_strdup_printf("%c\n", DICT_PROTOCOL_REPLY_FAIL);
+               str_append_c(str, DICT_PROTOCOL_REPLY_FAIL);
+               str_append_tabescaped(str, result->error);
        }
+       dict_cmd_reply_handle_timings(cmd, str, cmd_stats.lookups);
+       str_append_c(str, '\n');
+
+       cmd->reply = i_strdup(str_c(str));
        dict_connection_cmds_flush(cmd->conn);
 }
 
@@ -168,10 +188,10 @@ static int cmd_iterate_flush(struct dict_connection_cmd *cmd)
        str_truncate(str, 0);
        if (dict_iterate_deinit(&cmd->iter) < 0)
                str_append_c(str, DICT_PROTOCOL_REPLY_FAIL);
+       dict_cmd_reply_handle_timings(cmd, str, cmd_stats.iterations);
        str_append_c(str, '\n');
        o_stream_uncork(cmd->conn->output);
 
-       cmd_stats_update(cmd, cmd_stats.iterations);
        cmd->reply = i_strdup(str_c(str));
        return 1;
 }
@@ -289,10 +309,9 @@ dict_connection_transaction_lookup_parse(struct dict_connection *conn,
 static void
 cmd_commit_finish(struct dict_connection_cmd *cmd, int ret, bool async)
 {
+       string_t *str = t_str_new(64);
        char chr;
 
-       cmd_stats_update(cmd, cmd_stats.commits);
-
        switch (ret) {
        case 1:
                chr = DICT_PROTOCOL_REPLY_OK;
@@ -309,11 +328,15 @@ cmd_commit_finish(struct dict_connection_cmd *cmd, int ret, bool async)
                break;
        }
        if (async) {
-               cmd->reply = i_strdup_printf("%c%c%u\n",
+               str_printfa(str, "%c%c%u",
                        DICT_PROTOCOL_REPLY_ASYNC_COMMIT, chr, cmd->trans_id);
        } else {
-               cmd->reply = i_strdup_printf("%c%u\n", chr, cmd->trans_id);
+               str_printfa(str, "%c%u", chr, cmd->trans_id);
        }
+       dict_cmd_reply_handle_timings(cmd, str, cmd_stats.commits);
+       str_append_c(str, '\n');
+       cmd->reply = i_strdup(str_c(str));
+
        dict_connection_transaction_array_remove(cmd->conn, cmd->trans_id);
        dict_connection_cmds_flush(cmd->conn);
 }

diff --git a/src/dict/dict-connection.c b/src/dict/dict-connection.c
index 4cbffc1d7871c7bbe173260ab64791f9ff852315..318b0741a616045bce28f8027c3299657cc7775c 100644 (file)
--- a/src/dict/dict-connection.c
+++ b/src/dict/dict-connection.c
@@ -33,9 +33,9 @@ static int dict_connection_parse_handshake(struct dict_connection *conn,
            *line++ != '\t')
                return -1;
 
-       /* skip minor version */
-       while (*line != '\t' && *line != '\0') line++;
-
+       /* read minor version */
+       if (str_parse_uint(line, &conn->minor_version, &line) < 0)
+               return -1;
        if (*line++ != '\t')
                return -1;
 

diff --git a/src/dict/dict-connection.h b/src/dict/dict-connection.h
index 2f9149c0f05b76b8a5cb6b7f2eba3d2ff364ba3c..6202149c5888a4b518aed5601d7ef97defefce18 100644 (file)
--- a/src/dict/dict-connection.h
+++ b/src/dict/dict-connection.h
@@ -18,6 +18,7 @@ struct dict_connection {
        char *name;
        struct dict *dict;
        enum dict_data_type value_type;
+       unsigned int minor_version;
 
        int fd;
        struct io *io;

diff --git a/src/lib-dict/dict-client.c b/src/lib-dict/dict-client.c
index 42a8d8f51f155f75fc118f0669b16062b383483d..eb9c94b6dcdaaafc1a0e7ec1f1458196a486fc64 100644 (file)
--- a/src/lib-dict/dict-client.c
+++ b/src/lib-dict/dict-client.c
@@ -761,17 +761,42 @@ static const char *dict_wait_warnings(const struct client_dict_cmd *cmd)
                lock_msecs/1000, lock_msecs%1000);
 }
 
-static const char *dict_warnings_sec(const struct client_dict_cmd *cmd, int msecs)
+static const char *
+dict_warnings_sec(const struct client_dict_cmd *cmd, int msecs,
+                 const char *const *extra_args)
 {
-       return t_strdup_printf("%d.%03d secs (%s)", msecs/1000, msecs%1000,
-                              dict_wait_warnings(cmd));
+       string_t *str = t_str_new(64);
+       struct timeval tv_start, tv_end;
+       unsigned int tv_start_usec, tv_end_usec;
+
+       str_printfa(str, "%d.%03d secs (%s", msecs/1000, msecs%1000,
+                   dict_wait_warnings(cmd));
+       if (str_array_length(extra_args) >= 4 &&
+           str_to_time(extra_args[0], &tv_start.tv_sec) == 0 &&
+           str_to_uint(extra_args[1], &tv_start_usec) == 0 &&
+           str_to_time(extra_args[2], &tv_end.tv_sec) == 0 &&
+           str_to_uint(extra_args[3], &tv_end_usec) == 0) {
+               tv_start.tv_usec = tv_start_usec;
+               tv_end.tv_usec = tv_end_usec;
+
+               int server_msecs_since_start =
+                       timeval_diff_msecs(&ioloop_timeval, &tv_start);
+               int server_msecs = timeval_diff_msecs(&tv_end, &tv_start);
+               str_printfa(str, ", started on dict-server %u.%03d secs ago, "
+                           "took %u.%03d secs",
+                           server_msecs_since_start/1000,
+                           server_msecs_since_start%1000,
+                           server_msecs/1000, server_msecs%1000);
+       }
+       str_append_c(str, ')');
+       return str_c(str);
 }
 
 static void
 client_dict_lookup_async_callback(struct client_dict_cmd *cmd,
                                  enum dict_protocol_reply reply,
                                  const char *value,
-                                 const char *const *extra_args ATTR_UNUSED,
+                                 const char *const *extra_args,
                                  const char *error,
                                  bool disconnected ATTR_UNUSED)
 {
@@ -809,11 +834,11 @@ client_dict_lookup_async_callback(struct client_dict_cmd *cmd,
        if (result.error != NULL) {
                /* include timing info always in error messages */
                result.error = t_strdup_printf("%s (reply took %s)",
-                       result.error, dict_warnings_sec(cmd, diff));
+                       result.error, dict_warnings_sec(cmd, diff, extra_args));
        } else if (!cmd->background &&
                   diff >= DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS) {
                i_warning("read(%s): dict lookup took %s: %s",
-                         dict->conn.conn.name, dict_warnings_sec(cmd, diff),
+                         dict->conn.conn.name, dict_warnings_sec(cmd, diff, extra_args),
                          cmd->query);
        }
 
@@ -898,7 +923,8 @@ static void client_dict_iterate_free(struct client_dict_iterate_context *ctx)
 
 static void
 client_dict_iter_api_callback(struct client_dict_iterate_context *ctx,
-                             struct client_dict_cmd *cmd)
+                             struct client_dict_cmd *cmd,
+                             const char *const *extra_args)
 {
        struct client_dict *dict = cmd->dict;
 
@@ -911,13 +937,13 @@ client_dict_iter_api_callback(struct client_dict_iterate_context *ctx,
                if (ctx->error != NULL) {
                        /* include timing info always in error messages */
                        char *new_error = i_strdup_printf("%s (reply took %s)",
-                               ctx->error, dict_warnings_sec(cmd, diff));
+                               ctx->error, dict_warnings_sec(cmd, diff, extra_args));
                        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 %s: %s",
-                                 dict->conn.conn.name, dict_warnings_sec(cmd, diff),
+                                 dict->conn.conn.name, dict_warnings_sec(cmd, diff, extra_args),
                                  cmd->query);
                }
        }
@@ -955,13 +981,14 @@ client_dict_iter_async_callback(struct client_dict_cmd *cmd,
        case DICT_PROTOCOL_REPLY_ITER_FINISHED:
                /* end of iteration */
                ctx->finished = TRUE;
-               client_dict_iter_api_callback(ctx, cmd);
+               client_dict_iter_api_callback(ctx, cmd, extra_args);
                client_dict_iterate_free(ctx);
                return;
        case DICT_PROTOCOL_REPLY_OK:
                /* key \t value */
                iter_key = value;
                iter_value = extra_args[0];
+               extra_args++;
                break;
        case DICT_PROTOCOL_REPLY_FAIL:
                error = t_strdup_printf("dict-server returned failure: %s", value);
@@ -980,7 +1007,7 @@ client_dict_iter_async_callback(struct client_dict_cmd *cmd,
                if (ctx->error == NULL)
                        ctx->error = i_strdup(error);
                ctx->finished = TRUE;
-               client_dict_iter_api_callback(ctx, cmd);
+               client_dict_iter_api_callback(ctx, cmd, extra_args);
                client_dict_iterate_free(ctx);
                return;
        }
@@ -995,7 +1022,7 @@ client_dict_iter_async_callback(struct client_dict_cmd *cmd,
        result->key = p_strdup(ctx->results_pool, iter_key);
        result->value = p_strdup(ctx->results_pool, iter_value);
 
-       client_dict_iter_api_callback(ctx, cmd);
+       client_dict_iter_api_callback(ctx, cmd, NULL);
 }
 
 static struct dict_iterate_context *
@@ -1152,12 +1179,15 @@ client_dict_transaction_commit_callback(struct client_dict_cmd *cmd,
                ret = DICT_COMMIT_RET_WRITE_UNCERTAIN;
                /* fallthrough */
        case DICT_PROTOCOL_REPLY_FAIL: {
+               /* value contains the obsolete trans_id */
                const char *error = extra_args[0];
 
                i_error("dict-client: server returned failure: %s "
                        "(reply took %u.%03u secs)",
                        error != NULL ? error : "",
                        diff/1000, diff%1000);
+               if (error != NULL)
+                       extra_args++;
                break;
        }
        default:
@@ -1174,7 +1204,7 @@ client_dict_transaction_commit_callback(struct client_dict_cmd *cmd,
            diff >= DICT_CLIENT_REQUEST_WARN_TIMEOUT_MSECS) {
                i_warning("read(%s): dict commit took %s: "
                          "%s (%u commands, first: %s)",
-                         dict->conn.conn.name, dict_warnings_sec(cmd, diff),
+                         dict->conn.conn.name, dict_warnings_sec(cmd, diff, extra_args),
                          cmd->query, cmd->trans->query_count,
                          cmd->trans->first_query);
        }

diff --git a/src/lib-dict/dict-client.h b/src/lib-dict/dict-client.h
index 349b2f1bbda4158f6143364422dfa466eef8ba5e..4a4a3a4c764154feb75e0062ca56a562e1669d97 100644 (file)
--- a/src/lib-dict/dict-client.h
+++ b/src/lib-dict/dict-client.h
@@ -6,7 +6,7 @@
 #define DEFAULT_DICT_SERVER_SOCKET_FNAME "dict"
 
 #define DICT_CLIENT_PROTOCOL_MAJOR_VERSION 2
-#define DICT_CLIENT_PROTOCOL_MINOR_VERSION 0
+#define DICT_CLIENT_PROTOCOL_MINOR_VERSION 1
 
 #define DICT_CLIENT_MAX_LINE_LENGTH (64*1024)