diff --git a/include/MySQL_Session.h b/include/MySQL_Session.h index 10f976f99..00316e6f4 100644 --- a/include/MySQL_Session.h +++ b/include/MySQL_Session.h @@ -51,6 +51,7 @@ class Query_Info { bool have_affected_rows; uint64_t affected_rows; uint64_t rows_sent; + uint64_t waiting_since; Query_Info(); ~Query_Info(); diff --git a/include/MySQL_Thread.h b/include/MySQL_Thread.h index 7c40dca62..7f956155c 100644 --- a/include/MySQL_Thread.h +++ b/include/MySQL_Thread.h @@ -228,6 +228,8 @@ class MySQL_Thread unsigned long long queries_slow; unsigned long long queries_gtid; unsigned long long queries_with_max_lag_ms; + unsigned long long queries_with_max_lag_ms__delayed; + unsigned long long queries_with_max_lag_ms__total_wait_time_us; unsigned long long queries_backends_bytes_sent; unsigned long long queries_backends_bytes_recv; unsigned long long queries_frontends_bytes_sent; @@ -541,6 +543,8 @@ class MySQL_Threads_Handler unsigned long long get_backend_lagging_during_query(); unsigned long long get_backend_offline_during_query(); unsigned long long get_queries_with_max_lag_ms(); + unsigned long long get_queries_with_max_lag_ms__delayed(); + unsigned long long get_queries_with_max_lag_ms__total_wait_time_us(); unsigned long long get_killed_connections(); unsigned long long get_killed_queries(); iface_info *MLM_find_iface_from_fd(int fd) { diff --git a/lib/MySQL_Monitor.cpp b/lib/MySQL_Monitor.cpp index 00a1fd338..e11245801 100644 --- a/lib/MySQL_Monitor.cpp +++ b/lib/MySQL_Monitor.cpp @@ -3869,9 +3869,11 @@ void * monitor_AWS_Aurora_thread_HG(void *arg) { next_loop_at = t1 + check_interval_ms * 1000; continue; } +#ifdef TEST_AURORA if (rand() % 1000 == 0) { // suppress 99.9% of the output, too verbose proxy_info("Running check for AWS Aurora writer HG %u on %s:%d\n", wHG , hpa[cur_host_idx].host, hpa[cur_host_idx].port); } +#endif // TEST_AURORA mmsd = NULL; mmsd = new MySQL_Monitor_State_Data(hpa[cur_host_idx].host, hpa[cur_host_idx].port, NULL, hpa[cur_host_idx].use_ssl); mmsd->writer_hostgroup = wHG; @@ -3894,10 +3896,14 @@ void * monitor_AWS_Aurora_thread_HG(void *arg) { if (rc==false) { unsigned long long now=monotonic_time(); char * new_error = (char *)malloc(50+strlen(mmsd->mysql_error_msg)); + bool access_denied = false; + if (strncmp(mmsd->mysql_error_msg,(char *)"Access denied for user",strlen((char *)"Access denied for user"))==0) { + access_denied = true; + } sprintf(new_error,"timeout or error in creating new connection: %s",mmsd->mysql_error_msg); free(mmsd->mysql_error_msg); mmsd->mysql_error_msg = new_error; - proxy_error("Error on AWS Aurora check for %s:%d after %lldms. Unable to create a connection. If the server is overload, increase mysql-monitor_connect_timeout. Error: %s.\n", mmsd->hostname, mmsd->port, (now-mmsd->t1)/1000, new_error); + proxy_error("Error on AWS Aurora check for %s:%d after %lldms. Unable to create a connection. %sError: %s.\n", mmsd->hostname, mmsd->port, (now-mmsd->t1)/1000, (access_denied ? "" : "If the server is overload, increase mysql-monitor_connect_timeout. " ) , new_error); goto __exit_monitor_aws_aurora_HG_thread; } } @@ -3907,7 +3913,7 @@ void * monitor_AWS_Aurora_thread_HG(void *arg) { #ifdef TEST_AURORA mmsd->async_exit_status = mysql_query_start(&mmsd->interr, mmsd->mysql, "SELECT SERVER_ID, SESSION_ID, LAST_UPDATE_TIMESTAMP, REPLICA_LAG_IN_MILLISECONDS, CPU FROM REPLICA_HOST_STATUS ORDER BY SERVER_ID"); #else - mmsd->async_exit_status = mysql_query_start(&mmsd->interr, mmsd->mysql, "SELECT SERVER_ID, SESSION_ID, LAST_UPDATE_TIMESTAMP, REPLICA_LAG_IN_MILLISECONDS, CPU FROM INFORMATION_SCHEMA.REPLICA_HOST_STATUS ORDER BY SERVER_ID"); + mmsd->async_exit_status = mysql_query_start(&mmsd->interr, mmsd->mysql, "SELECT SERVER_ID, SESSION_ID, LAST_UPDATE_TIMESTAMP, REPLICA_LAG_IN_MILLISECONDS, CPU FROM INFORMATION_SCHEMA.REPLICA_HOST_STATUS WHERE REPLICA_LAG_IN_MILLISECONDS > 0 OR SESSION_ID = 'MASTER_SESSION_ID' ORDER BY SERVER_ID"); #endif // TEST_AURORA while (mmsd->async_exit_status) { mmsd->async_exit_status=wait_for_mysql(mmsd->mysql, mmsd->async_exit_status); diff --git a/lib/MySQL_Session.cpp b/lib/MySQL_Session.cpp index 50263a22a..adadd2e92 100644 --- a/lib/MySQL_Session.cpp +++ b/lib/MySQL_Session.cpp @@ -164,6 +164,7 @@ Query_Info::Query_Info() { bool_is_select_NOT_for_update=false; bool_is_select_NOT_for_update_computed=false; have_affected_rows=false; + waiting_since = 0; affected_rows=0; rows_sent=0; } @@ -193,6 +194,7 @@ 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; + waiting_since = 0; affected_rows=0; rows_sent=0; } @@ -228,6 +230,7 @@ void Query_Info::init(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; + waiting_since = 0; affected_rows=0; rows_sent=0; } @@ -5344,7 +5347,7 @@ void MySQL_Session::handler___client_DSS_QUERY_SENT___server_DSS_NOT_INITIALIZED now_us = realtime_time(); } long long now_ms = now_us/1000; - qpo->max_lag_ms -= now_ms; + qpo->max_lag_ms = now_ms - qpo->max_lag_ms; if (qpo->max_lag_ms < 0) { qpo->max_lag_ms = -1; // time expired } @@ -5393,19 +5396,34 @@ void MySQL_Session::handler___client_DSS_QUERY_SENT___server_DSS_NOT_INITIALIZED } if (qpo->max_lag_ms >= 0) { if (qpo->max_lag_ms <= 360000) { // this is a relative time , we convert it to absolute + if (mc == NULL) { + if (CurrentQuery.waiting_since == 0) { + CurrentQuery.waiting_since = thread->curtime; + thread->status_variables.queries_with_max_lag_ms__delayed++; + } + } if (now_us == 0) { now_us = realtime_time(); } long long now_ms = now_us/1000; - qpo->max_lag_ms += now_ms; + qpo->max_lag_ms = now_ms - qpo->max_lag_ms; + } + } + if (mc) { + if (CurrentQuery.waiting_since) { + unsigned long long waited = thread->curtime - CurrentQuery.waiting_since; + thread->status_variables.queries_with_max_lag_ms__total_wait_time_us += waited; + CurrentQuery.waiting_since = 0; } } proxy_debug(PROXY_DEBUG_MYSQL_CONNECTION, 5, "Sess=%p -- server_myds=%p -- MySQL_Connection %p\n", this, mybe->server_myds, mybe->server_myds->myconn); if (mybe->server_myds->myconn==NULL) { // we couldn't get a connection for whatever reason, ex: no backends, or too busy if (thread->mypolls.poll_timeout==0) { // tune poll timeout - if (thread->mypolls.poll_timeout > (unsigned int)mysql_thread___poll_timeout_on_failure) { - thread->mypolls.poll_timeout = mysql_thread___poll_timeout_on_failure; + thread->mypolls.poll_timeout = mysql_thread___poll_timeout_on_failure * 1000; + } else { + if (thread->mypolls.poll_timeout > (unsigned int)mysql_thread___poll_timeout_on_failure * 1000) { + thread->mypolls.poll_timeout = mysql_thread___poll_timeout_on_failure * 1000; } } return; diff --git a/lib/MySQL_Thread.cpp b/lib/MySQL_Thread.cpp index da213b4d9..7e39384e2 100644 --- a/lib/MySQL_Thread.cpp +++ b/lib/MySQL_Thread.cpp @@ -4050,6 +4050,8 @@ MySQL_Thread::MySQL_Thread() { status_variables.backend_lagging_during_query = 0; status_variables.backend_offline_during_query = 0; status_variables.queries_with_max_lag_ms = 0; + status_variables.queries_with_max_lag_ms__delayed = 0; + status_variables.queries_with_max_lag_ms__total_wait_time_us = 0; status_variables.unexpected_com_quit = 0; status_variables.unexpected_packet = 0; status_variables.killed_connections = 0; @@ -4585,6 +4587,18 @@ SQLite3_result * MySQL_Threads_Handler::SQL3_GlobalStatus(bool _memory) { pta[1]=buf; result->add_row(pta); } + { // queries_with_max_lag_ms__delayed + pta[0]=(char *)"queries_with_max_lag_ms__delayed"; + sprintf(buf,"%llu",get_queries_with_max_lag_ms__delayed()); + pta[1]=buf; + result->add_row(pta); + } + { // queries_with_max_lag_ms__total_wait_time_us + pta[0]=(char *)"queries_with_max_lag_ms__total_wait_time_us"; + sprintf(buf,"%llu",get_queries_with_max_lag_ms__total_wait_time_us()); + pta[1]=buf; + result->add_row(pta); + } { // Unexpected COM_QUIT pta[0]=(char *)"mysql_unexpected_frontend_com_quit"; sprintf(buf,"%llu",get_unexpected_com_quit()); @@ -5623,6 +5637,32 @@ unsigned long long MySQL_Threads_Handler::get_queries_with_max_lag_ms() { return q; } +unsigned long long MySQL_Threads_Handler::get_queries_with_max_lag_ms__delayed() { + unsigned long long q=0; + unsigned int i; + for (i=0;istatus_variables.queries_with_max_lag_ms__delayed,0); + } + } + return q; +} + +unsigned long long MySQL_Threads_Handler::get_queries_with_max_lag_ms__total_wait_time_us() { + unsigned long long q=0; + unsigned int i; + for (i=0;istatus_variables.queries_with_max_lag_ms__total_wait_time_us,0); + } + } + return q; +} + unsigned long long MySQL_Threads_Handler::get_max_connect_timeout() { unsigned long long q=0; unsigned int i; diff --git a/lib/ProxySQL_Admin.cpp b/lib/ProxySQL_Admin.cpp index f15c7e90f..5f8dc069d 100644 --- a/lib/ProxySQL_Admin.cpp +++ b/lib/ProxySQL_Admin.cpp @@ -8234,11 +8234,11 @@ void ProxySQL_Admin::load_mysql_servers_to_runtime() { if (resultset) delete resultset; resultset=NULL; -#ifdef TEST_AURORA // temporary enabled only for testing purpose +//#ifdef TEST_AURORA // temporary enabled only for testing purpose query=(char *)"SELECT a.* FROM mysql_aws_aurora_hostgroups a LEFT JOIN mysql_aws_aurora_hostgroups b ON (a.writer_hostgroup=b.reader_hostgroup) WHERE b.reader_hostgroup IS NULL"; -#else - query=(char *)"SELECT a.* FROM mysql_aws_aurora_hostgroups a WHERE 1=0"; -#endif +//#else +// query=(char *)"SELECT a.* FROM mysql_aws_aurora_hostgroups a WHERE 1=0"; +//#endif proxy_debug(PROXY_DEBUG_ADMIN, 4, "%s\n", query); admindb->execute_statement(query, &error , &cols , &affected_rows , &resultset_aws_aurora); if (error) {