thread id is logged differently in Percona Server 5.6 when log_slow_verbosity is full

[Peter Boros]

The logging format of the thread id is changed in Percona Server 5.6

# Time: 140328 9:25:23
# User@Host: sbtest[sbtest] @ bench1 [10.116.191.113] Id: 652
# Schema: sbtest Last_errno: 0 Killed: 0
# Query_time: 0.000050 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0
# Bytes_sent: 11 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
SET timestamp=1395998723;
BEGIN;

It's in the line with User@Host, Percona Server 5.5 had a separate Thread_id field. This prevents tools like pt-query-digest and percona-playback from working properly.

[Valerii Kravchuk (valerii-kravchuk)]

This is easy to confirm:

[openxs@chief p5.6]$ bin/mysql -uroot test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.16-64.2-log MySQL Community Server (GPL)

Copyright (c) 2009-2014 Percona LLC and/or its affiliates
Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select sleep(10);
+-----------+
| sleep(10) |
+-----------+
| 0 |
+-----------+
1 row in set (10.00 sec)

mysql> exit
Bye
[openxs@chief p5.6]$ tail data/chief-slow.log
# Time: 140328 12:28:58
# User@Host: root[root] @ localhost [] Id: 1
# Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000007 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0
# Bytes_sent: 0 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
SET timestamp=1396002538;
# administrator command: Quit;

Now, on 5.5:

[openxs@chief p5.6]$ cd ../p5.5
[openxs@chief p5.5]$ bin/mysqld_safe --long_query_time=0 --slow_query_log --log_slow_verbosity=full &
[1] 21118
[openxs@chief p5.5]$ 140328 12:29:52 mysqld_safe Logging to '/home/openxs/dbs/p5.5/data/chief.err'.
140328 12:29:52 mysqld_safe Starting mysqld daemon with databases from /home/openxs/dbs/p5.5/data

[openxs@chief p5.5]$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.35-debug-log MySQL Community Server (GPL)

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select sleep(10);
+-----------+
| sleep(10) |
+-----------+
| 0 |
+-----------+
1 row in set (10.00 sec)

mysql> exit
Bye
[openxs@chief p5.5]$ tail data/chief-slow.log
# Time: 140328 12:30:12
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000006 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 0 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
SET timestamp=1396002612;
# administrator command: Quit;

[Alexey Kopytov (akopytov)]

It's an upstream issue. There is the same difference between MySQL 5.5 and 5.6.

[Kenny Gryp (gryp)]

Should we then live with it and mark it as Percona Toolkit bug? (Already have a patch for this)

 I'm sure many other tools that process that will have issues with it.

[Alexey Kopytov (akopytov)]

Correction: MySQL 5.5 doesn't have thread ID in the slow query log. Percona Server 5.5 has Thread_id as an extension to the slow query log format. Both Percona Server 5.6 and MySQL 5.6 use "Id".

So the problem is in the incompatibility betweeb Percona Server 5.5 extension, and the format used by MySQL 5.6 and Percona Server 5.6.

I agree, it is unlikely that upstream will change the format to match PS 5.5, so PT should be able to live with it.

[Kenny Gryp (gryp)]

Opened Percona-Toolkit bug: https://bugs.launchpad.net/percona-toolkit/+bug/1299387

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3116