From 032b2f3846bfb7465e9720aa4997ca86aac2195e Mon Sep 17 00:00:00 2001 From: Esa Korhonen Date: Tue, 31 Oct 2017 15:16:34 +0200 Subject: [PATCH] MXS-1333: QLAFilter, add option to log execution time Adds an option 'reply_time' to log_data. When enabled, query execution time in milliseconds is logged. Execution time is measured as the time between routeQuery and the first clientReply. --- Documentation/Filters/Query-Log-All-Filter.md | 18 +- server/modules/filter/qlafilter/qlafilter.cc | 246 ++++++++++++++---- 2 files changed, 205 insertions(+), 59 deletions(-) diff --git a/Documentation/Filters/Query-Log-All-Filter.md b/Documentation/Filters/Query-Log-All-Filter.md index 39ebdf401..389bf50a5 100644 --- a/Documentation/Filters/Query-Log-All-Filter.md +++ b/Documentation/Filters/Query-Log-All-Filter.md @@ -116,18 +116,22 @@ Type of data to log in the log files. Parameter value is a comma separated list of the following values. By default the _date_, _user_ and _query_ options are enabled. -|Value | Description | -|--------|---------------------------------------------------| -|service | Log service name | -|session | Log unique session id (ignored for session-files) | -|date | Log timestamp | -|user | Log user and hostname of client | -|query | Log the actual query | +| Value | Description | +| -------- |--------------------------------------------------| +| service | Service name | +| session | Unique session id (ignored for session files) | +| date | Timestamp | +| user | User and hostname of client | +| reply_time | Response time (ms until first reply from server) | +| query | Query | ``` log_data=date, user, query ``` +If *reply_time* is enabled, the log entry is written when the first reply from server is received. +Otherwise, the entry is written when receiving query from client. + ### `flush` Flush log files after every write. The default is false. diff --git a/server/modules/filter/qlafilter/qlafilter.cc b/server/modules/filter/qlafilter/qlafilter.cc index 82dfda6e7..3125b6728 100644 --- a/server/modules/filter/qlafilter/qlafilter.cc +++ b/server/modules/filter/qlafilter/qlafilter.cc @@ -25,6 +25,7 @@ #include +#include #include #include #include @@ -60,6 +61,7 @@ enum log_options LOG_DATA_DATE = (1 << 2), LOG_DATA_USER = (1 << 3), LOG_DATA_QUERY = (1 << 4), + LOG_DATA_REPLY_TIME = (1 << 5), }; /* Default values for logged data */ @@ -71,7 +73,9 @@ static MXS_FILTER_SESSION *newSession(MXS_FILTER *instance, MXS_SESSION *session static void closeSession(MXS_FILTER *instance, MXS_FILTER_SESSION *session); static void freeSession(MXS_FILTER *instance, MXS_FILTER_SESSION *session); static void setDownstream(MXS_FILTER *instance, MXS_FILTER_SESSION *fsession, MXS_DOWNSTREAM *downstream); +static void setUpstream(MXS_FILTER *instance, MXS_FILTER_SESSION *session, MXS_UPSTREAM *upstream); static int routeQuery(MXS_FILTER *instance, MXS_FILTER_SESSION *fsession, GWBUF *queue); +static int clientReply(MXS_FILTER *instance, MXS_FILTER_SESSION *session, GWBUF *queue); static void diagnostic(MXS_FILTER *instance, MXS_FILTER_SESSION *fsession, DCB *dcb); static json_t* diagnostic_json(const MXS_FILTER *instance, const MXS_FILTER_SESSION *fsession); static uint64_t getCapabilities(MXS_FILTER* instance); @@ -108,10 +112,39 @@ typedef struct bool write_warning_given; } QLA_INSTANCE; +/** + * Helper struct for holding data before it's written to file. + */ +struct LOG_EVENT_DATA +{ + bool has_message; // Does message data exist? + GWBUF* query_clone; // Clone of the query buffer. + char query_date[QLA_DATE_BUFFER_SIZE]; // Text representation of date. + timespec begin_time; // Timer value at the moment of receiving query. +}; + +namespace +{ +/** + * Resets event data. Since QLA_SESSION is allocated with calloc, separate initialisation is not needed. + * + * @param event Event to reset + */ +void clear(LOG_EVENT_DATA& event) +{ + event.has_message = false; + gwbuf_free(event.query_clone); + event.query_clone = NULL; + event.query_date[0] = '\0'; + event.begin_time = {0, 0}; +} +} + /* The session structure for this QLA filter. */ typedef struct { int active; + MXS_UPSTREAM up; MXS_DOWNSTREAM down; char *filename; /* The session-specific log file name */ FILE *fp; /* The session-specific log file */ @@ -120,11 +153,12 @@ typedef struct size_t ses_id; /* The session this filter serves */ const char *user; /* The client */ pcre2_match_data* match_data; /* Regex match data */ + LOG_EVENT_DATA event_data; /* Information about the latest event, required if logging execution time. */ } QLA_SESSION; static FILE* open_log_file(uint32_t, QLA_INSTANCE *, const char *); -static int write_log_entry(uint32_t, FILE*, QLA_INSTANCE*, QLA_SESSION*, const char*, - const char*, size_t); +static int write_log_entry(uint32_t, FILE*, QLA_INSTANCE*, QLA_SESSION*, + const char*, const char*, size_t, int); static bool cb_log(const MODULECMD_ARG *argv, json_t** output); static const MXS_ENUM_VALUE option_values[] = @@ -144,11 +178,12 @@ static const MXS_ENUM_VALUE log_type_values[] = static const MXS_ENUM_VALUE log_data_values[] = { - {"service", LOG_DATA_SERVICE}, - {"session", LOG_DATA_SESSION}, - {"date", LOG_DATA_DATE}, - {"user", LOG_DATA_USER}, - {"query", LOG_DATA_QUERY}, + {"service", LOG_DATA_SERVICE}, + {"session", LOG_DATA_SESSION}, + {"date", LOG_DATA_DATE}, + {"user", LOG_DATA_USER}, + {"query", LOG_DATA_QUERY}, + {"reply_time", LOG_DATA_REPLY_TIME}, {NULL} }; @@ -199,9 +234,9 @@ MXS_MODULE* MXS_CREATE_MODULE() closeSession, freeSession, setDownstream, - NULL, // No Upstream requirement + setUpstream, routeQuery, - NULL, // No client reply + clientReply, diagnostic, diagnostic_json, getCapabilities, @@ -483,6 +518,7 @@ closeSession(MXS_FILTER *instance, MXS_FILTER_SESSION *session) { fclose(my_session->fp); } + clear(my_session->event_data); } /** @@ -518,6 +554,65 @@ setDownstream(MXS_FILTER *instance, MXS_FILTER_SESSION *session, MXS_DOWNSTREAM my_session->down = *downstream; } +/** + * Set the upstream filter or router to which queries will be + * passed from this filter. + * + * @param instance The filter instance data + * @param session The filter session + * @param upstream The upstream filter or router. + */ +static void +setUpstream(MXS_FILTER *instance, MXS_FILTER_SESSION *session, MXS_UPSTREAM *upstream) +{ + QLA_SESSION *my_session = (QLA_SESSION *) session; + my_session->up = *upstream; +} + +/** + * Write QLA log entry/entries to disk + * + * @param my_instance Filter instance + * @param my_session Filter session + * @param query Query string, not 0-terminated + * @param querylen Query string length + * @param date_string Date string + * @param elapsed_ms Query execution time, in milliseconds + */ +void write_log_entries(QLA_INSTANCE* my_instance, QLA_SESSION* my_session, + const char* query, int querylen, const char* date_string, int elapsed_ms) +{ + bool write_error = false; + if (my_instance->log_mode_flags & CONFIG_FILE_SESSION) + { + // In this case there is no need to write the session + // number into the files. + uint32_t data_flags = (my_instance->log_file_data_flags & + ~LOG_DATA_SESSION); + if (write_log_entry(data_flags, my_session->fp, my_instance, my_session, + date_string, query, querylen, elapsed_ms) < 0) + { + write_error = true; + } + } + if (my_instance->log_mode_flags & CONFIG_FILE_UNIFIED) + { + uint32_t data_flags = my_instance->log_file_data_flags; + if (write_log_entry(data_flags, my_instance->unified_fp, my_instance, my_session, + date_string, query, querylen, elapsed_ms) < 0) + { + write_error = true; + } + } + if (write_error && !my_instance->write_warning_given) + { + MXS_ERROR("qla-filter '%s': Log file write failed. " + "Suppressing further similar warnings.", + my_instance->name); + my_instance->write_warning_given = true; + } +} + /** * The routeQuery entry point. This is passed the query buffer * to which the filter should be applied. Once applied the @@ -533,56 +628,46 @@ routeQuery(MXS_FILTER *instance, MXS_FILTER_SESSION *session, GWBUF *queue) { QLA_INSTANCE *my_instance = (QLA_INSTANCE *) instance; QLA_SESSION *my_session = (QLA_SESSION *) session; - char *ptr = NULL; - int length = 0; - struct tm t; - struct timeval tv; + char *query = NULL; + int query_len = 0; if (my_session->active && - modutil_extract_SQL(queue, &ptr, &length) && + modutil_extract_SQL(queue, &query, &query_len) && mxs_pcre2_check_match_exclude(my_instance->re_match, my_instance->re_exclude, - my_session->match_data, ptr, length, MXS_MODULE_NAME)) + my_session->match_data, query, query_len, MXS_MODULE_NAME)) { - char buffer[QLA_DATE_BUFFER_SIZE]; - gettimeofday(&tv, NULL); - localtime_r(&tv.tv_sec, &t); - strftime(buffer, sizeof(buffer), "%F %T", &t); - - /** - * Loop over all the possible log file modes and write to - * the enabled files. - */ - - char *sql_string = ptr; - bool write_error = false; - if (my_instance->log_mode_flags & CONFIG_FILE_SESSION) + const uint32_t data_flags = my_instance->log_file_data_flags; + LOG_EVENT_DATA& event = my_session->event_data; + if (data_flags & LOG_DATA_DATE) { - // In this case there is no need to write the session - // number into the files. - uint32_t data_flags = (my_instance->log_file_data_flags & - ~LOG_DATA_SESSION); - - if (write_log_entry(data_flags, my_session->fp, - my_instance, my_session, buffer, sql_string, length) < 0) - { - write_error = true; - } + // Print current date to a buffer. Use the buffer in the event data struct even if execution time + // is not needed. + const time_t utc_seconds = time(NULL); + tm local_time; + localtime_r(&utc_seconds, &local_time); + strftime(event.query_date, QLA_DATE_BUFFER_SIZE, "%F %T", &local_time); } - if (my_instance->log_mode_flags & CONFIG_FILE_UNIFIED) + + if (data_flags & LOG_DATA_REPLY_TIME) { - uint32_t data_flags = my_instance->log_file_data_flags; - if (write_log_entry(data_flags, my_instance->unified_fp, - my_instance, my_session, buffer, sql_string, length) < 0) + // Have to measure reply time from server. Save query data for printing during clientReply. + // If old event data exists, it is erased. This only happens if client sends a query before + // receiving reply to previous query. + if (event.has_message) { - write_error = true; + clear(event); } + clock_gettime(CLOCK_MONOTONIC, &event.begin_time); + if (data_flags & LOG_DATA_QUERY) + { + event.query_clone = gwbuf_clone(queue); + } + event.has_message = true; } - if (write_error && !my_instance->write_warning_given) + else { - MXS_ERROR("qla-filter '%s': Log file write failed. " - "Suppressing further similar warnings.", - my_instance->name); - my_instance->write_warning_given = true; + // If execution times are not logged, write the log entry now. + write_log_entries(my_instance, my_session, query, query_len, event.query_date, -1); } } /* Pass the query downstream */ @@ -590,6 +675,41 @@ routeQuery(MXS_FILTER *instance, MXS_FILTER_SESSION *session, GWBUF *queue) my_session->down.session, queue); } +/** + * The clientReply entry point. Required for measuring and printing query execution time. + * + * @param instance The filter instance data + * @param session The filter session + * @param queue The query data + */ +static int +clientReply(MXS_FILTER *instance, MXS_FILTER_SESSION *session, GWBUF *queue) +{ + QLA_INSTANCE *my_instance = (QLA_INSTANCE *) instance; + QLA_SESSION *my_session = (QLA_SESSION *) session; + LOG_EVENT_DATA& event = my_session->event_data; + if (event.has_message) + { + const uint32_t data_flags = my_instance->log_file_data_flags; + ss_dassert(data_flags & LOG_DATA_REPLY_TIME); + char* query = NULL; + int query_len = 0; + if (data_flags & LOG_DATA_QUERY) + { + modutil_extract_SQL(event.query_clone, &query, &query_len); + } + timespec now; + clock_gettime(CLOCK_MONOTONIC, &now); // Gives time in seconds + nanoseconds + // Calculate elapsed time in milliseconds. + double elapsed_ms = 1E3 * (now.tv_sec - event.begin_time.tv_sec) + + (now.tv_nsec - event.begin_time.tv_nsec) / (double)1E6; + write_log_entries(my_instance, my_session, query, query_len, event.query_date, + std::floor(elapsed_ms + 0.5)); + clear(event); + } + return my_session->up.clientReply(my_session->up.instance, my_session->up.session, queue); +} + /** * Diagnostics routine * @@ -731,9 +851,9 @@ static FILE* open_log_file(uint32_t data_flags, QLA_INSTANCE *instance, const ch const char DATE[] = "Date,"; const char USERHOST[] = "User@Host,"; const char QUERY[] = "Query,"; - + const char REPLY_TIME[] = "Reply_time,"; const int headerlen = sizeof(SERVICE) + sizeof(SERVICE) + sizeof(DATE) + - sizeof(USERHOST) + sizeof(QUERY); + sizeof(USERHOST) + sizeof(QUERY) + sizeof(REPLY_TIME); char print_str[headerlen]; memset(print_str, '\0', headerlen); @@ -759,6 +879,11 @@ static FILE* open_log_file(uint32_t data_flags, QLA_INSTANCE *instance, const ch strcat(current_pos, USERHOST); current_pos += sizeof(USERHOST) - 1; } + if (instance->log_file_data_flags & LOG_DATA_REPLY_TIME) + { + strcat(current_pos, REPLY_TIME); + current_pos += sizeof(REPLY_TIME) - 1; + } if (instance->log_file_data_flags & LOG_DATA_QUERY) { strcat(current_pos, QUERY); @@ -800,11 +925,12 @@ static FILE* open_log_file(uint32_t data_flags, QLA_INSTANCE *instance, const ch * @param time_string Date entry * @param sql_string SQL-query, *not* NULL terminated * @param sql_str_len Length of SQL-string + * @param elapsed_ms Query execution time, in milliseconds * @return The number of characters written, or a negative value on failure */ static int write_log_entry(uint32_t data_flags, FILE *logfile, QLA_INSTANCE *instance, QLA_SESSION *session, const char *time_string, const char *sql_string, - size_t sql_str_len) + size_t sql_str_len, int elapsed_ms) { ss_dassert(logfile != NULL); size_t print_len = 0; @@ -816,13 +942,14 @@ static int write_log_entry(uint32_t data_flags, FILE *logfile, QLA_INSTANCE *ins */ // The numbers have some extra for delimiters. + const size_t integer_chars = 20; // Enough space for any integer type if (data_flags & LOG_DATA_SERVICE) { print_len += strlen(session->service) + 1; } if (data_flags & LOG_DATA_SESSION) { - print_len += 20; // To print a 64bit integer + print_len += integer_chars; } if (data_flags & LOG_DATA_DATE) { @@ -832,6 +959,10 @@ static int write_log_entry(uint32_t data_flags, FILE *logfile, QLA_INSTANCE *ins { print_len += strlen(session->user) + strlen(session->remote) + 2; } + if (data_flags & LOG_DATA_REPLY_TIME) + { + print_len += integer_chars; + } if (data_flags & LOG_DATA_QUERY) { print_len += sql_str_len + 1; // Can't use strlen, not null-terminated @@ -898,6 +1029,17 @@ static int write_log_entry(uint32_t data_flags, FILE *logfile, QLA_INSTANCE *ins current_pos += rval; } } + if (!error && (data_flags & LOG_DATA_REPLY_TIME)) + { + if ((rval = sprintf(current_pos, "%d,", elapsed_ms)) < 0) + { + error = true; + } + else + { + current_pos += rval; + } + } if (!error && (data_flags & LOG_DATA_QUERY)) { strncat(current_pos, sql_string, sql_str_len); // non-null-terminated string