Add server_cpu and warnings to query response attributes

Summary:
This diff adds server CPU time to query response attributes. The key of the attribute is "server_cpu" and the value is the stringified version of the cpu time.

This diff also adds warnings information to query response attributes. The key of the attribute is "warnings" and the value is the string that serializes the warnings information. Since there could be more than one warnings for a statement, the value is a list of pairs included with in brackets separated by commas. The first value of the pair is the error number (code) and the second value of the pair is the message text and these are separated by a comma.

The following example shows the query response attribute for 'warnings' where two warnings are raised for the statement:
**1265,Data truncated for column 'c1' at row 1),(1264,Out of range value for column 'c2' at row 1)**

The variable 'response_attrs_contain_warnings' controls this feature and is disabled by default.

If the query raises any errors then the response OK packet is not set to the client. So in this case putting warnings into response attributes is skipped.

Reviewed By: george-reynya

Differential Revision: D26598990

Author: Satya Valluri

Diff for: include/mysql/components/services/psi_statement_bits.h

@@ -586,6 +586,14 @@ typedef struct PSI_digest_locker *(*digest_start_v1_t)(
 typedef void (*digest_end_v1_t)(struct PSI_digest_locker *locker,
                                 const struct sql_digest_storage *digest);
 
+/**
+  Set a statement event cpu time.
+  @param locker the statement locker
+  @param cpu_time the cpu time, in microseconds
+*/
+typedef unsigned long long (*get_statement_cpu_time_v1_t)(
+    struct PSI_statement_locker *locker);
+
 /**
   Acquire a sp share instrumentation.
   @param object_type type of stored program

Diff for: include/mysql/components/services/psi_statement_service.h

@@ -117,6 +117,8 @@ digest_start_v1_t digest_start;
 /** @sa digest_end_v1_t. */
 digest_end_v1_t digest_end;
 
+/** @sa get_statement_cpu_time_v1_t. */
+get_statement_cpu_time_v1_t get_statement_cpu_time;
 /** @sa get_sp_share_v1_t. */
 get_sp_share_v1_t get_sp_share;
 /** @sa release_sp_share_v1_t. */
@@ -218,6 +220,8 @@ digest_start_v1_t digest_start;
 /** @sa digest_end_v1_t. */
 digest_end_v1_t digest_end;
 
+/** @sa get_statement_cpu_time_v1_t. */
+get_statement_cpu_time_v1_t get_statement_cpu_time;
 /** @sa get_sp_share_v1_t. */
 get_sp_share_v1_t get_sp_share;
 /** @sa release_sp_share_v1_t. */

Diff for: include/mysql/psi/mysql_statement.h

@@ -227,6 +227,13 @@ struct CHARSET_INFO;
   } while (0)
 #endif
 
+#ifdef HAVE_PSI_STATEMENT_INTERFACE
+#define MYSQL_GET_STATEMENT_CPU_TIME(LOCKER) \
+  inline_mysql_get_statement_cpu_time(LOCKER)
+#else
+#define MYSQL_GET_STATEMENT_CPU_TIME(LOCKER) 0
+#endif
+
 static inline void inline_mysql_statement_register(
 #ifdef HAVE_PSI_STATEMENT_INTERFACE
     const char *category, PSI_statement_info *info, int count
@@ -386,6 +393,16 @@ static inline void inline_mysql_end_statement(
 }
 #endif
 
+static inline unsigned long long inline_mysql_get_statement_cpu_time(
+    PSI_statement_locker *locker) {
+  unsigned long long cpu_time = 0;
+
+  if (likely(locker != nullptr)) {
+    cpu_time = PSI_STATEMENT_CALL(get_statement_cpu_time)(locker);
+  }
+  return cpu_time;
+}
+
 /** @} (end of group psi_api_statement) */
 
 #endif

Diff for: include/mysql/psi/psi_abi_statement_v1.h.pp

@@ -190,6 +190,8 @@
     struct PSI_statement_locker *locker);
 typedef void (*digest_end_v1_t)(struct PSI_digest_locker *locker,
                                 const struct sql_digest_storage *digest);
