Add CPU scheduler usage and delay to slow log report

Summary:
This is part 3 of adding the scheduler CPU stats to the slow log report. The change adds `cpu_usage` and `delay_total` columns to the `mysql.slowlog` table and the similar two outputs to the file. The data is obtained by calling the new CPU scheduler API `tp_get_current_task_cpu_stats`.

Also includes the fix for the `thread_pool.admission_control` flaky test (there's a race between a connection getting killed and the query returning the number of connections).

Differential Revision: D52822589

fbshipit-source-id: 14eb469

mysql-test/r/log_state.result

@@ -41,7 +41,7 @@ select sleep(@long_query_time + 1);
 sleep(@long_query_time + 1)
 0
 select * from mysql.slow_log where sql_text NOT LIKE '%slow_log%';
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
 # Switch to connection default
 set global slow_query_log= ON;
 # Switch to connection con1
@@ -50,8 +50,8 @@ select sleep(@long_query_time + 1);
 sleep(@long_query_time + 1)
 0
 select * from mysql.slow_log where sql_text NOT LIKE '%slow_log%';
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
-TIMESTAMP	USER_HOST	QUERY_TIME	LOCK_TIME	1	1	test	0	0	1	QUERY	THREAD_ID
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
+TIMESTAMP	USER_HOST	QUERY_TIME	LOCK_TIME	1	1	test	0	0	1	QUERY	THREAD_ID	CPU_USAGE	DELAY_TOTAL
 # Switch to connection default
 show global variables
 where Variable_name = 'log' or Variable_name = 'log_slow_queries' or

mysql-test/r/log_tables.result

@@ -18,7 +18,7 @@ event_time	user_host	thread_id	server_id	command_type	argument
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	select * from general_log
 truncate table slow_log;
 select * from slow_log;
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
 truncate table general_log;
 select * from general_log where argument like '%general_log%';
 event_time	user_host	thread_id	server_id	command_type	argument
@@ -83,7 +83,9 @@ slow_log	CREATE TABLE `slow_log` (
   `insert_id` int NOT NULL,
   `server_id` int unsigned NOT NULL,
   `sql_text` mediumblob NOT NULL,
-  `thread_id` bigint unsigned NOT NULL
+  `thread_id` bigint unsigned NOT NULL,
+  `cpu_usage` time(6) NOT NULL,
+  `delay_total` time(6) NOT NULL
 ) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'
 show fields from mysql.slow_log;
 Field	Type	Null	Key	Default	Extra
@@ -99,6 +101,8 @@ insert_id	int	NO		NULL
 server_id	int unsigned	NO		NULL	
 sql_text	mediumblob	NO		NULL	
 thread_id	bigint unsigned	NO		NULL	
+cpu_usage	time(6)	NO		NULL	
+delay_total	time(6)	NO		NULL	
 flush logs;
 flush tables;
 SET GLOBAL GENERAL_LOG=ON;
@@ -157,8 +161,8 @@ select sleep(2);
 sleep(2)
 0
 select * from mysql.slow_log;
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
-TIMESTAMP	USER_HOST	QUERY_TIME	LOCK_TIME	1	1	mysql	0	0	1	QUERY	THREAD_ID
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
+TIMESTAMP	USER_HOST	QUERY_TIME	LOCK_TIME	1	1	mysql	0	0	1	QUERY	THREAD_ID	CPU_USAGE	DELAY_TOTAL
 set @@session.long_query_time = @saved_long_query_time;
 flush tables with read lock;
 unlock tables;
@@ -182,7 +186,7 @@ event_time	user_host	thread_id	server_id	command_type	argument
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	select * from general_log
 truncate table slow_log;
 select * from slow_log;
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
 create table general_log_new like general_log;
 rename table general_log TO renamed_general_log, general_log_new TO general_log;
 create table slow_log_new like slow_log;
@@ -203,9 +207,9 @@ TIMESTAMP	USER_HOST	THREAD_ID	1	Query	select * from slow_log
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	create table general_log_new like general_log
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	rename table general_log TO renamed_general_log, general_log_new TO general_log
 select * from slow_log;
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
 select * from renamed_slow_log;
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
 set global general_log='OFF';
 RENAME TABLE general_log TO general_log2;
 set global slow_query_log='OFF';
@@ -339,7 +343,9 @@ CREATE TABLE `db_17876.slow_log_data` (
 `insert_id` int(11) default NULL,
 `server_id` int(11) default NULL,
 `sql_text` mediumblob,
-`thread_id` bigint(21) unsigned not NULL
+`thread_id` bigint(21) unsigned not NULL,
+`cpu_usage` time,
+`delay_total` time
 );
 Warnings:
 Warning	1681	Integer display width is deprecated and will be removed in a future release.
@@ -361,7 +367,7 @@ Warning	1681	Integer display width is deprecated and will be removed in a future
 Warning	1681	Integer display width is deprecated and will be removed in a future release.
 CREATE procedure `db_17876.archiveSlowLog`()
 BEGIN
-DECLARE start_time, query_time, lock_time CHAR(20);
+DECLARE start_time, query_time, lock_time, cpu_usage, delay_total CHAR(20);
 DECLARE user_host MEDIUMTEXT;
 DECLARE rows_set, rows_examined, last_insert_id, insert_id, server_id INT;
 DECLARE thread_id BIGINT UNSIGNED;
@@ -378,14 +384,16 @@ DECLARE CONTINUE HANDLER FOR ER_SP_FETCH_NO_DATA SET done = 1;
 FETCH cur1 INTO
 start_time, user_host, query_time, lock_time,
 rows_set, rows_examined, dbname, last_insert_id,
-insert_id, server_id, sql_text, thread_id;
+insert_id, server_id, sql_text, thread_id,
+cpu_usage, delay_total;
 END;
 IF NOT done THEN
 BEGIN
 INSERT INTO
 `db_17876.slow_log_data`
             VALUES(start_time, user_host, query_time, lock_time, rows_set, rows_examined,
-dbname, last_insert_id,  insert_id, server_id, sql_text, thread_id);
+dbname, last_insert_id,  insert_id, server_id, sql_text, thread_id,
+cpu_usage, delay_total);
 END;
 END IF;
 END;

