Logging improvements, related to #561

- added new function realtime_time() to get real time
- added support for multiple events, default PROXYSQL_QUERY
- MySQL_Event::write() will perfom a different action depending from log_event_type
- rewrote part of eventslog_reader_sample.cpp:
  - it had few bugs
  - MySQL_Event::read() will perform a different action depending from log_event_type
	- time are printed in real time and not monotonic time
	- all info about a query are printed in one line
connleak
René Cannaò 10 years ago
parent 1b5dcaf46a
commit 31ac6625f6

@ -22,9 +22,11 @@ class MySQL_Event {
size_t client_len;
uint64_t total_length;
unsigned char buf[10];
enum log_event_type et;
public:
MySQL_Event(uint32_t _thread_id, char * _username, char * _schemaname , uint64_t _start_time , uint64_t _end_time , uint64_t _query_digest);
uint64_t write(std::fstream *f);
uint64_t write_query(std::fstream *f);
void set_query(const char *ptr, int len);
};

@ -147,10 +147,16 @@ inline unsigned long long monotonic_time() {
clock_gettime(CLOCK_MONOTONIC, &ts);
return (((unsigned long long) ts.tv_sec) * 1000000) + (ts.tv_nsec / 1000);
}
inline unsigned long long realtime_time() {
struct timespec ts;
clock_gettime(CLOCK_REALTIME, &ts);
return (((unsigned long long) ts.tv_sec) * 1000000) + (ts.tv_nsec / 1000);
}
#endif /* __GEN_FUNCTIONS */
bool Proxy_file_exists(const char *);
bool Proxy_file_regular(const char *);
int remove_spaces(const char *);
char *trim_spaces_in_place(char *str);
char *trim_spaces_in_place(char *str);

