Bug #115285 log_slow_extra duplicates session number in Id and Thread_id
Submitted: 11 Jun 16:56 Modified: 12 Jun 9:37
Reporter: Jean-François Gagné Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[11 Jun 16:56] Jean-François Gagné
Description:
Hi,

when using log_slow_extra, the session number / thread id is logged in both in Id and Thread_id fields.  I would expect it to be logged only once, and Thread_id is probably the redundant place.  See How to repeat for details.

How to repeat is for 8.4.0, but 8.0.37 shows the same behavior.

We can see, by code inspection, that Id and Thread_id contains the same information (thd->thread_id()): [1] for Id and [2] for Thread_id.

[1]: https://github.com/mysql/mysql-server/blob/mysql-8.4.0/sql/log.cc#L713

[2]: https://github.com/mysql/mysql-server/blob/mysql-8.4.0/sql/log.cc#L767

Related: Bug#89637 and WL#12393.

Removing Thread_id would be a breaking change, it could be done at the same time as fields are added to the slow log, see Bug#114961 for such feature request.

Many thanks for looking into this,

Jean-François Gagné

How to repeat:
dbdeployer deploy single 8.4.0 -c slow_query_log_file=slow.log -c slow_query_log=ON -c long_query_time=0.5 -c log_slow_extra=ON

./use <<< "create database test_jfg;use test_jfg; create table t(id int); insert into t value(1)"
./use test_jfg <<< "select sleep(1), t.* from t" > /dev/null

# In below, we have "Id:" and "Thread_id:" containing the same information.
cat data/slow.log 
/Users/jf.gagne/opt/mysql/8.4.0/bin/mysqld, Version: 8.4.0 (MySQL Community Server - GPL). started with:
Tcp port: 8400  Unix socket: /var/folders/6_/_y6fmz_n7wg0scgh8dddgndr0000gn/T/mysql_sandbox8400.sock
Time                 Id Command    Argument
# Time: 2024-06-11T16:44:57.950545Z
# User@Host: msandbox[msandbox] @ localhost []  Id:    14
# Query_time: 1.003275  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 1 Thread_id: 14 Errno: 0 Killed: 0 Bytes_received: 34 Bytes_sent: 98 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 2 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2024-06-11T16:44:56.947270Z End: 2024-06-11T16:44:57.950545Z
use test_jfg;
SET timestamp=1718124296;
select sleep(1), t.* from t;
[12 Jun 9:37] MySQL Verification Team
Salut, Monsieur Gagne,

Thank you for your bug report.

We have managed to repeat the problem with both 8.0 and 8.4.

This is now a verified bug for version 8.0 and higher.

Thanks.