mysql-test/r/log_tables_myisam.result

@@ -7,7 +7,7 @@ event_time	user_host	thread_id	server_id	command_type	argument
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	select * from general_log
 truncate table slow_log;
 select * from slow_log;
-start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
+start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id	cpu_usage	delay_total
 alter table mysql.general_log engine=myisam;
 ERROR HY000: You cannot 'ALTER' a log table if logging is enabled
 alter table mysql.slow_log engine=myisam;
@@ -44,7 +44,9 @@ slow_log	CREATE TABLE `slow_log` (
   `insert_id` int NOT NULL,
   `server_id` int unsigned NOT NULL,
   `sql_text` mediumblob NOT NULL,
-  `thread_id` bigint unsigned NOT NULL
+  `thread_id` bigint unsigned NOT NULL,
+  `cpu_usage` time(6) NOT NULL,
+  `delay_total` time(6) NOT NULL
 ) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'
 alter table mysql.general_log engine=myisam;
 alter table mysql.slow_log engine=myisam;
@@ -72,7 +74,9 @@ slow_log	CREATE TABLE `slow_log` (
   `insert_id` int NOT NULL,
   `server_id` int unsigned NOT NULL,
   `sql_text` mediumblob NOT NULL,
-  `thread_id` bigint unsigned NOT NULL
+  `thread_id` bigint unsigned NOT NULL,
+  `cpu_usage` time(6) NOT NULL,
+  `delay_total` time(6) NOT NULL
 ) ENGINE=MyISAM DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'
 set global general_log='ON';
 set global slow_query_log='ON';
@@ -138,7 +142,9 @@ ON UPDATE CURRENT_TIMESTAMP(6),
 `insert_id` int(11) NOT NULL,
 `server_id` int(10) unsigned NOT NULL,
 `sql_text` mediumblob NOT NULL,
