MySQL Bugs: #80553: sysschema.fn_ps_thread_trx

Bug #80553	sysschema.fn_ps_thread_trx_info test unstable
Submitted:	29 Feb 2016 9:37	Modified:	5 May 2016 4:53
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: SYS Schema	Severity:	S3 (Non-critical)
Version:	5.7.11	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	mtr, sysschema

Description:
sysschema.fn_ps_thread_trx_info is prone to failing with

sysschema.fn_ps_thread_trx_info          w4 [ fail ]
        Test ended at 2016-02-06 00:28:06

CURRENT_TEST: sysschema.fn_ps_thread_trx_info
--- /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-vivid-64bit/mysql-test/suite/sysschema/r/fn_ps_thread_trx_info.result	2016-01-11 19:33:51.010083190 +0300
+++ /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-vivid-64bit/build/mysql-test/var/4/log/fn_ps_thread_trx_info.reject	2016-02-06 00:28:06.480062623 +0300
@@ -80,7 +80,7 @@
 SET @sys.ps_thread_trx_info.max_length = 100;
 SELECT sys.ps_thread_trx_info(@ps_thread_id);
 sys.ps_thread_trx_info(@ps_thread_id)
-{ "error": "Trx info truncated: Row 12 was cut by GROUP_CONCAT()" }
+{ "error": "Trx info truncated: Row 11 was cut by GROUP_CONCAT()" }
 SET @sys.ps_thread_trx_info.max_length = NULL;
 SELECT JSON_VALID(sys.ps_thread_trx_info(@ps_thread_id));
 JSON_VALID(sys.ps_thread_trx_info(@ps_thread_id))

mysqltest: Result content mismatch

Seen more than once:
http://jenkins.percona.com/job/mysql-5.7-param/88/BUILD_TYPE=debug,Host=ubuntu-vivid-64bit...
http://jenkins.percona.com/job/mysql-5.7-param/88/BUILD_TYPE=debug,Host=ubuntu-trusty-64bi...
http://jenkins.percona.com/job/mysql-5.7-param/88/BUILD_TYPE=debug,Host=centos6-64/console...

How to repeat:
See above

I have added SELECT @json_doc to the testcase and re-run (re-recorded its output with whatever "time : " snapshot, and it seems that whenever it fails, the JSON doc will have a missing entry for COMMIT in the end:

@@ -80,12 +80,12 @@
 SET @sys.ps_thread_trx_info.max_length = 100;
 SELECT sys.ps_thread_trx_info(@ps_thread_id);
 sys.ps_thread_trx_info(@ps_thread_id)
-{ "error": "Trx info truncated: Row 12 was cut by GROUP_CONCAT()" }
+{ "error": "Trx info truncated: Row 11 was cut by GROUP_CONCAT()" }
 SELECT @json_doc;
 @json_doc
 [
   {
-    "time": "1.64 ms",
+    "time": "3.12 ms",
     "state": "COMMITTED",
     "mode": "READ WRITE",
     "autocommitted": "NO",
@@ -94,7 +94,7 @@
     "statements_executed": [
       {
         "sql_text": "INSERT INTO info VALUES (1, 'foo')",
-        "time": "1.14 ms",
+        "time": "2.15 ms",
         "schema": "trx",
         "rows_examined": 0,
         "rows_affected": 1,
@@ -106,7 +106,7 @@
       },
       {
         "sql_text": "COMMIT",
-        "time": "343.69 us",
+        "time": "220.12 us",
         "schema": "trx",
         "rows_examined": 0,
         "rows_affected": 0,
@@ -119,7 +119,7 @@
     ]
   },
   {
-    "time": "916.52 us",
+    "time": "4.71 ms",
     "state": "COMMITTED",
     "mode": "READ WRITE",
     "autocommitted": "NO",
@@ -128,25 +128,13 @@
     "statements_executed": [
       {
         "sql_text": "INSERT INTO info VALUES (2, 'bar')",
-        "time": "400.11 us",
+        "time": "4.44 ms",
         "schema": "trx",
         "rows_examined": 0,
         "rows_affected": 1,
         "rows_sent": 0,
         "tmp_tables": 0,
         "tmp_disk_tables": 0,
-        "sort_rows": 0,
-        "sort_merge_passes": 0
-      },
-      {
-        "sql_text": "COMMIT",
-        "time": "341.45 us",
-        "schema": "trx",
-        "rows_examined": 0,
-        "rows_affected": 0,
-        "rows_sent": 0,
-        "tmp_tables": 0,
-        "tmp_disk_tables": 0,
         "sort_rows": 0,
         "sort_merge_passes": 0
       }

If PFS data is accounted after the client OK is sent, the this could be a race condition between COMMIT in con1 returning, and connection default proceeding to read the json doc.

Hello Laurynas,

Thank you for the report.
Observed this with 5.7.11 src build on FC23.

Thanks,
Umesh

-- 5.7.11

[ushastry@fedora23 mysql-5.7.11]$ cmake . -DWITH_BOOST=./boost/
[ushastry@fedora23 mysql-5.7.11]$ make
[ushastry@fedora23 mysql-5.7.11]$ cd mysql-test/
[ushastry@fedora23 mysql-test]$ ./mtr sysschema.fn_ps_thread_trx_info 
Logging: ./mtr  sysschema.fn_ps_thread_trx_info
2016-03-10T07:02:41.521594Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2016-03-10T07:02:41.524851Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
MySQL Version 5.7.11
Checking supported features...
 - SSL connections supported
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/ushastry/Downloads/mysql-5.7.11/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
sysschema.fn_ps_thread_trx_info          [ fail ]
        Test ended at 2016-03-10 02:02:51

CURRENT_TEST: sysschema.fn_ps_thread_trx_info
--- /home/ushastry/Downloads/mysql-5.7.11/mysql-test/suite/sysschema/r/fn_ps_thread_trx_info.result	2016-02-02 02:31:58.000000000 +0300
+++ /home/ushastry/Downloads/mysql-5.7.11/mysql-test/var/log/fn_ps_thread_trx_info.reject	2016-03-10 10:02:51.346501827 +0300
@@ -80,7 +80,7 @@
 SET @sys.ps_thread_trx_info.max_length = 100;
 SELECT sys.ps_thread_trx_info(@ps_thread_id);
 sys.ps_thread_trx_info(@ps_thread_id)
-{ "error": "Trx info truncated: Row 12 was cut by GROUP_CONCAT()" }
+{ "error": "Trx info truncated: Row 11 was cut by GROUP_CONCAT()" }
 SET @sys.ps_thread_trx_info.max_length = NULL;
 SELECT JSON_VALID(sys.ps_thread_trx_info(@ps_thread_id));
 JSON_VALID(sys.ps_thread_trx_info(@ps_thread_id))

mysqltest: Result content mismatch

safe_process[16975]: Child process: 16976, exit: 1

 - the logfile can be found in '/home/ushastry/Downloads/mysql-5.7.11/mysql-test/var/log/sysschema.fn_ps_thread_trx_info/fn_ps_thread_trx_info.log'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 11 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): sysschema.fn_ps_thread_trx_info

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

Test case was stabilized in 5.8.0.

Do you have any plans to backport the testcase fix to 5.7?