From: Timo Sirainen Date: Mon, 21 Nov 2016 14:45:55 +0000 (+0200) Subject: dict-client: Add time spent in dict-server to "slow dict lookup" messages. X-Git-Tag: 2.2.27~90 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=0bfc9b7585f0867bac09b5425ff2629c58f9bbc5;p=thirdparty%2Fdovecot%2Fcore.git 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 329347bed4..e5dc691ab9 100644 --- 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 4cbffc1d78..318b0741a6 100644 --- 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 2f9149c0f0..6202149c58 100644 --- 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 42a8d8f51f..eb9c94b6dc 100644 --- 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 349b2f1bbd..4a4a3a4c76 100644 --- 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)