-`thread_id` bigint(21) unsigned NOT NULL
+`thread_id` bigint(21) unsigned NOT NULL,
+`cpu_usage` time(6) NOT NULL,
+`delay_total` time(6) NOT NULL
 ) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log';
 Warnings:
 Warning	1681	Integer display width is deprecated and will be removed in a future release.

mysql-test/r/system_mysql_db.result

@@ -208,7 +208,9 @@ slow_log	CREATE TABLE `slow_log` (
   `insert_id` int NOT NULL,
   `server_id` int unsigned NOT NULL,
   `sql_text` mediumblob NOT NULL,
-  `thread_id` bigint unsigned NOT NULL
+  `thread_id` bigint unsigned NOT NULL,
+  `cpu_usage` time(6) NOT NULL,
+  `delay_total` time(6) NOT NULL
 ) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'
 show tables;
 Tables_in_test

mysql-test/suite/funcs_1/r/is_columns_mysql.result

@@ -224,6 +224,8 @@ def	mysql	slow_log	insert_id	9	NULL	NO	int	NULL	NULL	10	0	NULL	NULL	NULL	int			s
 def	mysql	slow_log	server_id	10	NULL	NO	int	NULL	NULL	10	0	NULL	NULL	NULL	int unsigned			select,insert,update,references			NULL	#
 def	mysql	slow_log	sql_text	11	NULL	NO	mediumblob	16777215	16777215	NULL	NULL	NULL	NULL	NULL	mediumblob			select,insert,update,references			NULL	#
 def	mysql	slow_log	thread_id	12	NULL	NO	bigint	NULL	NULL	20	0	NULL	NULL	NULL	bigint unsigned			select,insert,update,references			NULL	#
+def	mysql	slow_log	cpu_usage	13	NULL	NO	time	NULL	NULL	NULL	NULL	6	NULL	NULL	time(6)			select,insert,update,references			NULL	#
+def	mysql	slow_log	delay_total	14	NULL	NO	time	NULL	NULL	NULL	NULL	6	NULL	NULL	time(6)			select,insert,update,references			NULL	#
 def	mysql	tables_priv	Host	1		NO	char	255	255	NULL	NULL	NULL	ascii	ascii_general_ci	char(255)	PRI		select,insert,update,references			NULL	#
 def	mysql	tables_priv	Db	2		NO	char	64	192	NULL	NULL	NULL	utf8mb3	utf8mb3_bin	char(64)	PRI		select,insert,update,references			NULL	#
 def	mysql	tables_priv	User	3		NO	char	80	240	NULL	NULL	NULL	utf8mb3	utf8mb3_bin	char(80)	PRI		select,insert,update,references			NULL	#
@@ -588,6 +590,8 @@ NULL	mysql	slow_log	insert_id	int	NULL	NULL	NULL	NULL	int
 NULL	mysql	slow_log	server_id	int	NULL	NULL	NULL	NULL	int unsigned
 1.0000	mysql	slow_log	sql_text	mediumblob	16777215	16777215	NULL	NULL	mediumblob
 NULL	mysql	slow_log	thread_id	bigint	NULL	NULL	NULL	NULL	bigint unsigned
+NULL	mysql	slow_log	cpu_usage	time	NULL	NULL	NULL	NULL	time(6)
+NULL	mysql	slow_log	delay_total	time	NULL	NULL	NULL	NULL	time(6)
 1.0000	mysql	tables_priv	Host	char	255	255	ascii	ascii_general_ci	char(255)
 3.0000	mysql	tables_priv	Db	char	64	192	utf8mb3	utf8mb3_bin	char(64)
 3.0000	mysql	tables_priv	User	char	80	240	utf8mb3	utf8mb3_bin	char(80)

mysql-test/suite/rocksdb/r/sys_tables_mysql_db.result

@@ -209,7 +209,9 @@ slow_log	CREATE TABLE `slow_log` (
   `insert_id` int NOT NULL,
   `server_id` int unsigned NOT NULL,
   `sql_text` mediumblob NOT NULL,
-  `thread_id` bigint unsigned NOT NULL
+  `thread_id` bigint unsigned NOT NULL,
+  `cpu_usage` time(6) NOT NULL,
+  `delay_total` time(6) NOT NULL
 ) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'
 #
 # System table updates should be allowed in all binlog formats

