From 0831740e457f1963c53f040365bffffcaeb248b4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Sun, 14 Jul 2019 18:52:19 +1000 Subject: [PATCH 1/2] Several enhancements on Query logger Enhancements: - added metrics rows_affected and rows_sent - added global variable mysql-eventslog_default_log : if 1 , logging is enabled for every query unless explicitly disabled in mysql_query_rules.log . Default is 0 - added global variable mysql-eventslog_format : default is 1 (legacy format). A value of 2 enables logging in JSON format. Issue #871 Changing value at runtime causes the current file to be closed and a new one created - fixed logging for prepared statements: till 2.0.5 only some percentage of prepared statements was correctly logged Extended tables stats_mysql_query_digest and stats_mysql_query_digest_reset to also include sum_rows_affected and sum_rows_sent Extended `eventslog_reader_sample.cpp` to support the new enhancements --- include/MySQL_Logger.hpp | 10 +- include/MySQL_Protocol.h | 2 +- include/MySQL_Session.h | 12 ++- include/MySQL_Thread.h | 2 + include/proxysql_structs.h | 10 +- lib/MySQL_Logger.cpp | 171 ++++++++++++++++++++++++++++-- lib/MySQL_Protocol.cpp | 6 +- lib/MySQL_Session.cpp | 91 +++++++++++++--- lib/MySQL_Thread.cpp | 41 +++++++ lib/ProxySQL_Admin.cpp | 40 +++---- lib/Query_Processor.cpp | 38 +++++-- src/main.cpp | 1 + tools/eventslog_reader_sample.cpp | 51 ++++++++- 13 files changed, 414 insertions(+), 61 deletions(-) diff --git a/include/MySQL_Logger.hpp b/include/MySQL_Logger.hpp index 91a017c006..685a00755e 100644 --- a/include/MySQL_Logger.hpp +++ b/include/MySQL_Logger.hpp @@ -26,14 +26,21 @@ class MySQL_Event { enum log_event_type et; uint64_t hid; char *extra_info; + bool have_affected_rows; + bool have_rows_sent; + uint64_t affected_rows; + uint64_t rows_sent; public: MySQL_Event(log_event_type _et, uint32_t _thread_id, char * _username, char * _schemaname , uint64_t _start_time , uint64_t _end_time , uint64_t _query_digest, char *_client, size_t _client_len); uint64_t write(std::fstream *f, MySQL_Session *sess); - uint64_t write_query(std::fstream *f); + uint64_t write_query_format_1(std::fstream *f); + uint64_t write_query_format_2_json(std::fstream *f); void write_auth(std::fstream *f, MySQL_Session *sess); void set_query(const char *ptr, int len); void set_server(int _hid, const char *ptr, int len); void set_extra_info(char *); + void set_affected_rows(uint64_t ar); + void set_rows_sent(uint64_t rs); }; class MySQL_Logger { @@ -70,6 +77,7 @@ class MySQL_Logger { public: MySQL_Logger(); ~MySQL_Logger(); + void print_version(); void flush_log(); void events_flush_log_unlocked(); void audit_flush_log_unlocked(); diff --git a/include/MySQL_Protocol.h b/include/MySQL_Protocol.h index 63d4d80be5..dae46f8ea2 100644 --- a/include/MySQL_Protocol.h +++ b/include/MySQL_Protocol.h @@ -18,7 +18,7 @@ class MySQL_ResultSet { MYSQL *mysql; MYSQL_RES *result; unsigned int num_fields; - unsigned int num_rows; + unsigned long long num_rows; unsigned long long resultset_size; PtrSizeArray PSarrayOUT; //PtrSizeArray *PSarrayOUT; diff --git a/include/MySQL_Session.h b/include/MySQL_Session.h index 199913967f..ac370cbe49 100644 --- a/include/MySQL_Session.h +++ b/include/MySQL_Session.h @@ -48,6 +48,9 @@ class Query_Info { enum MYSQL_COM_QUERY_command MyComQueryCmd; bool bool_is_select_NOT_for_update; bool bool_is_select_NOT_for_update_computed; + bool have_affected_rows; + uint64_t affected_rows; + uint64_t rows_sent; Query_Info(); ~Query_Info(); @@ -95,6 +98,7 @@ class MySQL_Session bool handler_CommitRollback(PtrSize_t *); bool handler_SetAutocommit(PtrSize_t *); void RequestEnd(MySQL_Data_Stream *); + void LogQuery(MySQL_Data_Stream *); void handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY___create_mirror_session(); int handler_again___status_PINGING_SERVER(); @@ -123,10 +127,6 @@ class MySQL_Session void reset(); void add_ldap_comment_to_pkt(PtrSize_t *); - //this pointer is always initialized inside handler(). - // it is an attempt to start simplifying the complexing of handler() - PtrSize_t *pktH; - public: void * operator new(size_t); @@ -151,6 +151,10 @@ class MySQL_Session MySQL_Data_Stream *server_myds; char * default_schema; + //this pointer is always initialized inside handler(). + // it is an attempt to start simplifying the complexing of handler() + PtrSize_t *pktH; + uint32_t thread_session_id; unsigned long long last_insert_id; int last_HG_affected_rows; diff --git a/include/MySQL_Thread.h b/include/MySQL_Thread.h index 39b38c2ca8..b0a7d7ca46 100644 --- a/include/MySQL_Thread.h +++ b/include/MySQL_Thread.h @@ -443,6 +443,8 @@ class MySQL_Threads_Handler int connpoll_reset_queue_length; char *eventslog_filename; int eventslog_filesize; + int eventslog_default_log; + int eventslog_format; char *auditlog_filename; int auditlog_filesize; // SSL related, proxy to server diff --git a/include/proxysql_structs.h b/include/proxysql_structs.h index f9a04fb7ec..8e7ec0733c 100644 --- a/include/proxysql_structs.h +++ b/include/proxysql_structs.h @@ -11,7 +11,7 @@ #define PROXYSQL_ENUMS enum log_event_type { - PROXYSQL_QUERY, + PROXYSQL_COM_QUERY, PROXYSQL_MYSQL_AUTH_OK, PROXYSQL_MYSQL_AUTH_ERR, PROXYSQL_MYSQL_AUTH_CLOSE, @@ -26,7 +26,9 @@ enum log_event_type { PROXYSQL_SQLITE_AUTH_OK, PROXYSQL_SQLITE_AUTH_ERR, PROXYSQL_SQLITE_AUTH_CLOSE, - PROXYSQL_SQLITE_AUTH_QUIT + PROXYSQL_SQLITE_AUTH_QUIT, + PROXYSQL_COM_STMT_EXECUTE, + PROXYSQL_COM_STMT_PREPARE }; enum cred_username_type { USERNAME_BACKEND, USERNAME_FRONTEND }; @@ -685,6 +687,8 @@ __thread char * mysql_thread___ssl_p2s_cipher; /* variables used by events log */ __thread char * mysql_thread___eventslog_filename; __thread int mysql_thread___eventslog_filesize; +__thread int mysql_thread___eventslog_default_log; +__thread int mysql_thread___eventslog_format; /* variables used by audit log */ __thread char * mysql_thread___auditlog_filename; @@ -814,6 +818,8 @@ extern __thread char * mysql_thread___ssl_p2s_cipher; /* variables used by events log */ extern __thread char * mysql_thread___eventslog_filename; extern __thread int mysql_thread___eventslog_filesize; +extern __thread int mysql_thread___eventslog_default_log; +extern __thread int mysql_thread___eventslog_format; /* variables used by audit log */ extern __thread char * mysql_thread___auditlog_filename; diff --git a/lib/MySQL_Logger.cpp b/lib/MySQL_Logger.cpp index 8239061caa..b2556c35ab 100644 --- a/lib/MySQL_Logger.cpp +++ b/lib/MySQL_Logger.cpp @@ -7,6 +7,14 @@ #include "../deps/json/json.hpp" using json = nlohmann::json; +#ifdef DEBUG +#define DEB "_DEBUG" +#else +#define DEB "" +#endif /* DEBUG */ +#define PROXYSQL_MYSQL_LOGGER_VERSION "2.0.0714" DEB + + static uint8_t mysql_encode_length(uint64_t len, unsigned char *hd) { if (len < 251) return 1; if (len < 65536) { if (hd) { *hd=0xfc; }; return 3; } @@ -39,6 +47,20 @@ MySQL_Event::MySQL_Event (log_event_type _et, uint32_t _thread_id, char * _usern hid=UINT64_MAX; server=NULL; extra_info = NULL; + have_affected_rows=false; + affected_rows=0; + have_rows_sent=false; + rows_sent=0; +} + +void MySQL_Event::set_affected_rows(uint64_t ar) { + have_affected_rows=true; + affected_rows=ar; +} + +void MySQL_Event::set_rows_sent(uint64_t rs) { + have_rows_sent=true; + rows_sent=rs; } void MySQL_Event::set_extra_info(char *_err) { @@ -59,8 +81,14 @@ void MySQL_Event::set_server(int _hid, const char *ptr, int len) { uint64_t MySQL_Event::write(std::fstream *f, MySQL_Session *sess) { uint64_t total_bytes=0; switch (et) { - case PROXYSQL_QUERY: - total_bytes=write_query(f); + case PROXYSQL_COM_QUERY: + case PROXYSQL_COM_STMT_EXECUTE: + case PROXYSQL_COM_STMT_PREPARE: + if (mysql_thread___eventslog_format==1) { // format 1 , binary + total_bytes=write_query_format_1(f); + } else { // format 2 , json + total_bytes=write_query_format_2_json(f); + } break; case PROXYSQL_MYSQL_AUTH_OK: case PROXYSQL_MYSQL_AUTH_ERR: @@ -200,7 +228,7 @@ void MySQL_Event::write_auth(std::fstream *f, MySQL_Session *sess) { *f << j.dump() << std::endl; } -uint64_t MySQL_Event::write_query(std::fstream *f) { +uint64_t MySQL_Event::write_query_format_1(std::fstream *f) { uint64_t total_bytes=0; total_bytes+=1; // et total_bytes+=mysql_encode_length(thread_id, NULL); @@ -218,6 +246,9 @@ uint64_t MySQL_Event::write_query(std::fstream *f) { total_bytes+=mysql_encode_length(start_time,NULL); total_bytes+=mysql_encode_length(end_time,NULL); + total_bytes+=mysql_encode_length(affected_rows,NULL); + total_bytes+=mysql_encode_length(rows_sent,NULL); + total_bytes+=mysql_encode_length(query_digest,NULL); total_bytes+=mysql_encode_length(query_len,NULL)+query_len; @@ -267,6 +298,14 @@ uint64_t MySQL_Event::write_query(std::fstream *f) { write_encoded_length(buf,end_time,len,buf[0]); f->write((char *)buf,len); + len=mysql_encode_length(affected_rows,buf); + write_encoded_length(buf,affected_rows,len,buf[0]); + f->write((char *)buf,len); + + len=mysql_encode_length(rows_sent,buf); + write_encoded_length(buf,rows_sent,len,buf[0]); + f->write((char *)buf,len); + len=mysql_encode_length(query_digest,buf); write_encoded_length(buf,query_digest,len,buf[0]); f->write((char *)buf,len); @@ -281,6 +320,79 @@ uint64_t MySQL_Event::write_query(std::fstream *f) { return total_bytes; } +uint64_t MySQL_Event::write_query_format_2_json(std::fstream *f) { + json j; + uint64_t total_bytes=0; + if (hid!=UINT64_MAX) { + j["hostgroup_id"] = hid; + } else { + j["hostgroup_id"] = -1; + } + j["thread_id"] = thread_id; + switch (et) { + case PROXYSQL_COM_STMT_EXECUTE: + j["event"]="COM_STMT_EXECUTE"; + break; + case PROXYSQL_COM_STMT_PREPARE: + j["event"]="COM_STMT_PREPARE"; + break; + default: + j["event"]="COM_QUERY"; + break; + } + if (username) { + j["username"] = username; + } else { + j["username"] = ""; + } + if (schemaname) { + j["schemaname"] = schemaname; + } else { + j["schemaname"] = ""; + } + if (client) { + j["client"] = client; + } else { + j["client"] = ""; + } + if (hid!=UINT64_MAX) { + if (server) { + j["server"] = server; + } + } + j["rows_affected"] = affected_rows; + j["rows_sent"] = rows_sent; + j["query"] = string(query_ptr,query_len); + j["starttime_timestamp_us"] = start_time; + { + time_t timer=start_time/1000/1000; + struct tm* tm_info; + tm_info = localtime(&timer); + char buffer1[64]; + char buffer2[64]; + strftime(buffer1, 32, "%Y-%m-%d %H:%M:%S", tm_info); + sprintf(buffer2,"%s.%06u", buffer1, (unsigned)(start_time%1000000)); + j["starttime"] = buffer2; + } + j["endtime_timestamp_us"] = end_time; + { + time_t timer=end_time/1000/1000; + struct tm* tm_info; + tm_info = localtime(&timer); + char buffer1[64]; + char buffer2[64]; + strftime(buffer1, 32, "%Y-%m-%d %H:%M:%S", tm_info); + sprintf(buffer2,"%s.%06u", buffer1, (unsigned)(end_time%1000000)); + j["endtime"] = buffer2; + } + j["duration_us"] = end_time-start_time; + char digest_hex[20]; + sprintf(digest_hex,"0x%016llX", (long long unsigned int)query_digest); + j["digest"] = digest_hex; + *f << j.dump() << std::endl; + return total_bytes; // always 0 +} + extern Query_Processor *GloQPro; MySQL_Logger::MySQL_Logger() { @@ -503,20 +615,62 @@ void MySQL_Logger::log_request(MySQL_Session *sess, MySQL_Data_Stream *myds) { sprintf(ca,"%s:%d",sess->client_myds->addr.addr,sess->client_myds->addr.port); } cl=strlen(ca); - MySQL_Event me(PROXYSQL_QUERY, + enum log_event_type let = PROXYSQL_COM_QUERY; // default + switch (sess->status) { + case PROCESSING_STMT_EXECUTE: + let = PROXYSQL_COM_STMT_EXECUTE; + break; + case PROCESSING_STMT_PREPARE: + let = PROXYSQL_COM_STMT_PREPARE; + break; + case WAITING_CLIENT_DATA: + { + unsigned char c=*((unsigned char *)sess->pktH->ptr+sizeof(mysql_hdr)); + switch ((enum_mysql_command)c) { + case _MYSQL_COM_STMT_PREPARE: + // proxysql is responding to COM_STMT_PREPARE without + // preparing on any backend + let = PROXYSQL_COM_STMT_PREPARE; + break; + default: + break; + } + } + break; + default: + break; + } + MySQL_Event me(let, sess->thread_session_id,ui->username,ui->schemaname, sess->CurrentQuery.start_time + curtime_real - curtime_mono, sess->CurrentQuery.end_time + curtime_real - curtime_mono, GloQPro->get_digest(&sess->CurrentQuery.QueryParserArgs), ca, cl ); - char *c=(char *)sess->CurrentQuery.QueryPointer; + char *c = NULL; + int ql = 0; + switch (sess->status) { + case PROCESSING_STMT_EXECUTE: + c = (char *)sess->CurrentQuery.stmt_info->query; + ql = sess->CurrentQuery.stmt_info->query_length; + break; + case PROCESSING_STMT_PREPARE: + default: + c = (char *)sess->CurrentQuery.QueryPointer; + ql = sess->CurrentQuery.QueryLength; + break; + } if (c) { - me.set_query(c,sess->CurrentQuery.QueryLength); + me.set_query(c,ql); } else { me.set_query("",0); } + if (sess->CurrentQuery.have_affected_rows) { + me.set_affected_rows(sess->CurrentQuery.affected_rows); + } + me.set_rows_sent(sess->CurrentQuery.rows_sent); + int sl=0; char *sa=(char *)""; // default if (myds) { @@ -807,3 +961,8 @@ unsigned int MySQL_Logger::audit_find_next_id() { } return 0; } + +void MySQL_Logger::print_version() { + fprintf(stderr,"Standard ProxySQL MySQL Logger rev. %s -- %s -- %s\n", PROXYSQL_MYSQL_LOGGER_VERSION, __FILE__, __TIMESTAMP__); +}; + diff --git a/lib/MySQL_Protocol.cpp b/lib/MySQL_Protocol.cpp index 239e2d59c4..677fc5a7e0 100644 --- a/lib/MySQL_Protocol.cpp +++ b/lib/MySQL_Protocol.cpp @@ -631,6 +631,10 @@ bool MySQL_Protocol::generate_pkt_OK(bool send, void **ptr, unsigned int *len, u default: break; } + if (sess->session_type == PROXYSQL_SESSION_MYSQL) { + sess->CurrentQuery.have_affected_rows = true; + sess->CurrentQuery.affected_rows = affected_rows; + } } if (*myds && (*myds)->myconn) { if ((*myds)->myconn->options.no_backslash_escapes) { @@ -2273,7 +2277,7 @@ unsigned int MySQL_ResultSet::add_row(MYSQL_ROW row) { // it assumes that the MYSQL_ROW is an format ready to be sent to the client unsigned int MySQL_ResultSet::add_row2(MYSQL_ROWS *row, unsigned char *offset) { unsigned long length=row->length; - + num_rows++; uint8_t pkt_sid=sid; if (length < (0xFFFFFF+sizeof(mysql_hdr))) { mysql_hdr myhdr; diff --git a/lib/MySQL_Session.cpp b/lib/MySQL_Session.cpp index 782fac8686..8995c964fa 100644 --- a/lib/MySQL_Session.cpp +++ b/lib/MySQL_Session.cpp @@ -163,6 +163,9 @@ Query_Info::Query_Info() { stmt_info=NULL; bool_is_select_NOT_for_update=false; bool_is_select_NOT_for_update_computed=false; + have_affected_rows=false; + affected_rows=0; + rows_sent=0; } Query_Info::~Query_Info() { @@ -189,6 +192,9 @@ void Query_Info::begin(unsigned char *_p, int len, bool mysql_header) { } bool_is_select_NOT_for_update=false; bool_is_select_NOT_for_update_computed=false; + have_affected_rows=false; + affected_rows=0; + rows_sent=0; } void Query_Info::end() { @@ -221,6 +227,9 @@ void Query_Info::init(unsigned char *_p, int len, bool mysql_header) { MyComQueryCmd = MYSQL_COM_QUERY__UNINITIALIZED; bool_is_select_NOT_for_update=false; bool_is_select_NOT_for_update_computed=false; + have_affected_rows=false; + affected_rows=0; + rows_sent=0; } void Query_Info::query_parser_init() { @@ -672,6 +681,9 @@ bool MySQL_Session::handler_CommitRollback(PtrSize_t *pkt) { client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); if (c=='c' || c=='C') { __sync_fetch_and_add(&MyHGM->status.commit_cnt_filtered, 1); @@ -795,6 +807,9 @@ bool MySQL_Session::handler_SetAutocommit(PtrSize_t *pkt) { client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); __sync_fetch_and_add(&MyHGM->status.autocommit_cnt_filtered, 1); free(_new_pkt.ptr); @@ -948,6 +963,9 @@ void MySQL_Session::return_proxysql_internal(PtrSize_t *pkt) { client_myds->myprot.generate_pkt_ERR(true,NULL,NULL,1,1064,(char *)"42000",(char *)"Unknown PROXYSQL INTERNAL command",true); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); } @@ -1014,6 +1032,9 @@ bool MySQL_Session::handler_special_queries(PtrSize_t *pkt) { status=WAITING_CLIENT_DATA; client_myds->DSS=STATE_SLEEP; client_myds->PSarrayOUT->add(pkt_2.ptr,pkt_2.size); + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); return true; } @@ -1030,6 +1051,9 @@ bool MySQL_Session::handler_special_queries(PtrSize_t *pkt) { SQLite3_to_MySQL(resultset, error, affected_rows, &client_myds->myprot); delete resultset; free(query2); + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); return true; } @@ -1155,6 +1179,9 @@ bool MySQL_Session::handler_special_queries(PtrSize_t *pkt) { } client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); free(unstripped); __sync_fetch_and_add(&MyHGM->status.frontend_set_names, 1); @@ -1169,6 +1196,9 @@ bool MySQL_Session::handler_special_queries(PtrSize_t *pkt) { delete resultset; client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); return true; } @@ -2706,7 +2736,9 @@ int MySQL_Session::handler() { if (rc_break==true) { if (mirror==false) { // track also special queries - RequestEnd(NULL); + //RequestEnd(NULL); + // we moved this inside handler_special_queries() + // because a pointer was becoming invalid break; } else { handler_ret = -1; @@ -2895,9 +2927,10 @@ int MySQL_Session::handler() { // for this reason, we do not need to prepare it again, and we can already reply to the client // we will now generate a unique stmt and send it to the client uint32_t new_stmt_id=client_myds->myconn->local_stmts->generate_new_client_stmt_id(stmt_info->statement_id); - l_free(pkt.size,pkt.ptr); client_myds->setDSS_STATE_QUERY_SENT_NET(); client_myds->myprot.generate_STMT_PREPARE_RESPONSE(client_myds->pkt_sid+1,stmt_info,new_stmt_id); + LogQuery(NULL); + l_free(pkt.size,pkt.ptr); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; CurrentQuery.end_time=thread->curtime; @@ -3387,6 +3420,7 @@ int MySQL_Session::handler() { if (stmt_info->num_params == 0) { prepared_stmt_with_no_params = true; } + LogQuery(myds); GloMyStmt->unlock(); } } @@ -3395,6 +3429,7 @@ int MySQL_Session::handler() { { thread->status_variables.backend_stmt_execute++; MySQL_Stmt_Result_to_MySQL_wire(CurrentQuery.mysql_stmt, myds->myconn); + LogQuery(myds); if (CurrentQuery.stmt_meta) if (CurrentQuery.stmt_meta->pkt) { uint32_t stmt_global_id=0; @@ -3410,7 +3445,6 @@ int MySQL_Session::handler() { assert(0); break; } - RequestEnd(myds); finishQuery(myds,myconn,prepared_stmt_with_no_params); } else { @@ -4399,6 +4433,9 @@ void MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C } client_myds->myconn->userinfo->set_schemaname(schemanameptr,strlen(schemanameptr)); free(schemaname); + if (mirror==false) { + RequestEnd(NULL); + } l_free(pkt->size,pkt->ptr); client_myds->setDSS_STATE_QUERY_SENT_NET(); unsigned int nTrx=NumActiveTransactions(); @@ -4453,8 +4490,8 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C // ER_NET_PACKET_TOO_LARGE client_myds->DSS=STATE_QUERY_SENT_NET; client_myds->myprot.generate_pkt_ERR(true,NULL,NULL,client_myds->pkt_sid+1,1153,(char *)"08S01",(char *)"Got a packet bigger than 'max_allowed_packet' bytes", true); - l_free(pkt->size,pkt->ptr); RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } @@ -4464,16 +4501,16 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C uint16_t setStatus = (nTrx ? SERVER_STATUS_IN_TRANS : 0 ); if (autocommit) setStatus += SERVER_STATUS_AUTOCOMMIT; client_myds->myprot.generate_pkt_OK(true,NULL,NULL,client_myds->pkt_sid+1,0,0,setStatus,0,qpo->OK_msg); - l_free(pkt->size,pkt->ptr); RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } if (qpo->error_msg) { client_myds->DSS=STATE_QUERY_SENT_NET; client_myds->myprot.generate_pkt_ERR(true,NULL,NULL,client_myds->pkt_sid+1,1148,(char *)"42000",qpo->error_msg); - l_free(pkt->size,pkt->ptr); RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } @@ -4512,8 +4549,8 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; - l_free(pkt->size,pkt->ptr); RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } } else { @@ -4526,8 +4563,8 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; - l_free(pkt->size,pkt->ptr); RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } else { string nqn = string((char *)CurrentQuery.QueryPointer,CurrentQuery.QueryLength); @@ -4726,8 +4763,8 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); client_myds->DSS=STATE_SLEEP; status=WAITING_CLIENT_DATA; - l_free(pkt->size,pkt->ptr); RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } } @@ -4766,10 +4803,10 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C myds->DSS=STATE_ROW; myprot->generate_pkt_EOF(true,NULL,NULL,sid,0, setStatus); sid++; myds->DSS=STATE_SLEEP; + RequestEnd(NULL); l_free(pkt->size,pkt->ptr); free(p); free(l); - RequestEnd(NULL); return true; } @@ -4838,10 +4875,10 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C myds->DSS=STATE_ROW; myprot->generate_pkt_EOF(true,NULL,NULL,sid,0, setStatus); sid++; myds->DSS=STATE_SLEEP; + RequestEnd(NULL); l_free(pkt->size,pkt->ptr); free(p); free(l); - RequestEnd(NULL); return true; } @@ -4870,7 +4907,6 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C qpo->cache_ttl ); if (aa) { - l_free(pkt->size,pkt->ptr); client_myds->buffer2resultset(aa,resbuf); free(aa); client_myds->PSarrayOUT->copy_add(client_myds->resultset,0,client_myds->resultset->len); @@ -4880,6 +4916,7 @@ bool MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C current_hostgroup=-1; } RequestEnd(NULL); + l_free(pkt->size,pkt->ptr); return true; } } @@ -5082,6 +5119,7 @@ void MySQL_Session::MySQL_Stmt_Result_to_MySQL_wire(MYSQL_STMT *stmt, MySQL_Conn MySQL_ResultSet *MyRS=new MySQL_ResultSet(); MyRS->init(&client_myds->myprot, stmt_result, stmt->mysql, stmt); MyRS->get_resultset(client_myds->PSarrayOUT); + CurrentQuery.rows_sent = MyRS->num_rows; //removed bool resultset_completed=MyRS->get_resultset(client_myds->PSarrayOUT); delete MyRS; } else { @@ -5119,6 +5157,7 @@ void MySQL_Session::MySQL_Result_to_MySQL_wire(MYSQL *mysql, MySQL_ResultSet *My assert(MyRS->result); bool transfer_started=MyRS->transfer_started; bool resultset_completed=MyRS->get_resultset(client_myds->PSarrayOUT); + CurrentQuery.rows_sent = MyRS->num_rows; assert(resultset_completed); // the resultset should always be completed if MySQL_Result_to_MySQL_wire is called if (transfer_started==false) { // we have all the resultset when MySQL_Result_to_MySQL_wire was called if (qpo && qpo->cache_ttl>0) { // the resultset should be cached @@ -5309,9 +5348,11 @@ unsigned long long MySQL_Session::IdleTime() { return thread->curtime - last_time; } -// this should execute most of the commands executed when a request is finalized -// this should become the place to hook other functions -void MySQL_Session::RequestEnd(MySQL_Data_Stream *myds) { + + +// this is called either from RequestEnd(), or at the end of executing +// prepared statements +void MySQL_Session::LogQuery(MySQL_Data_Stream *myds) { // we need to access statistics before calling CurrentQuery.end() // so we track the time here CurrentQuery.end_time=thread->curtime; @@ -5319,8 +5360,28 @@ void MySQL_Session::RequestEnd(MySQL_Data_Stream *myds) { if (qpo) { if (qpo->log==1) { GloMyLogger->log_request(this, myds); // we send for logging only if logging is enabled for this query + } else { + if (qpo->log==-1) { + if (mysql_thread___eventslog_default_log==1) { + GloMyLogger->log_request(this, myds); // we send for logging only if enabled by default + } + } } } +} +// this should execute most of the commands executed when a request is finalized +// this should become the place to hook other functions +void MySQL_Session::RequestEnd(MySQL_Data_Stream *myds) { + + switch (status) { + case PROCESSING_STMT_EXECUTE: + case PROCESSING_STMT_PREPARE: + // if a prepared statement is executed, LogQuery was already called + break; + default: + LogQuery(myds); + break; + } GloQPro->delete_QP_out(qpo); // if there is an associated myds, clean its status diff --git a/lib/MySQL_Thread.cpp b/lib/MySQL_Thread.cpp index 67c3799c43..cb8280362f 100644 --- a/lib/MySQL_Thread.cpp +++ b/lib/MySQL_Thread.cpp @@ -220,6 +220,8 @@ static char * mysql_thread_variables_names[]= { (char *)"connect_timeout_server_max", (char *)"eventslog_filename", (char *)"eventslog_filesize", + (char *)"eventslog_default_log", + (char *)"eventslog_format", (char *)"auditlog_filename", (char *)"auditlog_filesize", (char *)"default_charset", @@ -430,6 +432,8 @@ MySQL_Threads_Handler::MySQL_Threads_Handler() { variables.server_version=strdup((char *)"5.5.30"); variables.eventslog_filename=strdup((char *)""); // proxysql-mysql-eventslog is recommended variables.eventslog_filesize=100*1024*1024; + variables.eventslog_default_log=0; + variables.eventslog_format=1; variables.auditlog_filename=strdup((char *)""); variables.auditlog_filesize=100*1024*1024; //variables.server_capabilities=CLIENT_FOUND_ROWS | CLIENT_PROTOCOL_41 | CLIENT_IGNORE_SIGPIPE | CLIENT_TRANSACTIONS | CLIENT_SECURE_CONNECTION | CLIENT_CONNECT_WITH_DB; @@ -758,6 +762,8 @@ int MySQL_Threads_Handler::get_variable_int(const char *name) { if (!strcmp(name,"default_max_latency_ms")) return (int)variables.default_max_latency_ms; } if (!strcmp(name,"eventslog_filesize")) return (int)variables.eventslog_filesize; + if (!strcmp(name,"eventslog_default_log")) return (int)variables.eventslog_default_log; + if (!strcmp(name,"eventslog_format")) return (int)variables.eventslog_format; if (!strcmp(name,"auditlog_filesize")) return (int)variables.auditlog_filesize; if (!strcmp(name,"hostgroup_manager_verbose")) return (int)variables.hostgroup_manager_verbose; if (!strcmp(name,"binlog_reader_connect_retry_msec")) return (int)variables.binlog_reader_connect_retry_msec; @@ -1061,6 +1067,14 @@ char * MySQL_Threads_Handler::get_variable(char *name) { // this is the public f sprintf(intbuf,"%d",variables.eventslog_filesize); return strdup(intbuf); } + if (!strcasecmp(name,"eventslog_default_log")) { + sprintf(intbuf,"%d",variables.eventslog_default_log); + return strdup(intbuf); + } + if (!strcasecmp(name,"eventslog_format")) { + sprintf(intbuf,"%d",variables.eventslog_format); + return strdup(intbuf); + } if (!strcasecmp(name,"auditlog_filesize")) { sprintf(intbuf,"%d",variables.auditlog_filesize); return strdup(intbuf); @@ -1937,6 +1951,31 @@ bool MySQL_Threads_Handler::set_variable(char *name, char *value) { // this is t return false; } } + if (!strcasecmp(name,"eventslog_default_log")) { + int intv=atoi(value); + if (intv >= 0 && intv <= 1) { + variables.eventslog_default_log=intv; + return true; + } else { + return false; + } + } + if (!strcasecmp(name,"eventslog_format")) { + int intv=atoi(value); + if (intv >= 1 && intv <= 2) { + if (variables.eventslog_format!=intv) { + // if we are switching format, we need to switch file too + if (GloMyLogger) { + proxy_info("Switching query logging format from %d to %d\n", variables.eventslog_format , intv); + GloMyLogger->flush_log(); + } + variables.eventslog_format=intv; + } + return true; + } else { + return false; + } + } if (!strcasecmp(name,"auditlog_filesize")) { int intv=atoi(value); if (intv >= 1024*1024 && intv <= 1*1024*1024*1024) { @@ -3859,6 +3898,8 @@ void MySQL_Thread::refresh_variables() { mysql_thread___server_version=GloMTH->get_variable_string((char *)"server_version"); if (mysql_thread___eventslog_filename) free(mysql_thread___eventslog_filename); mysql_thread___eventslog_filesize=GloMTH->get_variable_int((char *)"eventslog_filesize"); + mysql_thread___eventslog_default_log=GloMTH->get_variable_int((char *)"eventslog_default_log"); + mysql_thread___eventslog_format=GloMTH->get_variable_int((char *)"eventslog_format"); mysql_thread___eventslog_filename=GloMTH->get_variable_string((char *)"eventslog_filename"); if (mysql_thread___auditlog_filename) free(mysql_thread___auditlog_filename); mysql_thread___auditlog_filesize=GloMTH->get_variable_int((char *)"auditlog_filesize"); diff --git a/lib/ProxySQL_Admin.cpp b/lib/ProxySQL_Admin.cpp index da84224db0..177c155f7d 100644 --- a/lib/ProxySQL_Admin.cpp +++ b/lib/ProxySQL_Admin.cpp @@ -324,9 +324,9 @@ static int http_handler(void *cls, struct MHD_Connection *connection, const char #define STATS_SQLITE_TABLE_MYSQL_FREE_CONNECTIONS "CREATE TABLE stats_mysql_free_connections (fd INT NOT NULL , hostgroup INT NOT NULL , srv_host VARCHAR NOT NULL , srv_port INT NOT NULL , user VARCHAR NOT NULL , schema VARCHAR , init_connect VARCHAR , time_zone VARCHAR , sql_mode VARCHAR , autocommit VARCHAR , idle_ms INT , statistics VARCHAR , mysql_info VARCHAR)" -#define STATS_SQLITE_TABLE_MYSQL_QUERY_DIGEST "CREATE TABLE stats_mysql_query_digest (hostgroup INT , schemaname VARCHAR NOT NULL , username VARCHAR NOT NULL , client_address VARCHAR NOT NULL , digest VARCHAR NOT NULL , digest_text VARCHAR NOT NULL , count_star INTEGER NOT NULL , first_seen INTEGER NOT NULL , last_seen INTEGER NOT NULL , sum_time INTEGER NOT NULL , min_time INTEGER NOT NULL , max_time INTEGER NOT NULL , PRIMARY KEY(hostgroup, schemaname, username, client_address, digest))" +#define STATS_SQLITE_TABLE_MYSQL_QUERY_DIGEST "CREATE TABLE stats_mysql_query_digest (hostgroup INT , schemaname VARCHAR NOT NULL , username VARCHAR NOT NULL , client_address VARCHAR NOT NULL , digest VARCHAR NOT NULL , digest_text VARCHAR NOT NULL , count_star INTEGER NOT NULL , first_seen INTEGER NOT NULL , last_seen INTEGER NOT NULL , sum_time INTEGER NOT NULL , min_time INTEGER NOT NULL , max_time INTEGER NOT NULL , sum_rows_affected INTEGER NOT NULL , sum_rows_sent INTEGER NOT NULL , PRIMARY KEY(hostgroup, schemaname, username, client_address, digest))" -#define STATS_SQLITE_TABLE_MYSQL_QUERY_DIGEST_RESET "CREATE TABLE stats_mysql_query_digest_reset (hostgroup INT , schemaname VARCHAR NOT NULL , username VARCHAR NOT NULL , client_address VARCHAR NOT NULL , digest VARCHAR NOT NULL , digest_text VARCHAR NOT NULL , count_star INTEGER NOT NULL , first_seen INTEGER NOT NULL , last_seen INTEGER NOT NULL , sum_time INTEGER NOT NULL , min_time INTEGER NOT NULL , max_time INTEGER NOT NULL , PRIMARY KEY(hostgroup, schemaname, username, client_address, digest))" +#define STATS_SQLITE_TABLE_MYSQL_QUERY_DIGEST_RESET "CREATE TABLE stats_mysql_query_digest_reset (hostgroup INT , schemaname VARCHAR NOT NULL , username VARCHAR NOT NULL , client_address VARCHAR NOT NULL , digest VARCHAR NOT NULL , digest_text VARCHAR NOT NULL , count_star INTEGER NOT NULL , first_seen INTEGER NOT NULL , last_seen INTEGER NOT NULL , sum_time INTEGER NOT NULL , min_time INTEGER NOT NULL , max_time INTEGER NOT NULL , sum_rows_affected INTEGER NOT NULL , sum_rows_sent INTEGER NOT NULL , PRIMARY KEY(hostgroup, schemaname, username, client_address, digest))" #define STATS_SQLITE_TABLE_MYSQL_GLOBAL "CREATE TABLE stats_mysql_global (Variable_Name VARCHAR NOT NULL PRIMARY KEY , Variable_Value VARCHAR NOT NULL)" @@ -6248,11 +6248,11 @@ void ProxySQL_Admin::stats___mysql_query_digests(bool reset) { } // char *a=(char *)"INSERT INTO stats_mysql_query_digest VALUES (%s,\"%s\",\"%s\",\"%s\",\"%s\",%s,%s,%s,%s,%s,%s)"; if (reset) { - query1=(char *)"INSERT INTO stats_mysql_query_digest_reset VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12)"; - query32=(char *)"INSERT INTO stats_mysql_query_digest_reset VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12), (?13, ?14, ?15, ?16, ?17, ?18, ?19, ?20, ?21, ?22, ?23, ?24), (?25, ?26, ?27, ?28, ?29, ?30, ?31, ?32, ?33, ?34, ?35, ?36), (?37, ?38, ?39, ?40, ?41, ?42, ?43, ?44, ?45, ?46, ?47, ?48), (?49, ?50, ?51, ?52, ?53, ?54, ?55, ?56, ?57, ?58, ?59, ?60), (?61, ?62, ?63, ?64, ?65, ?66, ?67, ?68, ?69, ?70, ?71, ?72), (?73, ?74, ?75, ?76, ?77, ?78, ?79, ?80, ?81, ?82, ?83, ?84), (?85, ?86, ?87, ?88, ?89, ?90, ?91, ?92, ?93, ?94, ?95, ?96), (?97, ?98, ?99, ?100, ?101, ?102, ?103, ?104, ?105, ?106, ?107, ?108), (?109, ?110, ?111, ?112, ?113, ?114, ?115, ?116, ?117, ?118, ?119, ?120), (?121, ?122, ?123, ?124, ?125, ?126, ?127, ?128, ?129, ?130, ?131, ?132), (?133, ?134, ?135, ?136, ?137, ?138, ?139, ?140, ?141, ?142, ?143, ?144), (?145, ?146, ?147, ?148, ?149, ?150, ?151, ?152, ?153, ?154, ?155, ?156), (?157, ?158, ?159, ?160, ?161, ?162, ?163, ?164, ?165, ?166, ?167, ?168), (?169, ?170, ?171, ?172, ?173, ?174, ?175, ?176, ?177, ?178, ?179, ?180), (?181, ?182, ?183, ?184, ?185, ?186, ?187, ?188, ?189, ?190, ?191, ?192), (?193, ?194, ?195, ?196, ?197, ?198, ?199, ?200, ?201, ?202, ?203, ?204), (?205, ?206, ?207, ?208, ?209, ?210, ?211, ?212, ?213, ?214, ?215, ?216), (?217, ?218, ?219, ?220, ?221, ?222, ?223, ?224, ?225, ?226, ?227, ?228), (?229, ?230, ?231, ?232, ?233, ?234, ?235, ?236, ?237, ?238, ?239, ?240), (?241, ?242, ?243, ?244, ?245, ?246, ?247, ?248, ?249, ?250, ?251, ?252), (?253, ?254, ?255, ?256, ?257, ?258, ?259, ?260, ?261, ?262, ?263, ?264), (?265, ?266, ?267, ?268, ?269, ?270, ?271, ?272, ?273, ?274, ?275, ?276), (?277, ?278, ?279, ?280, ?281, ?282, ?283, ?284, ?285, ?286, ?287, ?288), (?289, ?290, ?291, ?292, ?293, ?294, ?295, ?296, ?297, ?298, ?299, ?300), (?301, ?302, ?303, ?304, ?305, ?306, ?307, ?308, ?309, ?310, ?311, ?312), (?313, ?314, ?315, ?316, ?317, ?318, ?319, ?320, ?321, ?322, ?323, ?324), (?325, ?326, ?327, ?328, ?329, ?330, ?331, ?332, ?333, ?334, ?335, ?336), (?337, ?338, ?339, ?340, ?341, ?342, ?343, ?344, ?345, ?346, ?347, ?348), (?349, ?350, ?351, ?352, ?353, ?354, ?355, ?356, ?357, ?358, ?359, ?360), (?361, ?362, ?363, ?364, ?365, ?366, ?367, ?368, ?369, ?370, ?371, ?372), (?373, ?374, ?375, ?376, ?377, ?378, ?379, ?380, ?381, ?382, ?383, ?384)"; + query1=(char *)"INSERT INTO stats_mysql_query_digest_reset VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12, ?13, ?14)"; + query32=(char *)"INSERT INTO stats_mysql_query_digest_reset VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12, ?13, 14), (?15, ?16, ?17, ?18, ?19, ?20, ?21, ?22, ?23, ?24, ?25, ?26, ?27, 28), (?29, ?30, ?31, ?32, ?33, ?34, ?35, ?36, ?37, ?38, ?39, ?40, ?41, 42), (?43, ?44, ?45, ?46, ?47, ?48, ?49, ?50, ?51, ?52, ?53, ?54, ?55, 56), (?57, ?58, ?59, ?60, ?61, ?62, ?63, ?64, ?65, ?66, ?67, ?68, ?69, 70), (?71, ?72, ?73, ?74, ?75, ?76, ?77, ?78, ?79, ?80, ?81, ?82, ?83, 84), (?85, ?86, ?87, ?88, ?89, ?90, ?91, ?92, ?93, ?94, ?95, ?96, ?97, 98), (?99, ?100, ?101, ?102, ?103, ?104, ?105, ?106, ?107, ?108, ?109, ?110, ?111, 112), (?113, ?114, ?115, ?116, ?117, ?118, ?119, ?120, ?121, ?122, ?123, ?124, ?125, 126), (?127, ?128, ?129, ?130, ?131, ?132, ?133, ?134, ?135, ?136, ?137, ?138, ?139, 140), (?141, ?142, ?143, ?144, ?145, ?146, ?147, ?148, ?149, ?150, ?151, ?152, ?153, 154), (?155, ?156, ?157, ?158, ?159, ?160, ?161, ?162, ?163, ?164, ?165, ?166, ?167, 168), (?169, ?170, ?171, ?172, ?173, ?174, ?175, ?176, ?177, ?178, ?179, ?180, ?181, 182), (?183, ?184, ?185, ?186, ?187, ?188, ?189, ?190, ?191, ?192, ?193, ?194, ?195, 196), (?197, ?198, ?199, ?200, ?201, ?202, ?203, ?204, ?205, ?206, ?207, ?208, ?209, 210), (?211, ?212, ?213, ?214, ?215, ?216, ?217, ?218, ?219, ?220, ?221, ?222, ?223, 224), (?225, ?226, ?227, ?228, ?229, ?230, ?231, ?232, ?233, ?234, ?235, ?236, ?237, 238), (?239, ?240, ?241, ?242, ?243, ?244, ?245, ?246, ?247, ?248, ?249, ?250, ?251, 252), (?253, ?254, ?255, ?256, ?257, ?258, ?259, ?260, ?261, ?262, ?263, ?264, ?265, 266), (?267, ?268, ?269, ?270, ?271, ?272, ?273, ?274, ?275, ?276, ?277, ?278, ?279, 280), (?281, ?282, ?283, ?284, ?285, ?286, ?287, ?288, ?289, ?290, ?291, ?292, ?293, 294), (?295, ?296, ?297, ?298, ?299, ?300, ?301, ?302, ?303, ?304, ?305, ?306, ?307, 308), (?309, ?310, ?311, ?312, ?313, ?314, ?315, ?316, ?317, ?318, ?319, ?320, ?321, 322), (?323, ?324, ?325, ?326, ?327, ?328, ?329, ?330, ?331, ?332, ?333, ?334, ?335, 336), (?337, ?338, ?339, ?340, ?341, ?342, ?343, ?344, ?345, ?346, ?347, ?348, ?349, 350), (?351, ?352, ?353, ?354, ?355, ?356, ?357, ?358, ?359, ?360, ?361, ?362, ?363, 364), (?365, ?366, ?367, ?368, ?369, ?370, ?371, ?372, ?373, ?374, ?375, ?376, ?377, 378), (?379, ?380, ?381, ?382, ?383, ?384, ?385, ?386, ?387, ?388, ?389, ?390, ?391, 392), (?393, ?394, ?395, ?396, ?397, ?398, ?399, ?400, ?401, ?402, ?403, ?404, ?405, 406), (?407, ?408, ?409, ?410, ?411, ?412, ?413, ?414, ?415, ?416, ?417, ?418, ?419, 420), (?421, ?422, ?423, ?424, ?425, ?426, ?427, ?428, ?429, ?430, ?431, ?432, ?433, 434), (?435, ?436, ?437, ?438, ?439, ?440, ?441, ?442, ?443, ?444, ?445, ?446, ?447, 448)"; } else { - query1=(char *)"INSERT INTO stats_mysql_query_digest VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12)"; - query32=(char *)"INSERT INTO stats_mysql_query_digest VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12), (?13, ?14, ?15, ?16, ?17, ?18, ?19, ?20, ?21, ?22, ?23, ?24), (?25, ?26, ?27, ?28, ?29, ?30, ?31, ?32, ?33, ?34, ?35, ?36), (?37, ?38, ?39, ?40, ?41, ?42, ?43, ?44, ?45, ?46, ?47, ?48), (?49, ?50, ?51, ?52, ?53, ?54, ?55, ?56, ?57, ?58, ?59, ?60), (?61, ?62, ?63, ?64, ?65, ?66, ?67, ?68, ?69, ?70, ?71, ?72), (?73, ?74, ?75, ?76, ?77, ?78, ?79, ?80, ?81, ?82, ?83, ?84), (?85, ?86, ?87, ?88, ?89, ?90, ?91, ?92, ?93, ?94, ?95, ?96), (?97, ?98, ?99, ?100, ?101, ?102, ?103, ?104, ?105, ?106, ?107, ?108), (?109, ?110, ?111, ?112, ?113, ?114, ?115, ?116, ?117, ?118, ?119, ?120), (?121, ?122, ?123, ?124, ?125, ?126, ?127, ?128, ?129, ?130, ?131, ?132), (?133, ?134, ?135, ?136, ?137, ?138, ?139, ?140, ?141, ?142, ?143, ?144), (?145, ?146, ?147, ?148, ?149, ?150, ?151, ?152, ?153, ?154, ?155, ?156), (?157, ?158, ?159, ?160, ?161, ?162, ?163, ?164, ?165, ?166, ?167, ?168), (?169, ?170, ?171, ?172, ?173, ?174, ?175, ?176, ?177, ?178, ?179, ?180), (?181, ?182, ?183, ?184, ?185, ?186, ?187, ?188, ?189, ?190, ?191, ?192), (?193, ?194, ?195, ?196, ?197, ?198, ?199, ?200, ?201, ?202, ?203, ?204), (?205, ?206, ?207, ?208, ?209, ?210, ?211, ?212, ?213, ?214, ?215, ?216), (?217, ?218, ?219, ?220, ?221, ?222, ?223, ?224, ?225, ?226, ?227, ?228), (?229, ?230, ?231, ?232, ?233, ?234, ?235, ?236, ?237, ?238, ?239, ?240), (?241, ?242, ?243, ?244, ?245, ?246, ?247, ?248, ?249, ?250, ?251, ?252), (?253, ?254, ?255, ?256, ?257, ?258, ?259, ?260, ?261, ?262, ?263, ?264), (?265, ?266, ?267, ?268, ?269, ?270, ?271, ?272, ?273, ?274, ?275, ?276), (?277, ?278, ?279, ?280, ?281, ?282, ?283, ?284, ?285, ?286, ?287, ?288), (?289, ?290, ?291, ?292, ?293, ?294, ?295, ?296, ?297, ?298, ?299, ?300), (?301, ?302, ?303, ?304, ?305, ?306, ?307, ?308, ?309, ?310, ?311, ?312), (?313, ?314, ?315, ?316, ?317, ?318, ?319, ?320, ?321, ?322, ?323, ?324), (?325, ?326, ?327, ?328, ?329, ?330, ?331, ?332, ?333, ?334, ?335, ?336), (?337, ?338, ?339, ?340, ?341, ?342, ?343, ?344, ?345, ?346, ?347, ?348), (?349, ?350, ?351, ?352, ?353, ?354, ?355, ?356, ?357, ?358, ?359, ?360), (?361, ?362, ?363, ?364, ?365, ?366, ?367, ?368, ?369, ?370, ?371, ?372), (?373, ?374, ?375, ?376, ?377, ?378, ?379, ?380, ?381, ?382, ?383, ?384)"; + query1=(char *)"INSERT INTO stats_mysql_query_digest VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12, ?13, ?14)"; + query32=(char *)"INSERT INTO stats_mysql_query_digest VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, ?11, ?12, ?13, 14), (?15, ?16, ?17, ?18, ?19, ?20, ?21, ?22, ?23, ?24, ?25, ?26, ?27, 28), (?29, ?30, ?31, ?32, ?33, ?34, ?35, ?36, ?37, ?38, ?39, ?40, ?41, 42), (?43, ?44, ?45, ?46, ?47, ?48, ?49, ?50, ?51, ?52, ?53, ?54, ?55, 56), (?57, ?58, ?59, ?60, ?61, ?62, ?63, ?64, ?65, ?66, ?67, ?68, ?69, 70), (?71, ?72, ?73, ?74, ?75, ?76, ?77, ?78, ?79, ?80, ?81, ?82, ?83, 84), (?85, ?86, ?87, ?88, ?89, ?90, ?91, ?92, ?93, ?94, ?95, ?96, ?97, 98), (?99, ?100, ?101, ?102, ?103, ?104, ?105, ?106, ?107, ?108, ?109, ?110, ?111, 112), (?113, ?114, ?115, ?116, ?117, ?118, ?119, ?120, ?121, ?122, ?123, ?124, ?125, 126), (?127, ?128, ?129, ?130, ?131, ?132, ?133, ?134, ?135, ?136, ?137, ?138, ?139, 140), (?141, ?142, ?143, ?144, ?145, ?146, ?147, ?148, ?149, ?150, ?151, ?152, ?153, 154), (?155, ?156, ?157, ?158, ?159, ?160, ?161, ?162, ?163, ?164, ?165, ?166, ?167, 168), (?169, ?170, ?171, ?172, ?173, ?174, ?175, ?176, ?177, ?178, ?179, ?180, ?181, 182), (?183, ?184, ?185, ?186, ?187, ?188, ?189, ?190, ?191, ?192, ?193, ?194, ?195, 196), (?197, ?198, ?199, ?200, ?201, ?202, ?203, ?204, ?205, ?206, ?207, ?208, ?209, 210), (?211, ?212, ?213, ?214, ?215, ?216, ?217, ?218, ?219, ?220, ?221, ?222, ?223, 224), (?225, ?226, ?227, ?228, ?229, ?230, ?231, ?232, ?233, ?234, ?235, ?236, ?237, 238), (?239, ?240, ?241, ?242, ?243, ?244, ?245, ?246, ?247, ?248, ?249, ?250, ?251, 252), (?253, ?254, ?255, ?256, ?257, ?258, ?259, ?260, ?261, ?262, ?263, ?264, ?265, 266), (?267, ?268, ?269, ?270, ?271, ?272, ?273, ?274, ?275, ?276, ?277, ?278, ?279, 280), (?281, ?282, ?283, ?284, ?285, ?286, ?287, ?288, ?289, ?290, ?291, ?292, ?293, 294), (?295, ?296, ?297, ?298, ?299, ?300, ?301, ?302, ?303, ?304, ?305, ?306, ?307, 308), (?309, ?310, ?311, ?312, ?313, ?314, ?315, ?316, ?317, ?318, ?319, ?320, ?321, 322), (?323, ?324, ?325, ?326, ?327, ?328, ?329, ?330, ?331, ?332, ?333, ?334, ?335, 336), (?337, ?338, ?339, ?340, ?341, ?342, ?343, ?344, ?345, ?346, ?347, ?348, ?349, 350), (?351, ?352, ?353, ?354, ?355, ?356, ?357, ?358, ?359, ?360, ?361, ?362, ?363, 364), (?365, ?366, ?367, ?368, ?369, ?370, ?371, ?372, ?373, ?374, ?375, ?376, ?377, 378), (?379, ?380, ?381, ?382, ?383, ?384, ?385, ?386, ?387, ?388, ?389, ?390, ?391, 392), (?393, ?394, ?395, ?396, ?397, ?398, ?399, ?400, ?401, ?402, ?403, ?404, ?405, 406), (?407, ?408, ?409, ?410, ?411, ?412, ?413, ?414, ?415, ?416, ?417, ?418, ?419, 420), (?421, ?422, ?423, ?424, ?425, ?426, ?427, ?428, ?429, ?430, ?431, ?432, ?433, 434), (?435, ?436, ?437, ?438, ?439, ?440, ?441, ?442, ?443, ?444, ?445, ?446, ?447, 448)"; } /* for (std::vector::iterator it = resultset->rows.begin() ; it != resultset->rows.end(); ++it) { @@ -6273,18 +6273,20 @@ void ProxySQL_Admin::stats___mysql_query_digests(bool reset) { SQLite3_row *r1=*it; int idx=row_idx%32; if (row_idxfields[11])); assert(rc==SQLITE_OK); - rc=sqlite3_bind_text(statement32, (idx*12)+2, r1->fields[0], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); - rc=sqlite3_bind_text(statement32, (idx*12)+3, r1->fields[1], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); - rc=sqlite3_bind_text(statement32, (idx*12)+4, r1->fields[2], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); - rc=sqlite3_bind_text(statement32, (idx*12)+5, r1->fields[3], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); - rc=sqlite3_bind_text(statement32, (idx*12)+6, r1->fields[4], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); - rc=sqlite3_bind_int64(statement32, (idx*12)+7, atoll(r1->fields[5])); assert(rc==SQLITE_OK); - rc=sqlite3_bind_int64(statement32, (idx*12)+8, atoll(r1->fields[6])); assert(rc==SQLITE_OK); - rc=sqlite3_bind_int64(statement32, (idx*12)+9, atoll(r1->fields[7])); assert(rc==SQLITE_OK); - rc=sqlite3_bind_int64(statement32, (idx*12)+10, atoll(r1->fields[8])); assert(rc==SQLITE_OK); - rc=sqlite3_bind_int64(statement32, (idx*12)+11, atoll(r1->fields[9])); assert(rc==SQLITE_OK); - rc=sqlite3_bind_int64(statement32, (idx*12)+12, atoll(r1->fields[10])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+1, atoll(r1->fields[11])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_text(statement32, (idx*14)+2, r1->fields[0], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); + rc=sqlite3_bind_text(statement32, (idx*14)+3, r1->fields[1], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); + rc=sqlite3_bind_text(statement32, (idx*14)+4, r1->fields[2], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); + rc=sqlite3_bind_text(statement32, (idx*14)+5, r1->fields[3], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); + rc=sqlite3_bind_text(statement32, (idx*14)+6, r1->fields[4], -1, SQLITE_TRANSIENT); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+7, atoll(r1->fields[5])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+8, atoll(r1->fields[6])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+9, atoll(r1->fields[7])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+10, atoll(r1->fields[8])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+11, atoll(r1->fields[9])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+12, atoll(r1->fields[10])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement32, (idx*14)+13, atoll(r1->fields[12])); assert(rc==SQLITE_OK); // rows affected + rc=sqlite3_bind_int64(statement32, (idx*14)+14, atoll(r1->fields[13])); assert(rc==SQLITE_OK); // rows sent if (idx==31) { SAFE_SQLITE3_STEP2(statement32); rc=sqlite3_clear_bindings(statement32); assert(rc==SQLITE_OK); @@ -6303,6 +6305,8 @@ void ProxySQL_Admin::stats___mysql_query_digests(bool reset) { rc=sqlite3_bind_int64(statement1, 10, atoll(r1->fields[8])); assert(rc==SQLITE_OK); rc=sqlite3_bind_int64(statement1, 11, atoll(r1->fields[9])); assert(rc==SQLITE_OK); rc=sqlite3_bind_int64(statement1, 12, atoll(r1->fields[10])); assert(rc==SQLITE_OK); + rc=sqlite3_bind_int64(statement1, 13, atoll(r1->fields[12])); assert(rc==SQLITE_OK); // rows affected + rc=sqlite3_bind_int64(statement1, 14, atoll(r1->fields[13])); assert(rc==SQLITE_OK); // rows sent SAFE_SQLITE3_STEP2(statement1); rc=sqlite3_clear_bindings(statement1); assert(rc==SQLITE_OK); rc=sqlite3_reset(statement1); assert(rc==SQLITE_OK); diff --git a/lib/Query_Processor.cpp b/lib/Query_Processor.cpp index f58380b72b..86fbdb526d 100644 --- a/lib/Query_Processor.cpp +++ b/lib/Query_Processor.cpp @@ -15,7 +15,7 @@ #else #define DEB "" #endif /* DEBUG */ -#define QUERY_PROCESSOR_VERSION "0.4.1031" DEB +#define QUERY_PROCESSOR_VERSION "2.0.0712" DEB #define QP_RE_MOD_CASELESS 1 #define QP_RE_MOD_GLOBAL 2 @@ -120,6 +120,8 @@ class QP_query_digest_stats { unsigned long long sum_time; unsigned long long min_time; unsigned long long max_time; + unsigned long long rows_affected; + unsigned long long rows_sent; int hid; QP_query_digest_stats(char *u, char *s, uint64_t d, char *dt, int h, char *ca) { digest=d; @@ -136,11 +138,15 @@ class QP_query_digest_stats { sum_time=0; min_time=0; max_time=0; + rows_affected=0; + rows_sent=0; hid=h; } - void add_time(unsigned long long t, unsigned long long n) { + void add_time(unsigned long long t, unsigned long long n, unsigned long long ra, unsigned long long rs) { count_star++; sum_time+=t; + rows_affected+=ra; + rows_sent+=rs; if (t < min_time || min_time==0) { if (t) min_time = t; } @@ -172,7 +178,7 @@ class QP_query_digest_stats { } char **get_row(umap_query_digest_text *digest_text_umap) { char buf[128]; - char **pta=(char **)malloc(sizeof(char *)*12); + char **pta=(char **)malloc(sizeof(char *)*14); assert(schemaname); pta[0]=strdup(schemaname); assert(username); @@ -221,11 +227,15 @@ class QP_query_digest_stats { pta[10]=strdup(buf); sprintf(buf,"%d",hid); pta[11]=strdup(buf); + sprintf(buf,"%llu",rows_affected); + pta[12]=strdup(buf); + sprintf(buf,"%llu",rows_sent); + pta[13]=strdup(buf); return pta; } void free_row(char **pta) { int i; - for (i=0;i<12;i++) { + for (i=0;i<14;i++) { assert(pta[i]); free(pta[i]); } @@ -864,7 +874,7 @@ unsigned long Query_Processor::get_query_digests_total_size() { SQLite3_result * Query_Processor::get_query_digests() { proxy_debug(PROXY_DEBUG_MYSQL_QUERY_PROCESSOR, 4, "Dumping current query digest\n"); - SQLite3_result *result=new SQLite3_result(12); + SQLite3_result *result=new SQLite3_result(14); #ifdef PROXYSQL_QPRO_PTHREAD_MUTEX pthread_rwlock_rdlock(&digest_rwlock); #else @@ -882,6 +892,8 @@ SQLite3_result * Query_Processor::get_query_digests() { result->add_column_definition(SQLITE_TEXT,"sum_time"); result->add_column_definition(SQLITE_TEXT,"min_time"); result->add_column_definition(SQLITE_TEXT,"max_time"); + result->add_column_definition(SQLITE_TEXT,"rows_affected"); + result->add_column_definition(SQLITE_TEXT,"rows_sent"); for (std::unordered_map::iterator it=digest_umap.begin(); it!=digest_umap.end(); ++it) { QP_query_digest_stats *qds=(QP_query_digest_stats *)it->second; char **pta=qds->get_row(&digest_text_umap); @@ -897,7 +909,7 @@ SQLite3_result * Query_Processor::get_query_digests() { } SQLite3_result * Query_Processor::get_query_digests_reset() { - SQLite3_result *result=new SQLite3_result(12); + SQLite3_result *result=new SQLite3_result(14); #ifdef PROXYSQL_QPRO_PTHREAD_MUTEX pthread_rwlock_wrlock(&digest_rwlock); #else @@ -915,6 +927,8 @@ SQLite3_result * Query_Processor::get_query_digests_reset() { result->add_column_definition(SQLITE_TEXT,"sum_time"); result->add_column_definition(SQLITE_TEXT,"min_time"); result->add_column_definition(SQLITE_TEXT,"max_time"); + result->add_column_definition(SQLITE_TEXT,"rows_affected"); + result->add_column_definition(SQLITE_TEXT,"rows_sent"); for (std::unordered_map::iterator it=digest_umap.begin(); it!=digest_umap.end(); ++it) { QP_query_digest_stats *qds=(QP_query_digest_stats *)it->second; char **pta=qds->get_row(&digest_text_umap); @@ -1464,12 +1478,20 @@ void Query_Processor::update_query_digest(SQP_par_t *qp, int hid, MySQL_Connecti #endif QP_query_digest_stats *qds; + unsigned long long rows_affected = 0; + unsigned long long rows_sent = 0; + + if (sess) { + rows_affected = sess->CurrentQuery.affected_rows; + rows_sent = sess->CurrentQuery.rows_sent; + } + std::unordered_map::iterator it; it=digest_umap.find(qp->digest_total); if (it != digest_umap.end()) { // found qds=(QP_query_digest_stats *)it->second; - qds->add_time(t,n); + qds->add_time(t,n, rows_affected,rows_sent); } else { char *dt = NULL; if (mysql_thread___query_digests_normalize_digest_text==false) { @@ -1492,7 +1514,7 @@ void Query_Processor::update_query_digest(SQP_par_t *qp, int hid, MySQL_Connecti } else { qds=new QP_query_digest_stats(ui->username, ui->schemaname, _stmt_info->digest, dt, hid, ca); } - qds->add_time(t,n); + qds->add_time(t,n, rows_affected,rows_sent); digest_umap.insert(std::make_pair(qp->digest_total,(void *)qds)); if (mysql_thread___query_digests_normalize_digest_text==true) { uint64_t dig = 0; diff --git a/src/main.cpp b/src/main.cpp index b99c4bc40a..64318113e4 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -816,6 +816,7 @@ void ProxySQL_Main_init_main_modules() { _tmp_GloMTH=new MySQL_Threads_Handler(); GloMTH = _tmp_GloMTH; GloMyLogger = new MySQL_Logger(); + GloMyLogger->print_version(); GloMyStmt=new MySQL_STMT_Manager_v14(); } diff --git a/tools/eventslog_reader_sample.cpp b/tools/eventslog_reader_sample.cpp index bd7e13fca1..e379fb9cc7 100644 --- a/tools/eventslog_reader_sample.cpp +++ b/tools/eventslog_reader_sample.cpp @@ -7,12 +7,30 @@ #endif /* __STDC_LIMIT_MACROS */ #include #include +#include using namespace std; #define CPY1(x) *((uint8_t *)x) enum log_event_type { - PROXYSQL_QUERY + PROXYSQL_COM_QUERY, + PROXYSQL_MYSQL_AUTH_OK, + PROXYSQL_MYSQL_AUTH_ERR, + PROXYSQL_MYSQL_AUTH_CLOSE, + PROXYSQL_MYSQL_AUTH_QUIT, + PROXYSQL_MYSQL_CHANGE_USER_OK, + PROXYSQL_MYSQL_CHANGE_USER_ERR, + PROXYSQL_MYSQL_INITDB, + PROXYSQL_ADMIN_AUTH_OK, + PROXYSQL_ADMIN_AUTH_ERR, + PROXYSQL_ADMIN_AUTH_CLOSE, + PROXYSQL_ADMIN_AUTH_QUIT, + PROXYSQL_SQLITE_AUTH_OK, + PROXYSQL_SQLITE_AUTH_ERR, + PROXYSQL_SQLITE_AUTH_CLOSE, + PROXYSQL_SQLITE_AUTH_QUIT, + PROXYSQL_COM_STMT_EXECUTE, + PROXYSQL_COM_STMT_PREPARE }; typedef union _4bytes_t { @@ -89,6 +107,8 @@ class MySQL_Event { size_t client_len; uint64_t total_length; uint64_t hid; + uint64_t affected_rows; + uint64_t rows_sent; log_event_type et; public: MySQL_Event() { @@ -97,7 +117,9 @@ class MySQL_Event { void read(std::fstream *f) { f->read((char *)&et,1); switch (et) { - case PROXYSQL_QUERY: + case PROXYSQL_COM_QUERY: + case PROXYSQL_COM_STMT_EXECUTE: + case PROXYSQL_COM_STMT_PREPARE: read_query(f); break; default: @@ -113,7 +135,22 @@ class MySQL_Event { schemaname=read_string(f,schemaname_len); read_encoded_length((uint64_t *)&client_len,f); client=read_string(f,client_len); - cout << "ProxySQL LOG QUERY: thread_id=\"" << thread_id << "\" username=\"" << username << "\" schemaname=\"" << schemaname << "\" client=\"" << client << "\""; + cout << "ProxySQL LOG "; + switch (et) { + case PROXYSQL_COM_STMT_EXECUTE: + cout << "COM_STMT_EXECUTE"; + break; + case PROXYSQL_COM_STMT_PREPARE: + cout << "COM_STMT_PREPARE"; + break; + case PROXYSQL_COM_QUERY: + cout << "COM_QUERY"; + break; + default: + assert(0); // not supported + break; + } + cout << ": thread_id=\"" << thread_id << "\" username=\"" << username << "\" schemaname=\"" << schemaname << "\" client=\"" << client << "\""; read_encoded_length((uint64_t *)&hid,f); if (hid==UINT64_MAX) { cout << " HID=NULL "; @@ -124,6 +161,8 @@ class MySQL_Event { } read_encoded_length((uint64_t *)&start_time,f); read_encoded_length((uint64_t *)&end_time,f); + read_encoded_length((uint64_t *)&affected_rows,f); + read_encoded_length((uint64_t *)&rows_sent,f); read_encoded_length((uint64_t *)&query_digest,f); char digest_hex[20]; sprintf(digest_hex,"0x%016llX", (long long unsigned int)query_digest); @@ -136,14 +175,16 @@ class MySQL_Event { timer=start_time/1000/1000; tm_info = localtime(&timer); strftime(buffer, 26, "%Y-%m-%d %H:%M:%S", tm_info); - sprintf(buffer2,"%6u", (unsigned)(start_time%1000000)); + sprintf(buffer2,"%06u", (unsigned)(start_time%1000000)); cout << " starttime=\"" << buffer << "." << buffer2 << "\""; timer=end_time/1000/1000; tm_info = localtime(&timer); strftime(buffer, 26, "%Y-%m-%d %H:%M:%S", tm_info); - sprintf(buffer2,"%6u", (unsigned)(end_time%1000000)); + sprintf(buffer2,"%06u", (unsigned)(end_time%1000000)); cout << " endtime=\"" << buffer << "." << buffer2 << "\""; cout << " duration=" << (end_time-start_time) << "us"; + cout << " rows_affected=" << affected_rows; + cout << " rows_sent=" << rows_sent; cout << " digest=\"" << digest_hex << "\"" << endl << query_ptr << endl; } ~MySQL_Event() { From 255d9247b8bdb57c5245c00c1b14f3f929babc60 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Sun, 14 Jul 2019 20:41:05 +1000 Subject: [PATCH 2/2] Reduce locking on MySQL_Logger writes to disk --- include/MySQL_Logger.hpp | 4 ++-- lib/MySQL_Logger.cpp | 21 +++++++++++++++++++-- 2 files changed, 21 insertions(+), 4 deletions(-) diff --git a/include/MySQL_Logger.hpp b/include/MySQL_Logger.hpp index 685a00755e..358ab4ec38 100644 --- a/include/MySQL_Logger.hpp +++ b/include/MySQL_Logger.hpp @@ -66,8 +66,6 @@ class MySQL_Logger { #else rwlock_t rwlock; #endif - void wrlock(); - void wrunlock(); void events_close_log_unlocked(); void events_open_log_unlocked(); void audit_close_log_unlocked(); @@ -88,6 +86,8 @@ class MySQL_Logger { void log_request(MySQL_Session *, MySQL_Data_Stream *); void log_audit_entry(log_event_type, MySQL_Session *, MySQL_Data_Stream *, char *e = NULL); void flush(); + void wrlock(); + void wrunlock(); }; diff --git a/lib/MySQL_Logger.cpp b/lib/MySQL_Logger.cpp index b2556c35ab..dea88e9c30 100644 --- a/lib/MySQL_Logger.cpp +++ b/lib/MySQL_Logger.cpp @@ -14,6 +14,7 @@ using json = nlohmann::json; #endif /* DEBUG */ #define PROXYSQL_MYSQL_LOGGER_VERSION "2.0.0714" DEB +extern MySQL_Logger *GloMyLogger; static uint8_t mysql_encode_length(uint64_t len, unsigned char *hd) { if (len < 251) return 1; @@ -225,6 +226,9 @@ void MySQL_Event::write_auth(std::fstream *f, MySQL_Session *sess) { } j["ssl"] = sess->client_myds->encrypted; } + // for performance reason, we are moving the write lock + // right before the write to disk + GloMyLogger->wrlock(); *f << j.dump() << std::endl; } @@ -253,6 +257,10 @@ uint64_t MySQL_Event::write_query_format_1(std::fstream *f) { total_bytes+=mysql_encode_length(query_len,NULL)+query_len; + // for performance reason, we are moving the write lock + // right before the write to disk + GloMyLogger->wrlock(); + // write total length , fixed size f->write((const char *)&total_bytes,sizeof(uint64_t)); //char prefix; @@ -389,6 +397,11 @@ uint64_t MySQL_Event::write_query_format_2_json(std::fstream *f) { char digest_hex[20]; sprintf(digest_hex,"0x%016llX", (long long unsigned int)query_digest); j["digest"] = digest_hex; + + // for performance reason, we are moving the write lock + // right before the write to disk + GloMyLogger->wrlock(); + *f << j.dump() << std::endl; return total_bytes; // always 0 } @@ -690,7 +703,9 @@ void MySQL_Logger::log_request(MySQL_Session *sess, MySQL_Data_Stream *myds) { me.set_server(hid,sa,sl); } - wrlock(); + // for performance reason, we are moving the write lock + // right before the write to disk + //wrlock(); me.write(events.logfile, sess); @@ -840,7 +855,9 @@ void MySQL_Logger::log_audit_entry(log_event_type _et, MySQL_Session *sess, MySQ me.set_extra_info(xi); } - wrlock(); + // for performance reason, we are moving the write lock + // right before the write to disk + //wrlock(); me.write(audit.logfile, sess);