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

Fix to bug #557, http://bugs.mariadb.com/show_bug.cgi?id=557

Browse Source 
query_classifier.cc: added function for printing combined query type from a bit field.
query_classifier.h: identify query types SHOW DATABASE, and SHOW TABLES to make log entries more understandable.
mysql_common.c: moved some trace log commands to debug log.
readwritesplit.c: moved some trace logs to debug log, added trace log commands to gather routing, query type and session information to one log entry.
skygw_debug.h: added string macros for several query and hint types.
This commit is contained in:
VilhoRaatikka 2014-09-30 16:31:30 +03:00
parent 24f3a8f7fd
commit ca7ae0bb64
5 changed files with 222 additions and 57 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

58
query_classifier/query_classifier.cc
View File

@ -639,7 +639,17 @@ static skygw_query_type_t resolve_query_type(
type |= QUERY_TYPE_PREPARE_NAMED_STMT;
goto return_qtype;
break;
case SQLCOM_SHOW_DATABASES:
type |= QUERY_TYPE_SHOW_DATABASES;
goto return_qtype;
break;
case SQLCOM_SHOW_TABLES:
type |= QUERY_TYPE_SHOW_TABLES;
goto return_qtype;
break;
default:
break;
}
@ -1375,3 +1385,49 @@ static void parsing_info_set_plain_str(
pi->pi_query_plain_str = str;
}
/**
* Generate a string of query type value.
* Caller must free the memory of the resulting string.
*
* @param qtype Query type value, combination of values listed in
* query_classifier.h
*
* @return string representing the query type value
*/
char* skygw_get_qtype_str(
skygw_query_type_t qtype)
{
int t1 = (int)qtype;
int t2 = 1;
skygw_query_type_t t = QUERY_TYPE_UNKNOWN;
char* qtype_str = NULL;
/**
* Test values (bits) and clear matching bits from t1 one by one until
* t1 is completely cleared.
*/
while (t1 != 0)
{
if (t1&t2)
{
t = (skygw_query_type_t)t2;
if (qtype_str == NULL)
{
qtype_str = strdup(STRQTYPE(t));
}
else
{
size_t len = strlen(STRQTYPE(t));
/** reallocate space for delimiter, new string and termination */
qtype_str = (char *)realloc(qtype_str, strlen(qtype_str)+1+len+1);
snprintf(qtype_str+strlen(qtype_str), 1+len+1, "|%s", STRQTYPE(t));
}
/** Remove found value from t1 */
t1 &= ~t2;
}
t2 <<= 1;
}
return qtype_str;
}

5
query_classifier/query_classifier.h
View File

@ -54,7 +54,9 @@ typedef enum {
QUERY_TYPE_PREPARE_STMT = 0x020000, /*< Prepared stmt with id provided by server:all */
QUERY_TYPE_EXEC_STMT = 0x040000, /*< Execute prepared statement:master or any */
QUERY_TYPE_CREATE_TMP_TABLE = 0x080000, /*< Create temporary table:master (could be all) */
QUERY_TYPE_READ_TMP_TABLE = 0x100000 /*< Read temporary table:master (could be any) */
QUERY_TYPE_READ_TMP_TABLE = 0x100000, /*< Read temporary table:master (could be any) */
QUERY_TYPE_SHOW_DATABASES = 0x200000, /*< Show list of databases */
QUERY_TYPE_SHOW_TABLES = 0x400000 /*< Show list of tables */
} skygw_query_type_t;
@ -91,6 +93,7 @@ bool parse_query (GWBUF* querybuf);
parsing_info_t* parsing_info_init(void (*donefun)(void *));
void parsing_info_done(void* ptr);
bool query_is_parsed(GWBUF* buf);
char* skygw_get_qtype_str(skygw_query_type_t qtype);
EXTERN_C_BLOCK_END

16
server/modules/protocol/mysql_common.c
View File

