From 6e8e1b16dfbb1cb3d401ddb6bfe45fc991f17c78 Mon Sep 17 00:00:00 2001 From: Arnold Robbins Date: Sun, 9 Oct 2016 15:41:30 +0300 Subject: [PATCH] Offsets MariaDB 5.5.52 and 10.1.8. Speed improvements in logging. --- include/audit_handler.h | 39 +++++---- src/audit_handler.cc | 188 +++++++++++++++++++++++++++------------- src/audit_offsets.cc | 8 ++ 3 files changed, 154 insertions(+), 81 deletions(-) diff --git a/include/audit_handler.h b/include/audit_handler.h index c5204c4..9012710 100644 --- a/include/audit_handler.h +++ b/include/audit_handler.h @@ -100,10 +100,7 @@ public: virtual ~IWriter() {} // return negative on fail virtual ssize_t write(const char *data, size_t size) = 0; - inline ssize_t write_str(const char *str) - { - return write(str, strlen(str)); - } + virtual ssize_t write_no_lock(const char *str, size_t size) = 0; // return 0 on success virtual int open(const char *io_dest, bool log_errors) = 0; virtual void close() = 0; @@ -545,11 +542,11 @@ protected: // creating additional instances Audit_handler & operator=(const Audit_handler&); Audit_handler(const Audit_handler&); + // lock io + pthread_mutex_t LOCK_io; private: // bool indicating if to print offset errors to log or not - bool m_print_offset_err; - // lock io - pthread_mutex_t LOCK_io; + bool m_print_offset_err; // audit (enable) lock rw_lock_t LOCK_audit; inline void lock_shared() @@ -585,8 +582,20 @@ public: * target we write to (socket/file). Public so we update via sysvar */ char *m_io_dest; + + inline ssize_t write(const char *data, size_t size) + { + pthread_mutex_lock(&LOCK_io); + ssize_t res = write_no_lock(data, size); + pthread_mutex_unlock(&LOCK_io); //release the IO lock + return res; + } protected: + /** + * Will format using the writer + */ + virtual bool handler_log_audit(ThdSesData *pThdData); virtual bool handler_start_internal(); virtual void handler_stop_internal(); // used for logging messages @@ -623,7 +632,7 @@ public: /** * Write function we pass to formatter */ - ssize_t write(const char *data, size_t size); + ssize_t write_no_lock(const char *data, size_t size); void close(); @@ -634,11 +643,7 @@ protected: // additional instances Audit_file_handler & operator=(const Audit_file_handler&); Audit_file_handler(const Audit_file_handler&); - - /** - * Will acquire locks and call handler_write - */ - virtual bool handler_log_audit(ThdSesData *pThdData); + FILE *m_log_file; // the period to use for syncing unsigned int m_sync_counter; @@ -666,7 +671,7 @@ public: /** * Write function we pass to formatter */ - ssize_t write(const char *data, size_t size); + ssize_t write_no_lock(const char *data, size_t size); void close(); @@ -675,11 +680,7 @@ protected: // override default assignment and copy to protect against creating additional instances Audit_socket_handler & operator=(const Audit_socket_handler&); Audit_socket_handler(const Audit_socket_handler&); - - /** - * Will acquire locks and call handler_write - */ - virtual bool handler_log_audit(ThdSesData *pThdData); + // Vio we write to // define as void* so we don't access members directly void *m_vio; diff --git a/src/audit_handler.cc b/src/audit_handler.cc index 4913430..b1dadb6 100644 --- a/src/audit_handler.cc +++ b/src/audit_handler.cc @@ -45,12 +45,59 @@ // initialize static stuff ThdOffsets Audit_formatter::thd_offsets = { 0 }; Audit_handler *Audit_handler::m_audit_handler_list[Audit_handler::MAX_AUDIT_HANDLERS_NUM]; -const char *Audit_json_formatter::DEF_MSG_DELIMITER = "\\n"; // FIXME: This is used ... #if MYSQL_VERSION_ID < 50709 #define C_STRING_WITH_LEN(X) ((char *) (X)), ((size_t) (sizeof(X) - 1)) #endif +////////////////////////////////////////////// +// Yajl alloc funcs based upon thd_alloc +static void * yajl_thd_malloc(void *ctx, size_t sz) +{ + THD *thd = (THD*)ctx; + //we allocate plus sizeof(size_t) and stored the alloced size at the start of the pointer (for support of realloc) + size_t * ptr = (size_t *)thd_alloc(thd, sz + sizeof(size_t)); + if(ptr) + { + *ptr = sz; //set the size at the start of the memory + ptr++; + } + return ptr; +} + +static void * yajl_thd_realloc(void *ctx, void * previous, + size_t sz) +{ + THD *thd = (THD*)ctx; + void *ptr; + if ((ptr= yajl_thd_malloc(thd,sz))) + { + if(previous) + { + //copy only the previous allocated size (which is stored just before the pointer passed in) + size_t prev_sz = *(((size_t *)previous) - 1); + memcpy(ptr,previous, prev_sz); + } + } + return ptr; +} + +static void yajl_thd_free(void *ctx, void * ptr) +{ + //do nothing as thd_alloc deosn't require free + return; +} + +static void yajl_set_thd_alloc_funcs(THD * thd, yajl_alloc_funcs * yaf) +{ + yaf->malloc = yajl_thd_malloc; + yaf->free = yajl_thd_free; + yaf->realloc = yajl_thd_realloc; + yaf->ctx = thd; +} + +////////////////////////////////////////////// + const char *Audit_formatter::retrieve_object_type(TABLE_LIST *pObj) { if (table_is_view(pObj)) @@ -148,8 +195,7 @@ void Audit_handler::log_audit(ThdSesData *pThdData) else { // offsets are good - m_print_offset_err = true; // mark to print offset err to log in case we encounter in the future - pthread_mutex_lock(&LOCK_io); + m_print_offset_err = true; // mark to print offset err to log in case we encounter in the future // check if failed bool do_log = true; if (m_failed) @@ -159,18 +205,35 @@ void Audit_handler::log_audit(ThdSesData *pThdData) difftime(time(NULL), m_last_retry_sec_ts) > m_retry_interval; if (retry) { - do_log = handler_start_nolock(); + pthread_mutex_lock(&LOCK_io); + //get the io lock. After acquiring the lock do another check that we really need to start (maybe another thread did this already) + if(!m_failed) + { + do_log = true; + } + else if(m_retry_interval > 0 && + difftime(time(NULL), m_last_retry_sec_ts) > m_retry_interval) + { + do_log = handler_start_nolock(); + } + pthread_mutex_unlock(&LOCK_io); + } } if (do_log) { if (! handler_log_audit(pThdData)) { - set_failed(); - handler_stop_internal(); + //failure - acquire io lock to set failed and do stop + pthread_mutex_lock(&LOCK_io); + if(!m_failed) //make sure someone else didn't set this already + { + set_failed(); + handler_stop_internal(); + } + pthread_mutex_unlock(&LOCK_io); } - } - pthread_mutex_unlock(&LOCK_io); + } } unlock(); } @@ -184,13 +247,30 @@ void Audit_file_handler::close() m_log_file = NULL; } -ssize_t Audit_file_handler::write(const char *data, size_t size) -{ - ssize_t res = my_fwrite(m_log_file, (uchar *) data, size, MYF(0)); - if (res < 0) // log the error +ssize_t Audit_file_handler::write_no_lock(const char *data, size_t size) +{ + ssize_t res = -1; + if(m_log_file) { - sql_print_error("%s failed writing to file: %s. Err: %s", - AUDIT_LOG_PREFIX, m_io_dest, strerror(errno)); + res = my_fwrite(m_log_file, (uchar *) data, size, MYF(0)); + if (res && m_sync_period && ++m_sync_counter >= m_sync_period) + { + m_sync_counter = 0; + // Note fflush() only flushes the user space buffers provided by the C library. + // To ensure that the data is physically stored on disk the kernel buffers must be flushed too, + // e.g. with sync(2) or fsync(2). + res = (fflush(m_log_file) == 0); + if (res) + { + int fd = fileno(m_log_file); + res = (my_sync(fd, MYF(MY_WME)) == 0); + } + } + if (res < 0) // log the error + { + sql_print_error("%s failed writing to file: %s. Err: %s", + AUDIT_LOG_PREFIX, m_io_dest, strerror(errno)); + } } return res; } @@ -280,6 +360,10 @@ bool Audit_io_handler::handler_start_internal() return true; } +bool Audit_io_handler::handler_log_audit(ThdSesData *pThdData) { + return (m_formatter->event_format(pThdData, this) >= 0); +} + void Audit_io_handler::handler_stop_internal() { if (! m_failed) @@ -299,6 +383,7 @@ bool Audit_handler::handler_start_nolock() else { set_failed(); + handler_stop_internal(); } return res; } @@ -318,25 +403,6 @@ void Audit_handler::handler_stop() pthread_mutex_unlock(&LOCK_io); } -bool Audit_file_handler::handler_log_audit(ThdSesData *pThdData) -{ - bool res = (m_formatter->event_format(pThdData, this) >= 0); - if (res && m_sync_period && ++m_sync_counter >= m_sync_period) - { - m_sync_counter = 0; - // Note fflush() only flushes the user space buffers provided by the C library. - // To ensure that the data is physically stored on disk the kernel buffers must be flushed too, - // e.g. with sync(2) or fsync(2). - res = (fflush(m_log_file) == 0); - if (res) - { - int fd = fileno(m_log_file); - res = (my_sync(fd, MYF(MY_WME)) == 0); - } - } - return res; -} - /////////////////// Audit_socket_handler ////////////////////////////////// void Audit_socket_handler::close() @@ -349,13 +415,17 @@ void Audit_socket_handler::close() m_vio = NULL; } -ssize_t Audit_socket_handler::write(const char *data, size_t size) -{ - ssize_t res = vio_write((Vio*)m_vio, (const uchar *) data, size); - if (res < 0) // log the error +ssize_t Audit_socket_handler::write_no_lock(const char *data, size_t size) +{ + ssize_t res = -1; + if (m_vio) { - sql_print_error("%s failed writing to socket: %s. Err: %s", - AUDIT_LOG_PREFIX, m_io_dest, strerror(vio_errno((Vio*)m_vio))); + res = vio_write((Vio*)m_vio, (const uchar *) data, size); + if (res < 0) // log the error + { + sql_print_error("%s failed writing to socket: %s. Err: %s", + AUDIT_LOG_PREFIX, m_io_dest, strerror(vio_errno((Vio*)m_vio))); + } } return res; } @@ -401,11 +471,6 @@ int Audit_socket_handler::open(const char *io_dest, bool log_errors) return 0; } -bool Audit_socket_handler::handler_log_audit(ThdSesData *pThdData) -{ - return (m_formatter->event_format(pThdData, this) >= 0); -} - //////////////////////// Audit Socket handler end /////////////////////////////////////////// @@ -558,17 +623,13 @@ ssize_t Audit_json_formatter::start_msg_format(IWriter *writer) yajl_gen_status stat = yajl_gen_map_close(gen); // close the object if (stat == yajl_gen_status_ok) // all is good write the buffer out { + //will add the delimiter to the buffer + yajl_gen_reset(gen, "\n"); const unsigned char *text = NULL; size_t len = 0; yajl_gen_get_buf(gen, &text, &len); - // print the json - res = writer->write((const char *)text, len); - if (res >= 0) - { - // TODO: use the msg_delimiter - res = writer->write("\n", 1); - } - // my_fwrite(log_file, (uchar *) b.data, json_size(&b), MYF(0)); + // no need for lock as it was acquired before as part of the connect + res = writer->write_no_lock((const char *)text, len); } yajl_gen_free(gen); // free the generator return res; @@ -615,7 +676,9 @@ ssize_t Audit_json_formatter::event_format(ThdSesData *pThdData, IWriter *writer query_id_t qid = thd_inst_query_id(thd); // initialize yajl - yajl_gen gen = yajl_gen_alloc(NULL); + yajl_alloc_funcs alloc_funcs; + yajl_set_thd_alloc_funcs(thd, &alloc_funcs); + yajl_gen gen = yajl_gen_alloc(&alloc_funcs); yajl_gen_map_open(gen); yajl_add_string_val(gen, "msg-type", "activity"); // TODO: get the start date from THD (but it is not in millis. Need to think about how we handle this) @@ -743,17 +806,13 @@ ssize_t Audit_json_formatter::event_format(ThdSesData *pThdData, IWriter *writer yajl_gen_status stat = yajl_gen_map_close(gen); // close the object if (stat == yajl_gen_status_ok) // all is good write the buffer out { + //will add the delimiter to the buffer + yajl_gen_reset(gen, "\n"); const unsigned char *text = NULL; size_t len = 0; yajl_gen_get_buf(gen, &text, &len); // print the json - res = writer->write((const char *)text, len); - if (res >= 0) - { - // TODO: use the msg_delimiter - res = writer->write("\n", 1); - } - // my_fwrite(log_file, (uchar *) b.data, json_size(&b), MYF(0)); + res = writer->write((const char *)text, len); } yajl_gen_free(gen); // free the generator return res; @@ -798,8 +857,13 @@ bool ThdSesData::startGetObjects() return false; } // only return query tables if command is COM_QUERY - // TODO: check if other commands can also generate query tables such as "show fields" - if (pLex && command == COM_QUERY && pLex->query_tables) + // TODO: check if other commands can also generate query tables + // such as "show fields" + if ( pLex + && ( command == COM_QUERY + || command == COM_STMT_PREPARE + || command == COM_STMT_EXECUTE) + && pLex->query_tables) { m_tables = pLex->query_tables; m_objIterType = OBJ_TABLE_LIST; diff --git a/src/audit_offsets.cc b/src/audit_offsets.cc index e0f6f33..746d9e3 100644 --- a/src/audit_offsets.cc +++ b/src/audit_offsets.cc @@ -855,6 +855,10 @@ const ThdOffsets thd_offsets_arr[] = const ThdOffsets thd_offsets_arr[] = { /* +++ MARIADB 64 OFFSETS GO HERE +++ */ + //offsets for: /mariadb/10.1.18/bin/mysqld (10.1.18-MariaDB) + {"10.1.18-MariaDB","fa401704df1eabec593f85cdc022d0e4", 13640, 13704, 6416, 8024, 88, 2976, 8, 0, 16, 24, 152, 13796}, + //offsets for: /mariadb/5.5.52/bin/mysqld (5.5.52-MariaDB) + {"5.5.52-MariaDB","fa1093ae4a7000c1209f848d155a2eba", 12032, 12096, 5800, 6904, 88, 2920, 8, 0, 16, 24, 152, 12168}, //offsets for: /mariadb/10.1.17/bin/mysqld (10.1.17-MariaDB) {"10.1.17-MariaDB","f1efa1e5abc9d95de5f06b2ac8e9f94e", 13640, 13704, 6416, 8024, 88, 2976, 8, 0, 16, 24, 152, 13796}, //offsets for: /mariadb/10.0.27/bin/mysqld (10.0.27-MariaDB) @@ -968,6 +972,10 @@ const ThdOffsets thd_offsets_arr[] = const ThdOffsets thd_offsets_arr[] = { /* +++ MARIADB 32 OFFSETS GO HERE +++ */ + //offsets for: /mariadb/10.1.18/bin/mysqld (10.1.18-MariaDB) + {"10.1.18-MariaDB","c1f42e4cc9dc7d04dff76566970d584c", 8496, 8532, 3840, 5300, 44, 1892, 4, 0, 8, 12, 84, 8608}, + //offsets for: /mariadb/5.5.52/bin/mysqld (5.5.52-MariaDB) + {"5.5.52-MariaDB","0ad2ab91c1723438bff04f5fa41dcb1f", 7276, 7312, 3460, 4468, 44, 1856, 4, 0, 8, 12, 84, 7372}, //offsets for: /mariadb/10.1.17/bin/mysqld (10.1.17-MariaDB) {"10.1.17-MariaDB","e1a72bffe9bcfd78cbcfc717746c9378", 8496, 8532, 3840, 5300, 44, 1892, 4, 0, 8, 12, 84, 8608}, //offsets for: /mariadb/10.0.27/bin/mysqld (10.0.27-MariaDB)