Skip to content

Commit 46c120e

Browse files
inikepinikep
committed
PS-4790: Improve user statistics accuracy
Measure times for `dispatch_command` instead of mysql_parse, mysqld_stmt_reset, mysqld_stmt_fetch, mysqld_stmt_prepare, mysqld_stmt_execute.
1 parent 394cdce commit 46c120e

9 files changed

+160
-342
lines changed

‎mysql-test/r/percona_userstat.result

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -41,7 +41,7 @@ SET @thread_statistics_old= @@thread_statistics;
4141
SET GLOBAL thread_statistics=ON;
4242
SELECT * FROM INFORMATION_SCHEMA.CLIENT_STATISTICS;
4343
CLIENT TOTAL_CONNECTIONS CONCURRENT_CONNECTIONS CONNECTED_TIME BUSY_TIME CPU_TIME BYTES_RECEIVED BYTES_SENT BINLOG_BYTES_WRITTEN ROWS_FETCHED ROWS_UPDATED TABLE_ROWS_READ SELECT_COMMANDS UPDATE_COMMANDS OTHER_COMMANDS COMMIT_TRANSACTIONS ROLLBACK_TRANSACTIONS DENIED_CONNECTIONS LOST_CONNECTIONS ACCESS_DENIED EMPTY_QUERIES TOTAL_SSL_CONNECTIONS
44-
localhost 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 88 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
44+
localhost 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 36 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0
4545
SELECT * FROM INFORMATION_SCHEMA.INDEX_STATISTICS;
4646
TABLE_SCHEMA TABLE_NAME INDEX_NAME ROWS_READ
4747
SELECT * FROM INFORMATION_SCHEMA.TABLE_STATISTICS;
@@ -51,10 +51,10 @@ THREAD_ID TOTAL_CONNECTIONS CONNECTED_TIME BUSY_TIME CPU_TIME BYTES_RECEIVED BYT
5151
THREAD_ID 1 CONNECTED_TIME BUSY_TIME CPU_TIME 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
5252
SELECT * FROM INFORMATION_SCHEMA.USER_STATISTICS;
5353
USER TOTAL_CONNECTIONS CONCURRENT_CONNECTIONS CONNECTED_TIME BUSY_TIME CPU_TIME BYTES_RECEIVED BYTES_SENT BINLOG_BYTES_WRITTEN ROWS_FETCHED ROWS_UPDATED TABLE_ROWS_READ SELECT_COMMANDS UPDATE_COMMANDS OTHER_COMMANDS COMMIT_TRANSACTIONS ROLLBACK_TRANSACTIONS DENIED_CONNECTIONS LOST_CONNECTIONS ACCESS_DENIED EMPTY_QUERIES TOTAL_SSL_CONNECTIONS
54-
root 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 306 0 0 2 0 0 4 0 2 0 0 0 0 0 2 0
54+
root 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 254 0 0 2 0 0 4 0 1 0 0 0 0 0 2 0
5555
SHOW CLIENT_STATISTICS;
5656
Client Total_connections Concurrent_connections Connected_time Busy_time Cpu_time Bytes_received Bytes_sent Binlog_bytes_written Rows_fetched Rows_updated Table_rows_read Select_commands Update_commands Other_commands Commit_transactions Rollback_transactions Denied_connections Lost_connections Access_denied Empty_queries Total_ssl_connections
57-
localhost 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 359 0 0 3 0 0 5 0 2 0 0 0 0 0 2 0
57+
localhost 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 307 0 0 3 0 0 5 0 1 0 0 0 0 0 2 0
5858
SHOW INDEX_STATISTICS;
5959
Table_schema Table_name Index_name Rows_read
6060
SHOW TABLE_STATISTICS;
@@ -64,7 +64,7 @@ Thread_id Total_connections Connected_time Busy_time Cpu_time Bytes_received Byt
6464
THREAD_ID 1 CONNECTED_TIME BUSY_TIME CPU_TIME 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
6565
SHOW USER_STATISTICS;
6666
User Total_connections Concurrent_connections Connected_time Busy_time Cpu_time Bytes_received Bytes_sent Binlog_bytes_written Rows_fetched Rows_updated Table_rows_read Select_commands Update_commands Other_commands Commit_transactions Rollback_transactions Denied_connections Lost_connections Access_denied Empty_queries Total_ssl_connections
67-
root 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 465 0 0 3 0 0 5 0 6 0 0 0 0 0 2 0
67+
root 1 0 CONNECTED_TIME BUSY_TIME CPU_TIME 413 0 0 3 0 0 5 0 5 0 0 0 0 0 2 0
6868
SET GLOBAL thread_statistics= @thread_statistics_old;
6969
SELECT
7070
Select_commands, Update_commands, Other_commands, Rows_fetched