@ -9,6 +9,10 @@
#ifndef PROXYSQL_ENUMS
#define PROXYSQL_ENUMS
enum log_event_type {
PROXYSQL_QUERY
};
enum cred_username_type { USERNAME_BACKEND, USERNAME_FRONTEND };
enum MDB_ASYNC_ST { // MariaDB Async State Machine

@ -30,6 +30,7 @@ MySQL_Event::MySQL_Event (uint32_t _thread_id, char * _username, char * _scheman
start_time=_start_time;
end_time=_end_time;
query_digest=_query_digest;
et=PROXYSQL_QUERY;
}
void MySQL_Event::set_query(const char *ptr, int len) {
@ -39,6 +40,19 @@ void MySQL_Event::set_query(const char *ptr, int len) {
uint64_t MySQL_Event::write(std::fstream *f) {
uint64_t total_bytes=0;
switch (et) {
case PROXYSQL_QUERY:
total_bytes=write_query(f);
break;
default:
break;
}
return total_bytes;
}
uint64_t MySQL_Event::write_query(std::fstream *f) {
uint64_t total_bytes=0;
total_bytes+=1; // et
total_bytes+=mysql_encode_length(thread_id, NULL);
username_len=strlen(username);
total_bytes+=mysql_encode_length(username_len,NULL)+username_len;
@ -56,6 +70,8 @@ uint64_t MySQL_Event::write(std::fstream *f) {
//char prefix;
uint8_t len;
f->write((char *)&et,1);
len=mysql_encode_length(thread_id,buf);
write_encoded_length(buf,thread_id,len,buf[0]);
f->write((char *)buf,len);
@ -207,7 +223,13 @@ void MySQL_Logger::log_request(MySQL_Session *sess) {
MySQL_Connection_userinfo *ui=sess->client_myds->myconn->userinfo;
MySQL_Event me(sess->thread_session_id,ui->username,ui->schemaname,sess->CurrentQuery.start_time,sess->CurrentQuery.end_time,GloQPro->get_digest(&sess->CurrentQuery.QueryParserArgs));
uint64_t curtime_real=realtime_time();
uint64_t curtime_mono=sess->thread->curtime;
std::cout << " " << curtime_real << " " << curtime_mono << " " << sess->CurrentQuery.end_time << std::endl;
MySQL_Event me(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));
char *c=(char *)sess->CurrentQuery.QueryPointer;
if (c) {
me.set_query(c,sess->CurrentQuery.QueryLength);

@ -1,2 +1,2 @@
eventslog_reader_sample: eventslog_reader_sample.cpp
$(CXX) -o eventslog_reader_sample eventslog_reader_sample.cpp
$(CXX) -ggdb -o eventslog_reader_sample eventslog_reader_sample.cpp

@ -3,12 +3,14 @@
#include <string>
#include <stdlib.h>
#include <stdint.h>
#include <string.h>
using namespace std;
#define CPY1(x) *((uint8_t *)x)
#define CPY2(x) *((uint16_t *)x)
#define CPY8(x) *((uint64_t *)x)
enum log_event_type {
PROXYSQL_QUERY
};
typedef union _4bytes_t {
unsigned char data[4];
@ -22,18 +24,33 @@ unsigned int CPY3(unsigned char *ptr) {
return buf.i;
}
uint8_t mysql_decode_length(unsigned char *ptr, uint64_t *len) {
if (*ptr <= 0xfb) { if (len) { *len = CPY1(ptr); }; return 1; }
if (*ptr == 0xfc) { if (len) { *len = CPY2(ptr+1); }; return 3; }
//if (*ptr == 0xfc) { if (len) { *len = CPY2(ptr+1); }; return 3; }
if (*ptr == 0xfc) {
if (len) {
memcpy((void *)len,(void *)(ptr+1),2);
};
return 3;
}
if (*ptr == 0xfd) { if (len) { *len = CPY3(ptr+1); }; return 4; }
if (*ptr == 0xfe) { if (len) { *len = CPY8(ptr+1); }; return 9; }
//if (*ptr == 0xfe) { if (len) { *len = CPY8(ptr+1); }; return 9; }
if (*ptr == 0xfe) {
if (len) {
memcpy((void *)len,(void *)(ptr+1),8);
};
return 9;
}
return 0; // never reaches here
}
void read_encoded_length(uint64_t *ptr, std::fstream *f) {
unsigned char buf[10];
unsigned char buf[9];
memset(buf,0,sizeof(uint64_t));
uint8_t len;
*ptr=0;
f->read((char *)buf,1);
len=mysql_decode_length(buf,NULL);
if (len) {
@ -68,24 +85,49 @@ class MySQL_Event {
size_t server_len;
size_t client_len;
uint64_t total_length;
log_event_type et;
public:
MySQL_Event() {
query_len=0;
}
void read(std::fstream *f) {
f->read((char *)&et,1);
switch (et) {
case PROXYSQL_QUERY:
read_query(f);
break;
default:
break;
}
}
void read_query(std::fstream *f) {
read_encoded_length((uint64_t *)&thread_id,f);
read_encoded_length((uint64_t *)&username_len,f);
username=read_string(f,username_len);
read_encoded_length((uint64_t *)&schemaname_len,f);
schemaname=read_string(f,schemaname_len);
cout << "username=" << username << " schemaname=" << schemaname;
cout << "thread_id=\"" << thread_id << "\" username=\"" << username << "\" schemaname=" << schemaname << "\"";
read_encoded_length((uint64_t *)&start_time,f);
read_encoded_length((uint64_t *)&end_time,f);
read_encoded_length((uint64_t *)&query_digest,f);
read_encoded_length((uint64_t *)&query_len,f);
query_ptr=read_string(f,query_len);
cout << " starttime=" << start_time << " endtime=" << end_time;
cout << " query=" << query_ptr << endl;
char buffer[26];
char buffer2[10];
struct tm* tm_info;
time_t timer;
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));
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));
cout << " endtime=\"" << buffer << "." << buffer2 << "\"";
cout << " query=\"" << query_ptr << "\""<< endl;
}
~MySQL_Event() {
free(username);
@ -105,7 +147,7 @@ int main(int argc, char **argv) {
while (more_data) {
try {
input.read((char *)&msg_len,sizeof(uint64_t));
cout << msg_len << endl;
//cout << msg_len << endl;
MySQL_Event me;
me.read(&input);

Loading…
Cancel
Save