mysql-test/suite/thread_pool/r/admission_control.result

@@ -84,6 +84,7 @@ set @@global.thread_pool_max_waiting_queries=6;
 Kill a thread that is waiting for admission.
 select count(*) from t1;
 kill ID;
+Wait for killed connection to be gone.
 set @@global.thread_pool_max_waiting_queries=5;
 Even though connection was killed before admission, pre-admission utilization is still accounted towards test_db.
 correct_utilization_1 = 1;

mysql-test/suite/thread_pool/t/admission_control.test

@@ -195,6 +195,11 @@ eval kill $id;
 disconnect killed_connection;
 
 connection default;
+--echo Wait for killed connection to be gone.
+let $wait_condition=
+  select count(*) = 0 from information_schema.processlist where id=$id;
+source include/wait_condition.inc;
+
 set @@global.thread_pool_max_waiting_queries=5;
 --echo Even though connection was killed before admission, pre-admission utilization is still accounted towards test_db.
 let $cpu_util_1_new = `select CPU_USEC from information_schema.tp_admission_control_entities where schema_name like 'test_db' order by schema_name`;

mysql-test/t/log_state.test

@@ -50,7 +50,7 @@ connection con1;
 set @long_query_time = 2;
 set session long_query_time = @long_query_time;
 select sleep(@long_query_time + 1);
---replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME 4 LOCK_TIME 11 QUERY 12 THREAD_ID
+--replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME 4 LOCK_TIME 11 QUERY 12 THREAD_ID 13 CPU_USAGE 14 DELAY_TOTAL
 select * from mysql.slow_log where sql_text NOT LIKE '%slow_log%';
 --echo # Switch to connection default
 connection default;
@@ -60,7 +60,7 @@ set global slow_query_log= ON;
 connection con1;
 set session long_query_time = @long_query_time;
 select sleep(@long_query_time + 1);
---replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME 4 LOCK_TIME 11 QUERY 12 THREAD_ID
+--replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME 4 LOCK_TIME 11 QUERY 12 THREAD_ID 13 CPU_USAGE 14 DELAY_TOTAL
 select * from mysql.slow_log where sql_text NOT LIKE '%slow_log%';
 --echo # Switch to connection default
 connection default;

mysql-test/t/log_tables.test

@@ -178,7 +178,7 @@ drop table bug16905;
 truncate table mysql.slow_log;
 set session long_query_time=1;
 select sleep(2);
---replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME 4 LOCK_TIME 11 QUERY 12 THREAD_ID
+--replace_column 1 TIMESTAMP 2 USER_HOST 3 QUERY_TIME 4 LOCK_TIME 11 QUERY 12 THREAD_ID 13 CPU_USAGE 14 DELAY_TOTAL
 select * from mysql.slow_log;
 set @@session.long_query_time = @saved_long_query_time;
 
@@ -521,7 +521,9 @@ CREATE TABLE `db_17876.slow_log_data` (
   `insert_id` int(11) default NULL,
   `server_id` int(11) default NULL,
   `sql_text` mediumblob,
-  `thread_id` bigint(21) unsigned not NULL
+  `thread_id` bigint(21) unsigned not NULL,
+  `cpu_usage` time,
+  `delay_total` time
 );
 
 CREATE TABLE `db_17876.general_log_data` (
@@ -537,7 +539,7 @@ DELIMITER //;
 
 CREATE procedure `db_17876.archiveSlowLog`()
 BEGIN
-  DECLARE start_time, query_time, lock_time CHAR(20);
+  DECLARE start_time, query_time, lock_time, cpu_usage, delay_total CHAR(20);
   DECLARE user_host MEDIUMTEXT;
   DECLARE rows_set, rows_examined, last_insert_id, insert_id, server_id INT;
   DECLARE thread_id BIGINT UNSIGNED;
@@ -558,15 +560,17 @@ BEGIN
         FETCH cur1 INTO
            start_time, user_host, query_time, lock_time,
            rows_set, rows_examined, dbname, last_insert_id,
-           insert_id, server_id, sql_text, thread_id;
+           insert_id, server_id, sql_text, thread_id,
+           cpu_usage, delay_total;
       END;
 
       IF NOT done THEN
         BEGIN
           INSERT INTO
             `db_17876.slow_log_data`
             VALUES(start_time, user_host, query_time, lock_time, rows_set, rows_examined,
-                   dbname, last_insert_id,  insert_id, server_id, sql_text, thread_id);
+                   dbname, last_insert_id,  insert_id, server_id, sql_text, thread_id,
+                   cpu_usage, delay_total);
         END;
       END IF;
     END;

