From e33462704d38d05c4109929da4923794f699e3cc Mon Sep 17 00:00:00 2001 From: Timo Sirainen Date: Mon, 26 Sep 2016 15:38:27 +0300 Subject: [PATCH] dict-client: Fixed lock and ioloop wait timings in log messages. Previously it was logging the total amount of time spent on lock waits or on ioloop during the existence of the entire process, rather than how much time the command itself was spending on those. This wasn't very useful. Now it also tries to separate the time spent on the main ioloop and in dict_wait(). --- src/lib-dict/dict-client.c | 57 ++++++++++++++++++++++++++++++-------- 1 file changed, 46 insertions(+), 11 deletions(-) diff --git a/src/lib-dict/dict-client.c b/src/lib-dict/dict-client.c index 311e5d7651..538855087b 100644 --- a/src/lib-dict/dict-client.c +++ b/src/lib-dict/dict-client.c @@ -34,6 +34,10 @@ struct client_dict_cmd { struct timeval start_time; char *query; + uint64_t start_main_ioloop_usecs; + uint64_t start_dict_ioloop_usecs; + uint64_t start_lock_usecs; + bool retry_errors; bool no_replies; bool unfinished; @@ -128,6 +132,17 @@ client_dict_cmd_init(struct client_dict *dict, const char *query) cmd->dict = dict; cmd->query = i_strdup(query); cmd->start_time = ioloop_timeval; + if (current_ioloop == dict->ioloop) { + /* coming here from client_dict_wait() */ + i_assert(dict->prev_ioloop != NULL); + cmd->start_main_ioloop_usecs = + io_loop_get_wait_usecs(dict->prev_ioloop); + } else { + cmd->start_main_ioloop_usecs = + io_loop_get_wait_usecs(current_ioloop); + } + cmd->start_dict_ioloop_usecs = io_loop_get_wait_usecs(dict->ioloop); + cmd->start_lock_usecs = file_lock_wait_get_total_usecs(); return cmd; } @@ -700,14 +715,34 @@ static bool client_dict_switch_ioloop(struct dict *_dict) return array_count(&dict->cmds) > 0; } -static const char *dict_warnings_sec(int msecs) +static const char *dict_warnings_sec(const struct client_dict_cmd *cmd, 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; + int main_ioloop_msecs; + + /* we'll assume that the main ioloop is always the same in here and + in client_dict_cmd_init(), which strictly doesn't have to be true, + but practically is. */ + if (current_ioloop == cmd->dict->ioloop) { + /* coming here from client_dict_wait() */ + i_assert(cmd->dict->prev_ioloop != NULL); + main_ioloop_msecs = + (io_loop_get_wait_usecs(cmd->dict->prev_ioloop) - + cmd->start_main_ioloop_usecs + 999) / 1000; + } else { + main_ioloop_msecs = + (io_loop_get_wait_usecs(current_ioloop) - + cmd->start_main_ioloop_usecs + 999) / 1000; + } + int dict_ioloop_msecs = (io_loop_get_wait_usecs(cmd->dict->ioloop) - + cmd->start_dict_ioloop_usecs + 999) / 1000; + int lock_msecs = (file_lock_wait_get_total_usecs() - + cmd->start_lock_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, + "%u.%03u secs (%u.%03u in main ioloop, %u.%03u in dict wait, " + "%u.%03u in locks)", msecs/1000, msecs%1000, + main_ioloop_msecs/1000, main_ioloop_msecs%1000, + dict_ioloop_msecs/1000, dict_ioloop_msecs%1000, lock_msecs/1000, lock_msecs%1000); } @@ -749,11 +784,11 @@ client_dict_lookup_async_callback(struct client_dict_cmd *cmd, const char *line, 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(diff)); + result.error, dict_warnings_sec(cmd, diff)); } 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(diff), + dict->conn.conn.name, dict_warnings_sec(cmd, diff), cmd->query); } @@ -846,13 +881,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(diff)); + ctx->error, dict_warnings_sec(cmd, 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 %s: %s", - dict->conn.conn.name, dict_warnings_sec(diff), + dict->conn.conn.name, dict_warnings_sec(cmd, diff), cmd->query); } } @@ -1088,12 +1123,12 @@ client_dict_transaction_commit_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(diff)); + result.error, dict_warnings_sec(cmd, diff)); } else if (!cmd->background && !cmd->trans->ctx.no_slowness_warning && 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(diff), + dict->conn.conn.name, dict_warnings_sec(cmd, diff), cmd->query, cmd->trans->query_count, cmd->trans->first_query); }