+typedef unsigned long long (*get_statement_cpu_time_v1_t)(
+    struct PSI_statement_locker *locker);
 typedef struct PSI_sp_share *(*get_sp_share_v1_t)(
     unsigned int object_type, const char *schema_name,
     unsigned int schema_name_length, const char *object_name,
@@ -253,6 +255,7 @@
   set_prepared_stmt_text_v1_t set_prepared_stmt_text;
   digest_start_v1_t digest_start;
   digest_end_v1_t digest_end;
+  get_statement_cpu_time_v1_t get_statement_cpu_time;
   get_sp_share_v1_t get_sp_share;
   release_sp_share_v1_t release_sp_share;
   start_sp_v1_t start_sp;

Diff for: include/mysql/psi/psi_statement.h

@@ -154,6 +154,8 @@ struct PSI_statement_service_v2 {
   /** @sa digest_end_v1_t. */
   digest_end_v1_t digest_end;
 
+  /** @sa get_statement_cpu_time_v1_t. */
+  get_statement_cpu_time_v1_t get_statement_cpu_time;
   /** @sa get_sp_share_v1_t. */
   get_sp_share_v1_t get_sp_share;
   /** @sa release_sp_share_v1_t. */

Diff for: include/pfs_statement_provider.h

@@ -166,6 +166,8 @@ PSI_digest_locker *pfs_digest_start_v2(PSI_statement_locker *locker);
 void pfs_digest_end_v2(PSI_digest_locker *locker,
                        const sql_digest_storage *digest);
 
+unsigned long long pfs_get_statement_cpu_time_v2(PSI_statement_locker *locker);
+
 #endif /* WITH_LOCK_ORDER */
 #endif /* MYSQL_DYNAMIC_PLUGIN */
 #endif /* MYSQL_SERVER || PFS_DIRECT_CALL */

Diff for: mysql-test/r/mysqld--help-notwin.result

@@ -1606,6 +1606,22 @@ The following options may be given as the first argument:
  pair - 'hlc_ts' is the key and the value is the
  stringified HLC timestamp. Note that HLC should be
  enabled by setting enable_binlog_hlc
+ --response-attrs-contain-server-cpu 
+ If this is enabled, then the server CPU time of the query
+ is sent back to clients as part of OK packet in session
+ response attribute. Server CPU time is sent as a
+ key-value pair - 'server_cpu' is the key and the value is
+ the stringified server CPU time.
+ --response-attrs-contain-warnings-bytes[=#] 
+ Specifies the size of the warnings information (specified
+ in bytes)  that can be included in the query response
+ attributes. The warnings are sent as a key-value pair -
+ 'warnings' is the key and the value is a list of pairs
+ included with in brackets separated by commas. The first
+ value of the pair is the error number (code) and the
+ second  value of the pair is the message text and these
+ are separated by a comma. The default value is 0 which
+ disables this feature
  --rocksdb[=name]    Enable or disable ROCKSDB plugin. Possible values are ON,
  OFF, FORCE (don't start if the plugin fails to load).
  --rocksdb-access-hint-on-compaction-start=# 
@@ -3107,6 +3123,8 @@ require-secure-transport FALSE
 reset-period-status-vars FALSE
 reset-seconds-behind-master TRUE
 response-attrs-contain-hlc FALSE
+response-attrs-contain-server-cpu FALSE
+response-attrs-contain-warnings-bytes 0
 rocksdb ON
 rocksdb-access-hint-on-compaction-start 1
 rocksdb-active-compaction-stats ON

Diff for: mysql-test/r/session_attrs_contain_server_cpu.result

@@ -0,0 +1,69 @@
+
+# Test server_cpu query response attribute
+
+use test;
+create table mytbl (a int, b int, c int, d int, e int);
+insert into mytbl values (1, 2, 3, 4, 5);
+insert into mytbl values (1, 2, 3, 4, 5);
+insert into mytbl values (1, 2, 3, 4, 5);
+insert into mytbl values (1, 2, 3, 4, 5);
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+insert into mytbl select * from mytbl;
+SET @@session.session_track_response_attributes = on;
+# Case 1: session level variable is default, i.e. FALSE
+set @@session.response_attrs_contain_server_cpu = default;
+select * from mytbl;
+Did not find server_cpu in query response attributes
+# Case 2: session level variable is TRUE
+set @@session.response_attrs_contain_server_cpu = true;
+select * from mytbl;
+Found valid value for server_cpu in query response attributes
+set @@session.response_attrs_contain_server_cpu = default;
+# Case 4: global level variable is TRUE but session is FALSE
+set @@global.response_attrs_contain_server_cpu = true;
+select a,b from mytbl;
+Did not find server_cpu in query response attributes
+set @@global.response_attrs_contain_server_cpu = default;
+
+# Test multistatement query
+
+use test;
+# Case 1: session level variable is default, i.e. FALSE
+set @@session.response_attrs_contain_server_cpu = default;
+select * from mytbl where a > 1;
+select * from mytbl where b > 1;
+select * from mytbl where c > 1;
+select * from mytbl where d > 1;
+select * from mytbl where e > 1;
+||||
+Did not find server_cpu in query response attributes
+# Case 2: session level variable is TRUE
+set @@session.response_attrs_contain_server_cpu = true;
+select * from mytbl where a > 1;
+select * from mytbl where b > 1;
+select * from mytbl where c > 1;
+select * from mytbl where d > 1;
+select * from mytbl where e > 1;
+||||
+Found valid value for server_cpu in query response attributes
+set @@session.response_attrs_contain_server_cpu = default;
+# Case 4: global level variable is TRUE but session is FALSE
+set @@global.response_attrs_contain_server_cpu = true;
+select * from mytbl where a > 1;
+select * from mytbl where b > 1;
+select * from mytbl where c > 1;
+select * from mytbl where d > 1;
+select * from mytbl where e > 1;
+||||
+Did not find server_cpu in query response attributes
+set @@global.response_attrs_contain_server_cpu = default;
+use test;
+drop table if exists mytbl;

Diff for: mysql-test/r/session_attrs_contain_warnings_bytes.result

@@ -0,0 +1,84 @@
+
+# Test server_cpu query response attribute
+
+use test;
+create table mytbl (c1 char(8) PRIMARY KEY, c2 int);
+SET @@session.session_track_response_attributes = on;
+# Test 1: session level variable is default, i.e. 0
+There should be no warnings present in the response
+set @@session.response_attrs_contain_warnings_bytes = default;
+explain select * from mytbl;
+id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered	Extra
+1	SIMPLE	mytbl	NULL	ALL	NULL	NULL	NULL	NULL	1	100.00	NULL
+Warnings:
+Note	1003	/* select#1 */ select `test`.`mytbl`.`c1` AS `c1`,`test`.`mytbl`.`c2` AS `c2` from `test`.`mytbl`
+[X] Did not find warnings in query response attributes
+# Test 2: session level variable is 1 MB
+There should be two warnings present in the response
+set @@session.response_attrs_contain_warnings_bytes = 1048576;
+explain select * from mytbl;
+id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered	Extra
+1	SIMPLE	mytbl	NULL	ALL	NULL	NULL	NULL	NULL	1	100.00	NULL
+Warnings:
+Note	1003	/* select#1 */ select `test`.`mytbl`.`c1` AS `c1`,`test`.`mytbl`.`c2` AS `c2` from `test`.`mytbl`
+[^] Warnings in query response attributes: (1003,/* select#1 */ select `test`.`mytbl`.`c1` AS `c1`,`test`.`mytbl`.`c2` AS `c2` from `test`.`mytbl`)
+# Test 5: session level variable is 5 bytes
+Warnings should be truncated to just message codes in the
+response since they exceed the bytes limit
+set @@session.response_attrs_contain_warnings_bytes = 5;
+explain select * from mytbl;
+id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered	Extra
+1	SIMPLE	mytbl	NULL	ALL	NULL	NULL	NULL	NULL	1	100.00	NULL
+Warnings:
+Note	1003	/* select#1 */ select `test`.`mytbl`.`c1` AS `c1`,`test`.`mytbl`.`c2` AS `c2` from `test`.`mytbl`
+[^] Warnings in query response attributes: (1003,)
+# Test 6: session level variable is 0, i.e., disabled
+There should be no warnings present in the response
+set @@session.response_attrs_contain_warnings_bytes = 0;
+explain select * from mytbl;
+id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered	Extra
+1	SIMPLE	mytbl	NULL	ALL	NULL	NULL	NULL	NULL	1	100.00	NULL
+Warnings:
+Note	1003	/* select#1 */ select `test`.`mytbl`.`c1` AS `c1`,`test`.`mytbl`.`c2` AS `c2` from `test`.`mytbl`
+[X] Did not find warnings in query response attributes
+Set variables to raise an additional warning for long running queries
+set @@GLOBAL.write_cpu_limit_milliseconds=1;
+set @@GLOBAL.write_control_level=NOTE;
+set @@GLOBAL.write_time_check_batch=3;
+set @@global.debug= '+d,dbug.force_long_running_query';
+# Test 7: session level variable is default, i.e. 0
+There should be no warnings present in the response
+set @@session.response_attrs_contain_warnings_bytes = default;
+insert into mytbl values('a1a1', -1), ('a2a2', -1), ('a3a3', -1);
+Warnings:
+Note	50091	Write CPU time exceeded (controlled by write_cpu_limit_milliseconds)
+[X] Did not find warnings in query response attributes
+# Test 8: session level variable is 1 MB
+There should be two warnings present in the response
+set @@session.response_attrs_contain_warnings_bytes = 1048576;
+insert into mytbl values('b1b1', -1), ('b2b2', -1), ('b3b3', -1);
+Warnings:
+Note	50091	Write CPU time exceeded (controlled by write_cpu_limit_milliseconds)
+[^] Warnings in query response attributes: (50091,Write CPU time exceeded (controlled by write_cpu_limit_milliseconds))
+# Test 9: session level variable is 5 bytes
+Warnings should be truncated to just message codes in the
+response since they exceed the bytes limit
+set @@session.response_attrs_contain_warnings_bytes = 5;
+insert into mytbl values('c1c1', -1), ('c2c2', -1), ('c3c3', -1);
+Warnings:
+Note	50091	Write CPU time exceeded (controlled by write_cpu_limit_milliseconds)
+[^] Warnings in query response attributes: (50091,)
+# Test 10: session level variable is 0, i.e., disabled
+There should be no warnings present in the response
+set @@session.response_attrs_contain_warnings_bytes = 0;
+insert into mytbl values('d1d1', -1), ('d2d2', -1), ('d3d3', -1);
+Warnings:
+Note	50091	Write CPU time exceeded (controlled by write_cpu_limit_milliseconds)
+[X] Did not find warnings in query response attributes
+set @@global.debug= '-d,dbug.force_long_running_query';
+set @@GLOBAL.write_control_level=OFF;
+set @@GLOBAL.write_cpu_limit_milliseconds=0;
+set @@GLOBAL.write_time_check_batch=0;
+set @@session.response_attrs_contain_warnings_bytes = default;
+use test;
+drop table if exists mytbl;