mysql-test/t/log_tables_myisam.test

@@ -136,7 +136,9 @@ CREATE TABLE `slow_log` (
   `insert_id` int(11) NOT NULL,
   `server_id` int(10) unsigned NOT NULL,
   `sql_text` mediumblob NOT NULL,
-  `thread_id` bigint(21) unsigned NOT NULL
+  `thread_id` bigint(21) unsigned NOT NULL,
+  `cpu_usage` time(6) NOT NULL,
+  `delay_total` time(6) NOT NULL
 ) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log';
 
 set global general_log='ON';
@@ -146,4 +148,3 @@ TRUNCATE TABLE mysql.general_log;
 
 --enable_ps_protocol
 use test;
-

scripts/mysql_system_tables.sql

@@ -358,7 +358,7 @@ SET @@session.sql_require_primary_key = 0;
 CREATE TABLE IF NOT EXISTS general_log (event_time TIMESTAMP(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6), user_host MEDIUMTEXT NOT NULL, thread_id BIGINT UNSIGNED NOT NULL, server_id INTEGER UNSIGNED NOT NULL, command_type VARCHAR(64) NOT NULL, argument MEDIUMBLOB NOT NULL) engine=CSV CHARACTER SET utf8mb3 comment="General log";
 
 -- Create slow_log
-CREATE TABLE IF NOT EXISTS slow_log (start_time TIMESTAMP(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6), user_host MEDIUMTEXT NOT NULL, query_time TIME(6) NOT NULL, lock_time TIME(6) NOT NULL, rows_sent INTEGER NOT NULL, rows_examined INTEGER NOT NULL, db VARCHAR(512) NOT NULL, last_insert_id INTEGER NOT NULL, insert_id INTEGER NOT NULL, server_id INTEGER UNSIGNED NOT NULL, sql_text MEDIUMBLOB NOT NULL, thread_id BIGINT UNSIGNED NOT NULL) engine=CSV CHARACTER SET utf8mb3 comment="Slow log";
+CREATE TABLE IF NOT EXISTS slow_log (start_time TIMESTAMP(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6), user_host MEDIUMTEXT NOT NULL, query_time TIME(6) NOT NULL, lock_time TIME(6) NOT NULL, rows_sent INTEGER NOT NULL, rows_examined INTEGER NOT NULL, db VARCHAR(512) NOT NULL, last_insert_id INTEGER NOT NULL, insert_id INTEGER NOT NULL, server_id INTEGER UNSIGNED NOT NULL, sql_text MEDIUMBLOB NOT NULL, thread_id BIGINT UNSIGNED NOT NULL, cpu_usage TIME(6) NOT NULL, delay_total TIME(6) NOT NULL) engine=CSV CHARACTER SET utf8mb3 comment="Slow log";
 
 SET @@session.sql_require_primary_key = @old_sql_require_primary_key;
 

scripts/mysql_system_tables_fix.sql

@@ -270,6 +270,9 @@ ALTER TABLE slow_log
   ADD COLUMN thread_id INTEGER NOT NULL AFTER sql_text;
 ALTER TABLE slow_log
   MODIFY thread_id BIGINT UNSIGNED NOT NULL;
+ALTER TABLE slow_log
+  ADD COLUMN cpu_usage TIME(6) NOT NULL AFTER thread_id,
+  ADD COLUMN delay_total TIME(6) NOT NULL AFTER cpu_usage;
 SET GLOBAL slow_query_log = @old_log_state;
 
 SET @@session.sql_require_primary_key = @old_sql_require_primary_key;