@ -1653,9 +1653,11 @@ void protocol_archive_srv_command(
s1 = &p->protocol_command;
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Move command %s from fd %d to command history.",
LOGIF(LD, (skygw_log_write(
LOGFILE_DEBUG,
"%lu [protocol_archive_srv_command] Move command %s from fd %d "
"to command history.",
pthread_self(),
STRPACKETTYPE(s1->scom_cmd),
p->owner_dcb->fd)));
@ -1727,8 +1729,8 @@ void protocol_add_srv_command(
p->protocol_command.scom_next = server_command_init(NULL, cmd);
}
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
LOGIF(LD, (skygw_log_write(
LOGFILE_DEBUG,
"Added command %s to fd %d.",
STRPACKETTYPE(cmd),
p->owner_dcb->fd)));
@ -1738,8 +1740,8 @@ void protocol_add_srv_command(
while (c != NULL && c->scom_cmd != MYSQL_COM_UNDEFINED)
{
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
LOGIF(LD, (skygw_log_write(
LOGFILE_DEBUG,
"fd %d : %d %s",
p->owner_dcb->fd,
c->scom_cmd,

162
server/modules/routing/readwritesplit/readwritesplit.c
View File

@ -1282,9 +1282,10 @@ static route_target_t get_route_target (
if (hint->type == HINT_ROUTE_TO_MASTER)
{
target = TARGET_MASTER; /*< override */
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Hint: route to master.")));
LOGIF(LD, (skygw_log_write(
LOGFILE_DEBUG,
"%lu [get_route_target] Hint: route to master.",
pthread_self())));
break;
}
else if (hint->type == HINT_ROUTE_TO_NAMED_SERVER)
@ -1294,9 +1295,11 @@ static route_target_t get_route_target (
* found, the oroginal target is chosen.
*/
target |= TARGET_NAMED_SERVER;
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Hint: route to named server : ")));
LOGIF(LD, (skygw_log_write(
LOGFILE_DEBUG,
"%lu [get_route_target] Hint: route to "
"named server : ",
pthread_self())));
}
else if (hint->type == HINT_ROUTE_TO_UPTODATE_SERVER)
{
@ -1334,9 +1337,11 @@ static route_target_t get_route_target (
else if (hint->type == HINT_ROUTE_TO_SLAVE)
{
target = TARGET_SLAVE;
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Hint: route to slave.")));
LOGIF(LD, (skygw_log_write(
LOGFILE_DEBUG,
"%lu [get_route_target] Hint: route to "
"slave.",
pthread_self())));
}
hint = hint->next;
} /*< while (hint != NULL) */
@ -1653,7 +1658,6 @@ static int routeQuery(
GWBUF* querybuf)
{
skygw_query_type_t qtype = QUERY_TYPE_UNKNOWN;
char* querystr = NULL;
mysql_server_cmd_t packet_type;
uint8_t* packet;
int ret = 0;
@ -1793,8 +1797,33 @@ static int routeQuery(
{
router_cli_ses->rses_autocommit_enabled = true;
router_cli_ses->rses_transaction_active = false;
}
}
if (LOG_IS_ENABLED(LOGFILE_TRACE))
{
uint8_t* packet = GWBUF_DATA(querybuf);
unsigned char ptype = packet[4];
size_t len = MIN(GWBUF_LENGTH(querybuf),
MYSQL_GET_PACKET_LEN((unsigned char *)querybuf->start)-1);
char* data = (char*)&packet[5];
char* contentstr = strndup(data, len);
char* qtypestr = skygw_get_qtype_str(qtype);
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"> Autocommit: %s, trx is %s, cmd: %s, type: %s, "
"stmt: %s%s %s",
(router_cli_ses->rses_autocommit_enabled ? "[enabled]" : "[disabled]"),
(router_cli_ses->rses_transaction_active ? "[open]" : "[not open]"),
STRPACKETTYPE(ptype),
(qtypestr==NULL ? "N/A" : qtypestr),
contentstr,
(querybuf->hint == NULL ? "" : ", Hint:"),
(querybuf->hint == NULL ? "" : STRHINTTYPE(querybuf->hint->type)))));
free(contentstr);
free(qtypestr);
}
/**
* Find out where to route the query. Result may not be clear; it is
* possible to have a hint for routing to a named server which can
@ -1911,6 +1940,27 @@ static int routeQuery(
btype,
named_server,
rlag_max);
if (!succp)
{
if (TARGET_IS_NAMED_SERVER(route_target))
{
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Was supposed to route to named server "
"%s but couldn't find the server in a "
"suitable state.",
named_server)));
}
else if (TARGET_IS_RLAG_MAX(route_target))
{
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Was supposed to route to server with "
"replication lag at most %d but couldn't "
"find such a slave.",
rlag_max)));
}
}
}
if (!succp && TARGET_IS_SLAVE(route_target))
@ -1930,9 +1980,16 @@ static int routeQuery(
NULL,
rlag_max);
if (succp)
{
{
atomic_add(&inst->stats.n_slave, 1);
}
else
{
LOGIF(LT, (skygw_log_write(LOGFILE_TRACE,
"Was supposed to route to slave"
"but finding suitable one "
"failed.")));
}
}
if (!succp && TARGET_IS_MASTER(route_target))
@ -1944,6 +2001,16 @@ static int routeQuery(
BE_MASTER,
NULL,
MAX_RLAG_UNDEFINED);
if (!succp)
{
LOGIF(LT, (skygw_log_write(LOGFILE_TRACE,
"Was supposed to "
"route to master "
"but couldn't find "
"master in a "
"suitable state "
"failed.")));
}
}
else
{
@ -1951,9 +2018,7 @@ static int routeQuery(
}
atomic_add(&inst->stats.n_master, 1);
target_dcb = master_dcb;
}
ss_dassert(succp);
}
if (succp) /*< Have DCB of the target backend */
{
@ -1962,6 +2027,14 @@ static int routeQuery(
bref = get_bref_from_dcb(router_cli_ses, target_dcb);
scur = &bref->bref_sescmd_cur;
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Route query to %s\t%s:%d <",
(SERVER_IS_MASTER(bref->bref_backend->backend_server) ?
"master" : "slave"),
bref->bref_backend->backend_server->name,
bref->bref_backend->backend_server->port)));
/**
* Store current stmt if execution of previous session command
* haven't completed yet. Note that according to MySQL protocol
@ -1993,8 +2066,7 @@ static int routeQuery(
{
LOGIF(LE, (skygw_log_write_flush(
LOGFILE_ERROR,
"Error : Routing query \"%s\" failed.",
querystr)));
"Error : Routing query failed.")));
}
}
rses_end_locked_router_action(router_cli_ses);
@ -3441,12 +3513,6 @@ static bool execute_sescmd_in_backend(
sescmd_cursor_clone_querybuf(scur));
break;
}
LOGIF(LT, (skygw_log_write_flush(
LOGFILE_TRACE,
"%lu [execute_sescmd_in_backend] Routed %s cmd %p.",
pthread_self(),
STRPACKETTYPE(scur->scmd_cur_cmd->my_sescmd_packet_type),
scur->scmd_cur_cmd)));
if (rc == 1)
{
@ -3573,8 +3639,8 @@ static void tracelog_routed_query(
querystr = (char *)malloc(len);
memcpy(querystr, startpos, len-1);
querystr[len-1] = '\0';
LOGIF(LT, (skygw_log_write_flush(
LOGFILE_TRACE,
LOGIF(LD, (skygw_log_write_flush(
LOGFILE_DEBUG,
"%lu [%s] %d bytes long buf, \"%s\" -> %s:%d %s dcb %p",
pthread_self(),
funcname,
@ -3595,8 +3661,8 @@ static void tracelog_routed_query(
querystr = (char *)malloc(len);
memcpy(querystr, startpos, len-1);
querystr[len-1] = '\0';
LOGIF(LT, (skygw_log_write_flush(
LOGFILE_TRACE,
LOGIF(LD, (skygw_log_write_flush(
LOGFILE_DEBUG,
"%lu [%s] %d bytes long buf, \"%s\" -> %s:%d %s dcb %p",
pthread_self(),
funcname,
@ -3663,10 +3729,7 @@ static bool route_session_write(
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Session write, query type\t%s, packet type %s, "
"routing to all servers.",
STRQTYPE(qtype),
STRPACKETTYPE(packet_type))));
"Session write, routing to all servers.")));
backend_ref = router_cli_ses->rses_backend_ref;
@ -3693,7 +3756,19 @@ static bool route_session_write(
for (i=0; i<router_cli_ses->rses_nbackends; i++)
{
DCB* dcb = backend_ref[i].bref_dcb;
DCB* dcb = backend_ref[i].bref_dcb;
if (LOG_IS_ENABLED(LOGFILE_TRACE))
{
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Route query to %s\t%s:%d%s",
(SERVER_IS_MASTER(backend_ref[i].bref_backend->backend_server) ?
"master" : "slave"),
backend_ref[i].bref_backend->backend_server->name,
backend_ref[i].bref_backend->backend_server->port,
(i+1==router_cli_ses->rses_nbackends ? " <" : ""))));
}
if (BREF_IS_IN_USE((&backend_ref[i])))
{
@ -3703,14 +3778,7 @@ static bool route_session_write(
{
succp = false;
}
else if (LOG_IS_ENABLED(LOGFILE_TRACE))
{
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Wrote to %s:%d",
backend_ref[i].bref_backend->backend_server->name,
backend_ref[i].bref_backend->backend_server->port)));
}
}
}
rses_end_locked_router_action(router_cli_ses);
@ -3740,6 +3808,18 @@ static bool route_session_write(
{
sescmd_cursor_t* scur;
if (LOG_IS_ENABLED(LOGFILE_TRACE))
{
LOGIF(LT, (skygw_log_write(
LOGFILE_TRACE,
"Route query to %s\t%s:%d%s",
(SERVER_IS_MASTER(backend_ref[i].bref_backend->backend_server) ?
"master" : "slave"),
backend_ref[i].bref_backend->backend_server->name,
backend_ref[i].bref_backend->backend_server->port,
(i+1==router_cli_ses->rses_nbackends ? " <" : ""))));
}
scur = backend_ref_get_sescmd_cursor(&backend_ref[i]);
/**
@ -3747,7 +3827,7 @@ static bool route_session_write(
*/
bref_set_state(get_bref_from_dcb(router_cli_ses,
backend_ref[i].bref_dcb),
BREF_WAITING_RESULT);
BREF_WAITING_RESULT);
/**
* Start execution if cursor is not already executing.
* Otherwise, cursor will execute pending commands

38
utils/skygw_debug.h
View File

@ -129,13 +129,29 @@ typedef enum skygw_chk_t {
# define STRBOOL(b) ((b) ? "true" : "false")
# define STRQTYPE(t) ((t) == QUERY_TYPE_WRITE ? "QUERY_TYPE_WRITE" : \
((t) == QUERY_TYPE_READ ? "QUERY_TYPE_READ" : \
((t) == QUERY_TYPE_SESSION_WRITE ? "QUERY_TYPE_SESSION_WRITE" : \
((t) == QUERY_TYPE_UNKNOWN ? "QUERY_TYPE_UNKNOWN" : \
((t) == QUERY_TYPE_LOCAL_READ ? "QUERY_TYPE_LOCAL_READ" : \
((t) == QUERY_TYPE_EXEC_STMT ? "QUERY_TYPE_EXEC_STMT" : \
"Unknown query type"))))))
# define STRQTYPE(t) ((t) == QUERY_TYPE_WRITE ? "QUERY_TYPE_WRITE" : \
((t) == QUERY_TYPE_READ ? "QUERY_TYPE_READ" : \
((t) == QUERY_TYPE_SESSION_WRITE ? "QUERY_TYPE_SESSION_WRITE" : \
((t) == QUERY_TYPE_UNKNOWN ? "QUERY_TYPE_UNKNOWN" : \
((t) == QUERY_TYPE_LOCAL_READ ? "QUERY_TYPE_LOCAL_READ" : \
((t) == QUERY_TYPE_MASTER_READ ? "QUERY_TYPE_MASTER_READ" : \
((t) == QUERY_TYPE_USERVAR_READ ? "QUERY_TYPE_USERVAR_READ" : \
((t) == QUERY_TYPE_SYSVAR_READ ? "QUERY_TYPE_SYSVAR_READ" : \
((t) == QUERY_TYPE_GSYSVAR_READ ? "QUERY_TYPE_GSYSVAR_READ" : \
((t) == QUERY_TYPE_GSYSVAR_WRITE ? "QUERY_TYPE_GSYSVAR_WRITE" : \
((t) == QUERY_TYPE_BEGIN_TRX ? "QUERY_TYPE_BEGIN_TRX" : \
((t) == QUERY_TYPE_ENABLE_AUTOCOMMIT ? "QUERY_TYPE_ENABLE_AUTOCOMMIT" : \
((t) == QUERY_TYPE_DISABLE_AUTOCOMMIT ? "QUERY_TYPE_DISABLE_AUTOCOMMIT" : \
((t) == QUERY_TYPE_ROLLBACK ? "QUERY_TYPE_ROLLBACK" : \
((t) == QUERY_TYPE_COMMIT ? "QUERY_TYPE_COMMIT" : \
((t) == QUERY_TYPE_PREPARE_NAMED_STMT ? "QUERY_TYPE_PREPARE_NAMED_STMT" : \
((t) == QUERY_TYPE_PREPARE_STMT ? "QUERY_TYPE_PREPARE_STMT" : \
((t) == QUERY_TYPE_EXEC_STMT ? "QUERY_TYPE_EXEC_STMT" : \
((t) == QUERY_TYPE_CREATE_TMP_TABLE ? "QUERY_TYPE_CREATE_TMP_TABLE" : \
((t) == QUERY_TYPE_READ_TMP_TABLE ? "QUERY_TYPE_READ_TMP_TABLE" : \
((t) == QUERY_TYPE_SHOW_DATABASES ? "QUERY_TYPE_SHOW_DATABASES" : \
((t) == QUERY_TYPE_SHOW_TABLES ? "QUERY_TYPE_SHOW_TABLES" : \
"Unknown query type"))))))))))))))))))))))
#define STRLOGID(i) ((i) == LOGFILE_TRACE ? "LOGFILE_TRACE" : \
((i) == LOGFILE_MESSAGE ? "LOGFILE_MESSAGE" : \
@ -247,6 +263,14 @@ typedef enum skygw_chk_t {
(SERVER_IS_RELAY_SERVER(s) ? "RUNNING RELAY" : \
(SERVER_IS_RUNNING(s) ? "RUNNING (only)" : "NO STATUS")))))))
#define STRHINTTYPE(t) (t == HINT_ROUTE_TO_MASTER ? "HINT_ROUTE_TO_MASTER" : \
((t) == HINT_ROUTE_TO_SLAVE ? "HINT_ROUTE_TO_SLAVE" : \
((t) == HINT_ROUTE_TO_NAMED_SERVER ? "HINT_ROUTE_TO_NAMED_SERVER" : \
((t) == HINT_ROUTE_TO_UPTODATE_SERVER ? "HINT_ROUTE_TO_UPTODATE_SERVER" : \
((t) == HINT_ROUTE_TO_ALL ? "HINT_ROUTE_TO_ALL" : \
((t) == HINT_PARAMETER ? "HINT_PARAMETER" : "UNKNOWN HINT TYPE"))))))
#define CHK_MLIST(l) { \
ss_info_dassert((l->mlist_chk_top == CHK_NUM_MLIST && \
l->mlist_chk_tail == CHK_NUM_MLIST), \