revision-id: 2762e165083c35b1ae70069200372aec95f6fd79 (mariadb-10.1.39-62-g2762e16) parent(s): 5b65d61d9384a45ea1b8df79694493fbb1a14e4a committer: Alexey Botchkov timestamp: 2019-06-14 11:32:30 +0400 message: MDEV-18661 loading the audit plugin causes performance regression. Plugin fixed to not lock the LOCK_operations when not active. Server fixed to lock the LOCK_plugin less - do it once per thread and then only if a plugin was installed/uninstalled. --- plugin/server_audit/server_audit.c | 112 ++++++++++++++++++++++--------------- sql/sql_audit.cc | 16 ++++++ sql/sql_audit.h | 1 + sql/sql_class.cc | 4 +- sql/sql_class.h | 1 + sql/sql_connect.cc | 3 +- sql/sql_plugin.cc | 3 + sql/sql_plugin.h | 1 + sql/threadpool_common.cc | 3 +- 9 files changed, 97 insertions(+), 47 deletions(-) diff --git a/plugin/server_audit/server_audit.c b/plugin/server_audit/server_audit.c index c9e7e3a..3da5264 100644 --- a/plugin/server_audit/server_audit.c +++ b/plugin/server_audit/server_audit.c @@ -15,7 +15,7 @@ #define PLUGIN_VERSION 0x104 -#define PLUGIN_STR_VERSION "1.4.4" +#define PLUGIN_STR_VERSION "1.4.7" #define _my_thread_var loc_thread_var @@ -295,7 +295,7 @@ static unsigned long long file_rotate_size; static unsigned int rotations; static my_bool rotate= TRUE; static char logging; -static int internal_stop_logging= 0; +static volatile int internal_stop_logging= 0; static char incl_user_buffer[1024]; static char excl_user_buffer[1024]; static char *big_buffer= NULL; @@ -533,16 +533,20 @@ static struct st_mysql_show_var audit_status[]= #if defined(HAVE_PSI_INTERFACE) && !defined(FLOGGER_NO_PSI) /* These belong to the service initialization */ static PSI_mutex_key key_LOCK_operations; +static PSI_mutex_key key_LOCK_atomic; static PSI_mutex_key key_LOCK_bigbuffer; static PSI_mutex_info mutex_key_list[]= { { &key_LOCK_operations, "SERVER_AUDIT_plugin::lock_operations", PSI_FLAG_GLOBAL}, + { &key_LOCK_atomic, "SERVER_AUDIT_plugin::lock_atomic", + PSI_FLAG_GLOBAL}, { &key_LOCK_bigbuffer, "SERVER_AUDIT_plugin::lock_bigbuffer", PSI_FLAG_GLOBAL} }; #endif static mysql_mutex_t lock_operations; +static mysql_mutex_t lock_atomic; static mysql_mutex_t lock_bigbuffer; /* The Percona server and partly MySQL don't support */ @@ -553,6 +557,14 @@ static mysql_mutex_t lock_bigbuffer; /* worths doing. */ #define CLIENT_ERROR if (!started_mysql) my_printf_error +#define ADD_ATOMIC(x, a) \ + do { \ + flogger_mutex_lock(&lock_atomic); \ + x+= a; \ + flogger_mutex_unlock(&lock_atomic); \ + } while (0) + + static uchar *getkey_user(const char *entry, size_t *length, my_bool nu __attribute__((unused)) ) { @@ -731,20 +743,20 @@ static int user_coll_fill(struct user_coll *c, char *users, if (cmp_user && take_over_cmp) { - internal_stop_logging= 1; + ADD_ATOMIC(internal_stop_logging, 1); CLIENT_ERROR(1, "User '%.*s' was removed from the" " server_audit_excl_users.", MYF(ME_JUST_WARNING), (int) cmp_length, users); - internal_stop_logging= 0; + ADD_ATOMIC(internal_stop_logging, -1); blank_user(cmp_user); refill_cmp_coll= 1; } else if (cmp_user) { - internal_stop_logging= 1; + ADD_ATOMIC(internal_stop_logging, 1); CLIENT_ERROR(1, "User '%.*s' is in the server_audit_incl_users, " "so wasn't added.", MYF(ME_JUST_WARNING), (int) cmp_length, users); - internal_stop_logging= 0; + ADD_ATOMIC(internal_stop_logging, -1); remove_user(users); continue; } @@ -1252,23 +1264,30 @@ static void change_connection(struct connection_info *cn, event->ip, event->ip_length); } -static int write_log(const char *message, int len) +static int write_log(const char *message, size_t len, int take_lock) { + int result= 0; + if (take_lock) + flogger_mutex_lock(&lock_operations); + if (output_type == OUTPUT_FILE) { if (logfile && - (is_active= (logger_write(logfile, message, len) == len))) - return 0; + (is_active= (logger_write(logfile, message, len) == (int) len))) + goto exit; ++log_write_failures; - return 1; + result= 1; } else if (output_type == OUTPUT_SYSLOG) { syslog(syslog_facility_codes[syslog_facility] | syslog_priority_codes[syslog_priority], - "%s %.*s", syslog_info, len, message); + "%s %.*s", syslog_info, (int) len, message); } - return 0; +exit: + if (take_lock) + flogger_mutex_unlock(&lock_operations); + return result; } @@ -1327,7 +1346,7 @@ static int log_connection(const struct connection_info *cn, csize+= my_snprintf(message+csize, sizeof(message) - 1 - csize, ",%.*s,,%d", cn->db_length, cn->db, event->status); message[csize]= '\n'; - return write_log(message, csize + 1); + return write_log(message, csize + 1, 1); } @@ -1348,7 +1367,7 @@ static int log_connection_event(const struct mysql_event_connection *event, csize+= my_snprintf(message+csize, sizeof(message) - 1 - csize, ",%.*s,,%d", event->database_length, event->database, event->status); message[csize]= '\n'; - return write_log(message, csize + 1); + return write_log(message, csize + 1, 1); } @@ -1477,21 +1496,28 @@ static size_t escape_string_hide_passwords(const char *str, unsigned int len, -static int do_log_user(const char *name) +static int do_log_user(const char *name, int take_lock) { size_t len; + int result; if (!name) return 0; len= strlen(name); - if (incl_user_coll.n_users) - return coll_search(&incl_user_coll, name, len) != 0; + if (take_lock) + flogger_mutex_lock(&lock_operations); - if (excl_user_coll.n_users) - return coll_search(&excl_user_coll, name, len) == 0; + if (incl_user_coll.n_users) + result= coll_search(&incl_user_coll, name, len) != 0; + else if (excl_user_coll.n_users) + result= coll_search(&excl_user_coll, name, len) == 0; + else + result= 1; - return 1; + if (take_lock) + flogger_mutex_unlock(&lock_operations); + return result; } @@ -1588,7 +1614,7 @@ static int filter_query_type(const char *query, struct sa_keyword *kwd) static int log_statement_ex(const struct connection_info *cn, time_t ev_time, unsigned long thd_id, const char *query, unsigned int query_len, - int error_code, const char *type) + int error_code, const char *type, int take_lock) { size_t csize; char message_loc[1024]; @@ -1736,7 +1762,7 @@ static int log_statement_ex(const struct connection_info *cn, csize+= my_snprintf(message+csize, message_size - 1 - csize, "\',%d", error_code); message[csize]= '\n'; - result= write_log(message, csize + 1); + result= write_log(message, csize + 1, take_lock); if (message == big_buffer) flogger_mutex_unlock(&lock_bigbuffer); @@ -1750,7 +1776,7 @@ static int log_statement(const struct connection_info *cn, { return log_statement_ex(cn, event->general_time, event->general_thread_id, event->general_query, event->general_query_length, - event->general_error_code, type); + event->general_error_code, type, 1); } @@ -1772,7 +1798,7 @@ static int log_table(const struct connection_info *cn, ",%.*s,%.*s,",event->database_length, event->database, event->table_length, event->table); message[csize]= '\n'; - return write_log(message, csize + 1); + return write_log(message, csize + 1, 1); } @@ -1796,7 +1822,7 @@ static int log_rename(const struct connection_info *cn, event->new_database_length, event->new_database, event->new_table_length, event->new_table); message[csize]= '\n'; - return write_log(message, csize + 1); + return write_log(message, csize + 1, 1); } @@ -1988,8 +2014,6 @@ void auditing(MYSQL_THD thd, unsigned int event_class, const void *ev) if (!thd || internal_stop_logging) return; - flogger_mutex_lock(&lock_operations); - if (maria_55_started && debug_server_started && event_class == MYSQL_AUDIT_GENERAL_CLASS) { @@ -2024,7 +2048,7 @@ void auditing(MYSQL_THD thd, unsigned int event_class, const void *ev) goto exit_func; if (event_class == MYSQL_AUDIT_GENERAL_CLASS && FILTER(EVENT_QUERY) && - cn && do_log_user(cn->user)) + cn && do_log_user(cn->user, 1)) { const struct mysql_event_general *event = (const struct mysql_event_general *) ev; @@ -2043,7 +2067,7 @@ void auditing(MYSQL_THD thd, unsigned int event_class, const void *ev) { const struct mysql_event_table *event = (const struct mysql_event_table *) ev; - if (do_log_user(event->user)) + if (do_log_user(event->user, 1)) { switch (event->event_subclass) { @@ -2109,7 +2133,6 @@ void auditing(MYSQL_THD thd, unsigned int event_class, const void *ev) } if (cn) cn->log_always= 0; - flogger_mutex_unlock(&lock_operations); } @@ -2377,6 +2400,7 @@ static int server_audit_init(void *p __attribute__((unused))) PSI_server->register_mutex("server_audit", mutex_key_list, 1); #endif flogger_mutex_init(key_LOCK_operations, &lock_operations, MY_MUTEX_INIT_FAST); + flogger_mutex_init(key_LOCK_operations, &lock_atomic, MY_MUTEX_INIT_FAST); flogger_mutex_init(key_LOCK_operations, &lock_bigbuffer, MY_MUTEX_INIT_FAST); coll_init(&incl_user_coll); @@ -2464,6 +2488,7 @@ static int server_audit_deinit(void *p __attribute__((unused))) (void) free(big_buffer); flogger_mutex_destroy(&lock_operations); + flogger_mutex_destroy(&lock_atomic); flogger_mutex_destroy(&lock_bigbuffer); error_header(); @@ -2553,10 +2578,10 @@ static void log_current_query(MYSQL_THD thd) return; cn= get_loc_info(thd); if (!ci_needs_setup(cn) && cn->query_length && - FILTER(EVENT_QUERY) && do_log_user(cn->user)) + FILTER(EVENT_QUERY) && do_log_user(cn->user, 0)) { log_statement_ex(cn, cn->query_time, thd_get_thread_id(thd), - cn->query, cn->query_length, 0, "QUERY"); + cn->query, cn->query_length, 0, "QUERY", 0); cn->log_always= 1; } } @@ -2568,12 +2593,13 @@ static void update_file_path(MYSQL_THD thd, { char *new_name= (*(char **) save) ? *(char **) save : empty_str; - if (!maria_55_started || !debug_server_started) - flogger_mutex_lock(&lock_operations); - internal_stop_logging= 1; + ADD_ATOMIC(internal_stop_logging, 1); error_header(); fprintf(stderr, "Log file name was changed to '%s'.\n", new_name); + if (!maria_55_started || !debug_server_started) + flogger_mutex_lock(&lock_operations); + if (logging) log_current_query(thd); @@ -2582,7 +2608,6 @@ static void update_file_path(MYSQL_THD thd, char *sav_path= file_path; file_path= new_name; - internal_stop_logging= 1; stop_logging(); if (start_logging()) { @@ -2598,16 +2623,15 @@ static void update_file_path(MYSQL_THD thd, } goto exit_func; } - internal_stop_logging= 0; } strncpy(path_buffer, new_name, sizeof(path_buffer)-1); path_buffer[sizeof(path_buffer)-1]= 0; file_path= path_buffer; exit_func: - internal_stop_logging= 0; if (!maria_55_started || !debug_server_started) flogger_mutex_unlock(&lock_operations); + ADD_ATOMIC(internal_stop_logging, -1); } @@ -2692,8 +2716,8 @@ static void update_output_type(MYSQL_THD thd, if (output_type == new_output_type) return; + ADD_ATOMIC(internal_stop_logging, 1); flogger_mutex_lock(&lock_operations); - internal_stop_logging= 1; if (logging) { log_current_query(thd); @@ -2707,8 +2731,8 @@ static void update_output_type(MYSQL_THD thd, if (logging) start_logging(); - internal_stop_logging= 0; flogger_mutex_unlock(&lock_operations); + ADD_ATOMIC(internal_stop_logging, -1); } @@ -2756,9 +2780,9 @@ static void update_logging(MYSQL_THD thd, if (new_logging == logging) return; + ADD_ATOMIC(internal_stop_logging, 1); if (!maria_55_started || !debug_server_started) flogger_mutex_lock(&lock_operations); - internal_stop_logging= 1; if ((logging= new_logging)) { start_logging(); @@ -2773,9 +2797,9 @@ static void update_logging(MYSQL_THD thd, stop_logging(); } - internal_stop_logging= 0; if (!maria_55_started || !debug_server_started) flogger_mutex_unlock(&lock_operations); + ADD_ATOMIC(internal_stop_logging, -1); } @@ -2787,16 +2811,16 @@ static void update_mode(MYSQL_THD thd __attribute__((unused)), if (mode_readonly || new_mode == mode) return; + ADD_ATOMIC(internal_stop_logging, 1); if (!maria_55_started || !debug_server_started) flogger_mutex_lock(&lock_operations); - internal_stop_logging= 1; mark_always_logged(thd); error_header(); fprintf(stderr, "Logging mode was changed from %d to %d.\n", mode, new_mode); mode= new_mode; - internal_stop_logging= 0; if (!maria_55_started || !debug_server_started) flogger_mutex_unlock(&lock_operations); + ADD_ATOMIC(internal_stop_logging, -1); } diff --git a/sql/sql_audit.cc b/sql/sql_audit.cc index dd98e3c..cee0ac2 100644 --- a/sql/sql_audit.cc +++ b/sql/sql_audit.cc @@ -212,6 +212,7 @@ void mysql_audit_acquire_plugins(THD *thd, ulong *event_class_mask) { plugin_foreach(thd, acquire_plugins, MYSQL_AUDIT_PLUGIN, event_class_mask); add_audit_mask(thd->audit_class_mask, event_class_mask); + thd->audit_plugin_version= global_plugin_version; } DBUG_VOID_RETURN; } @@ -242,6 +243,20 @@ void mysql_audit_notify(THD *thd, uint event_class, uint event_subtype, ...) /** + Check if there were changes in the state of plugins + so we need to do the mysql_audit_release asap. + + @param[in] thd + +*/ + +my_bool mysql_audit_release_required(THD *thd) +{ + return thd && (thd->audit_plugin_version != global_plugin_version); +} + + +/** Release any resources associated with the current thd. @param[in] thd @@ -276,6 +291,7 @@ void mysql_audit_release(THD *thd) /* Reset the state of thread values */ reset_dynamic(&thd->audit_class_plugins); bzero(thd->audit_class_mask, sizeof(thd->audit_class_mask)); + thd->audit_plugin_version= -1; } diff --git a/sql/sql_audit.h b/sql/sql_audit.h index 550b2a5..9a74675 100644 --- a/sql/sql_audit.h +++ b/sql/sql_audit.h @@ -60,6 +60,7 @@ static inline void mysql_audit_notify(THD *thd, uint event_class, #define mysql_audit_connection_enabled() 0 #define mysql_audit_table_enabled() 0 #endif +extern my_bool mysql_audit_release_required(THD *thd); extern void mysql_audit_release(THD *thd); #define MAX_USER_HOST_SIZE 512 diff --git a/sql/sql_class.cc b/sql/sql_class.cc index 8fabcd5..6bcff6d 100644 --- a/sql/sql_class.cc +++ b/sql/sql_class.cc @@ -776,6 +776,9 @@ THD::THD(bool is_wsrep_applier) waiting_on_group_commit(FALSE), has_waiter(FALSE), spcont(NULL), m_parser_state(NULL), +#ifndef EMBEDDED_LIBRARY + audit_plugin_version(-1), +#endif #if defined(ENABLED_DEBUG_SYNC) debug_sync_control(0), #endif /* defined(ENABLED_DEBUG_SYNC) */ @@ -1562,7 +1565,6 @@ THD::~THD() mdl_context.destroy(); ha_close_connection(this); - mysql_audit_release(this); plugin_thdvar_cleanup(this); main_security_ctx.destroy(); diff --git a/sql/sql_class.h b/sql/sql_class.h index 1cb516c..6392394 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -2978,6 +2978,7 @@ class THD :public Statement, added to the list of audit plugins which are currently in use. */ unsigned long audit_class_mask[MYSQL_AUDIT_CLASS_MASK_SIZE]; + int audit_plugin_version; #endif #if defined(ENABLED_DEBUG_SYNC) diff --git a/sql/sql_connect.cc b/sql/sql_connect.cc index 4dbb53f..a6a01b1 100644 --- a/sql/sql_connect.cc +++ b/sql/sql_connect.cc @@ -1326,7 +1326,8 @@ void do_handle_one_connection(THD *thd_arg) while (thd_is_connection_alive(thd)) { - mysql_audit_release(thd); + if (mysql_audit_release_required(thd)) + mysql_audit_release(thd); if (do_command(thd)) break; } diff --git a/sql/sql_plugin.cc b/sql/sql_plugin.cc index 21093e3..48131b1 100644 --- a/sql/sql_plugin.cc +++ b/sql/sql_plugin.cc @@ -228,6 +228,7 @@ static DYNAMIC_ARRAY plugin_array; static HASH plugin_hash[MYSQL_MAX_PLUGIN_TYPE_NUM]; static MEM_ROOT plugin_mem_root; static bool reap_needed= false; +volatile int global_plugin_version= 1; static bool initialized= 0; ulong dlopen_count; @@ -2181,6 +2182,7 @@ bool mysql_install_plugin(THD *thd, const LEX_STRING *name, reap_plugins(); } err: + global_plugin_version++; mysql_mutex_unlock(&LOCK_plugin); if (argv) free_defaults(argv); @@ -2327,6 +2329,7 @@ bool mysql_uninstall_plugin(THD *thd, const LEX_STRING *name, } reap_plugins(); + global_plugin_version++; mysql_mutex_unlock(&LOCK_plugin); DBUG_RETURN(error); diff --git a/sql/sql_plugin.h b/sql/sql_plugin.h index 7f74114..3bde06a 100644 --- a/sql/sql_plugin.h +++ b/sql/sql_plugin.h @@ -37,6 +37,7 @@ enum enum_plugin_load_option { PLUGIN_OFF, PLUGIN_ON, PLUGIN_FORCE, PLUGIN_FORCE_PLUS_PERMANENT }; extern const char *global_plugin_typelib_names[]; +extern volatile int global_plugin_version; extern ulong dlopen_count; #include <my_sys.h> diff --git a/sql/threadpool_common.cc b/sql/threadpool_common.cc index b4066bd..b8be708 100644 --- a/sql/threadpool_common.cc +++ b/sql/threadpool_common.cc @@ -266,7 +266,8 @@ int threadpool_process_request(THD *thd) { Vio *vio; thd->net.reading_or_writing= 0; - mysql_audit_release(thd); + if (mysql_audit_release_required(thd)) + mysql_audit_release(thd); if ((retval= do_command(thd)) != 0) goto end;