hcq/MaxScale
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

MXS-1333: QLAFilter, add option to log execution time

Browse Source 
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.
This commit is contained in:
Esa Korhonen
2017-10-31 15:16:34 +02:00
parent fca11f992a
commit 032b2f3846
2 changed files with 205 additions and 59 deletions
Download Patch File Download Diff File Expand all files Collapse all files

18
Documentation/Filters/Query-Log-All-Filter.md
View File

@ -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.

234
server/modules/filter/qlafilter/qlafilter.cc
View File

@ -25,6 +25,7 @@
#include <maxscale/cppdefs.hh>
#include <cmath>
#include <errno.h>
#include <fcntl.h>
#include <time.h>
@ -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[] =
@ -149,6 +183,7 @@ static const MXS_ENUM_VALUE log_data_values[] =
{"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);
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)
{
// 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);
}
/**
* 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)
if (data_flags & LOG_DATA_REPLY_TIME)
{
// 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)
// 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);
}
}
if (my_instance->log_mode_flags & CONFIG_FILE_UNIFIED)
clock_gettime(CLOCK_MONOTONIC, &event.begin_time);
if (data_flags & LOG_DATA_QUERY)
{
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)
{
write_error = true;
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