‎sql/CMakeLists.txt

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -498,6 +498,7 @@ SET(SQL_SHARED_SOURCES
498498
trigger_creation_ctx.cc
499499
trigger_chain.cc
500500
tztime.cc
501+
userstat.cc
501502
uniques.cc
502503
xa.cc
503504
${MYSQL_SERVER_SUB_COMPONENT_SOURCES}

‎sql/bootstrap.cc

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -275,7 +275,7 @@ static bool handle_bootstrap_impl(THD *thd) {
275275

276276
// Ignore ER_TOO_LONG_KEY for system tables.
277277
thd->push_internal_handler(&error_handler);
278-
mysql_parse(thd, &parser_state);
278+
mysql_parse(thd, &parser_state, true);
279279
thd->pop_internal_handler();
280280

281281
bootstrap_error = thd->is_error();

‎sql/log_event.cc

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5292,7 +5292,7 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
52925292
if (thd->m_digest != NULL)
52935293
thd->m_digest->reset(thd->m_token_array, max_digest_length);
52945294

5295-
mysql_parse(thd, &parser_state);
5295+
mysql_parse(thd, &parser_state, true);
52965296

52975297
enum_sql_command command = thd->lex->sql_command;
52985298

‎sql/sql_parse.cc

Lines changed: 31 additions & 66 deletions
Original file line numberDiff line numberDiff line change
@@ -163,6 +163,7 @@
163163
#include "sql/thd_raii.h"
164164
#include "sql/transaction.h" // trans_rollback_implicit
165165
#include "sql/transaction_info.h"
166+
#include "sql/userstat.h"
166167
#include "sql_string.h"
167168
#include "thr_lock.h"
168169
#include "violite.h"
@@ -1448,6 +1449,12 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
14481449
if (!(server_command_flags[command] & CF_SKIP_QUESTIONS))
14491450
thd->status_var.questions++;
14501451

1452+
/* Declare userstat variables and start timer */
1453+
double start_busy_usecs = 0.0;
1454+
double start_cpu_nsecs = 0.0;
1455+
if (unlikely(opt_userstat))
1456+
userstat_start_timer(&start_busy_usecs, &start_cpu_nsecs);
1457+
14511458
/**
14521459
Clear the set of flags that are expected to be cleared at the
14531460
beginning of each command.
@@ -1644,7 +1651,7 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
16441651
Parser_state parser_state;
16451652
if (parser_state.init(thd, thd->query().str, thd->query().length)) break;
16461653

1647-
mysql_parse(thd, &parser_state);
1654+
mysql_parse(thd, &parser_state, false);
16481655

16491656
DBUG_EXECUTE_IF("parser_stmt_to_error_log", {
16501657
LogErr(INFORMATION_LEVEL, ER_PARSER_TRACE, thd->query().str);
@@ -1716,7 +1723,7 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
17161723
thd->set_time(); /* Reset the query start time. */
17171724
parser_state.reset(beginning_of_next_stmt, length);
17181725
/* TODO: set thd->lex->sql_command to SQLCOM_END here */
1719-
mysql_parse(thd, &parser_state);
1726+
mysql_parse(thd, &parser_state, false);
17201727
}
17211728

17221729
/* Need to set error to true for graceful shutdown */
@@ -1993,6 +2000,15 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
19932000
DBUG_ASSERT(thd->open_tables == NULL ||
19942001
(thd->locked_tables_mode == LTM_LOCK_TABLES));
19952002

2003+
/* Update user statistics only if at least one timer was initialized */
2004+
if (unlikely(start_busy_usecs > 0.0 || start_cpu_nsecs > 0.0)) {
2005+
userstat_finish_timer(start_busy_usecs, start_cpu_nsecs, &thd->busy_time,
2006+
&thd->cpu_time);
2007+
/* Updates THD stats and the global user stats. */
2008+
thd->update_stats(true);
2009+
update_global_user_stats(thd, true, time(nullptr));
2010+
}
2011+
19962012
/* Finalize server status flags after executing a command. */
19972013
thd->update_slow_query_status();
19982014
if (thd->killed) thd->send_kill_message();
@@ -5002,7 +5018,7 @@ bool create_select_for_variable(Parse_context *pc, const char *var_name) {
50025018
@param parser_state Parser state.
50035019
*/
50045020

5005-
void mysql_parse(THD *thd, Parser_state *parser_state) {
5021+
void mysql_parse(THD *thd, Parser_state *parser_state, bool update_userstat) {
50065022
DBUG_ENTER("mysql_parse");
50075023
DBUG_PRINT("mysql_parse", ("query: '%s'", thd->query().str));
50085024

@@ -5011,31 +5027,11 @@ void mysql_parse(THD *thd, Parser_state *parser_state) {
50115027
mysql_reset_thd_for_next_command(thd);
50125028
lex_start(thd);
50135029

5014-
int start_time_error = 0;
5015-
int end_time_error = 0;
5016-
struct timeval start_time, end_time;
5017-
double start_usecs = 0;
5018-
double end_usecs = 0;
5019-
/* cpu time */
5020-
int cputime_error = 0;
5021-
#ifdef HAVE_CLOCK_GETTIME
5022-
struct timespec tp;
5023-
#endif
5024-
double start_cpu_nsecs = 0;
5025-
double end_cpu_nsecs = 0;
5026-
5027-
if (opt_userstat) {
5028-
#ifdef HAVE_CLOCK_GETTIME
5029-
/* get start cputime */
5030-
if (!(cputime_error = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
5031-
start_cpu_nsecs = tp.tv_sec * 1000000000.0 + tp.tv_nsec;
5032-
#endif
5033-
5034-
// Gets the start time, in order to measure how long this command takes.
5035-
if (!(start_time_error = gettimeofday(&start_time, nullptr))) {
5036-
start_usecs = start_time.tv_sec * 1000000.0 + start_time.tv_usec;
5037-
}
5038-
}
5030+
/* Declare userstat variables and start timer */
5031+
double start_busy_usecs = 0.0;
5032+
double start_cpu_nsecs = 0.0;
5033+
if (unlikely(opt_userstat && update_userstat))
5034+
userstat_start_timer(&start_busy_usecs, &start_cpu_nsecs);
50395035

50405036
thd->m_parser_state = parser_state;
50415037
invoke_pre_parse_rewrite_plugins(thd);
@@ -5190,45 +5186,14 @@ void mysql_parse(THD *thd, Parser_state *parser_state) {
51905186
thd->cleanup_after_query();
51915187
DBUG_ASSERT(thd->change_list.is_empty());
51925188

5193-
if (opt_userstat) {
5194-
// Gets the end time.
5195-
if (!(end_time_error = gettimeofday(&end_time, NULL))) {
5196-
end_usecs = end_time.tv_sec * 1000000.0 + end_time.tv_usec;
5197-
}
5198-
5199-
// Calculates the difference between the end and start times.
5200-
if (start_usecs && end_usecs >= start_usecs && !start_time_error &&
5201-
!end_time_error) {
5202-
thd->busy_time = (end_usecs - start_usecs) / 1000000;
5203-
// In case there are bad values, 2629743 is the #seconds in a month.
5204-
if (thd->busy_time > 2629743) {
5205-
thd->busy_time = 0;
5206-
}
5207-
} else {
5208-
// end time went back in time, or gettimeofday() failed.
5209-
thd->busy_time = 0;
5210-
}
5211-
5212-
#ifdef HAVE_CLOCK_GETTIME
5213-
/* get end cputime */
5214-
if (!cputime_error &&
5215-
!(cputime_error = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
5216-
end_cpu_nsecs = tp.tv_sec * 1000000000.0 + tp.tv_nsec;
5217-
#endif
5218-
if (start_cpu_nsecs && !cputime_error) {
5219-
thd->cpu_time = (end_cpu_nsecs - start_cpu_nsecs) / 1000000000;
5220-
// In case there are bad values, 2629743 is the #seconds in a month.
5221-
if (thd->cpu_time > 2629743) {
5222-
thd->cpu_time = 0;
5223-
}
5224-
} else
5225-
thd->cpu_time = 0;
5226-
}
5227-
5228-
// Updates THD stats and the global user stats.
5229-
if (unlikely(opt_userstat)) {
5189+
/* Update user statistics only if at least one timer was initialized */
5190+
if (unlikely(update_userstat &&
5191+
(start_busy_usecs > 0.0 || start_cpu_nsecs > 0.0))) {
5192+
userstat_finish_timer(start_busy_usecs, start_cpu_nsecs, &thd->busy_time,
5193+
&thd->cpu_time);
5194+
/* Updates THD stats and the global user stats. */
52305195
thd->update_stats(true);
5231-
update_global_user_stats(thd, true, time(NULL));
5196+
update_global_user_stats(thd, true, time(nullptr));
52325197
}
52335198

52345199
DBUG_VOID_RETURN;

‎sql/sql_parse.h

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -96,7 +96,7 @@ bool is_update_query(enum enum_sql_command command);
9696
bool is_explainable_query(enum enum_sql_command command);
9797
bool is_log_table_write_query(enum enum_sql_command command);
9898
bool alloc_query(THD *thd, const char *packet, size_t packet_length);
99-
void mysql_parse(THD *thd, Parser_state *parser_state);
99+
void mysql_parse(THD *thd, Parser_state *parser_state, bool update_userstat);
100100
void mysql_reset_thd_for_next_command(THD *thd);
101101
bool create_select_for_variable(Parse_context *pc, const char *var_name);
102102
void create_table_set_open_action_and_adjust_tables(LEX *lex);

0 commit comments

Comments
 (0)