Bug #106897 performance_schema.metadata_locks wrong value for owner_thread_id
Submitted: 2 Apr 2022 0:14 Modified: 14 Apr 2022 10:10
Reporter: Mike Griffin Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:8.0.27, 8.0.28 OS:Linux
Assigned to: Marc ALFF CPU Architecture:Any

[2 Apr 2022 0:14] Mike Griffin
Description:
It appears that the owner_thread_id is a couple thousand larger than the real thread id:

mysql> select max(owner_thread_id) from performance_schema.metadata_locks;
+----------------------+
| max(owner_thread_id) |
+----------------------+
|               518115 |
+----------------------+
1 row in set (0.00 sec)

mysql> system mysql <<< "select connection_id()"
connection_id()
516142

I believe this could lead to blaming the wrong thread:

mysql> select count(*) from performance_schema.metadata_locks; select t1.object_type, t1.lock_type, t1.lock_duration from performance_schema.metadata_locks t1 join information_schema.processlist t2 on t1.owner_thread_id=t2.id;
+----------+
| count(*) |
+----------+
|        8 |
+----------+
1 row in set (0.00 sec)

+-------------+---------------------+---------------+
| object_type | lock_type           | lock_duration |
+-------------+---------------------+---------------+
| GLOBAL      | INTENTION_EXCLUSIVE | STATEMENT     |
| TABLE       | SHARED_WRITE        | TRANSACTION   |
+-------------+---------------------+---------------+
2 rows in set (0.01 sec)

mysql> select count(*) from performance_schema.metadata_locks; select t1.object_type, t1.lock_type, t1.lock_duration from performance_schema.metadata_locks t1 join information_schema.processlist t2 on t1.owner_thread_id=t2.id;
+----------+
| count(*) |
+----------+
|       19 |
+----------+
1 row in set (0.00 sec)

Empty set (0.01 sec)

In this environment, connections do not arrive very frequently through pool reuse:

# mysqladmin -rvi 1 ex | grep Connections
| Connections                                           | 517466                                                                                                                                                                                                                                                                                                                                                                                                                                                              |
| Connections                                           | 1                                                                                                                                                                                                                                                                                                                                                                                                                                                                   |
| Connections                                           | 2                                                                                                                                                                                                                                                                                                                                                                                                                                                                   |

How to repeat:
### session 1

create database dba_test;
use dba_test;
insert into t1 select null, 'foo';
select sleep(15) from dba_test.t1 for update;

### meanwhile session 2

set session lock_wait_timeout=1;
alter table dba_test.t1 default character set utf8mb4;

### back to session 1, wait for sleep to complete

mysql> select * from performance_schema.metadata_locks where object_schema='dba_test'\G
*************************** 1. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: dba_test
          OBJECT_NAME: t1
          COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139502955417424
            LOCK_TYPE: SHARED_WRITE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE: sql_parse.cc:5902
      OWNER_THREAD_ID: 519588
       OWNER_EVENT_ID: 23
1 row in set (0.00 sec)

mysql> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|          517590 |
+-----------------+
1 row in set (0.00 sec)

mysql> rollback;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from performance_schema.metadata_locks where object_schema='dba_test'\G
Empty set (0.00 sec)

If you do this several times in the same connection, you do get a consistent but wrong owner_thread_id;
[4 Apr 2022 20:52] Mike Griffin
CREATE TABLE `t` (
  `id` bigint unsigned NOT NULL AUTO_INCREMENT,
  `foo` varchar(32) DEFAULT NULL,
  UNIQUE KEY `id` (`id`)
) ENGINE=InnoDB;

INSERT INTO `t` VALUES (1,'foo');

BEGIN;

SELECT foo FROM t FOR UPDATE INTO @x;

SELECT * FROM performance_schema.metadata_locks WHERE object_schema='test';

SELECT CONNECTION_ID();

ROLLBACK;

DROP TABLE IF EXISTS t;
[9 Apr 2022 8:11] MySQL Verification Team
Hello Mike Griffin,

Thank you for the report.

Thanks,
Umesh
[14 Apr 2022 9:40] Marc ALFF
Please note that 'THREAD_ID' columns and related, like OWNER_THREAD_ID,
are different from 'PROCESSLIST_ID'.

mysql> use test;
Database changed
mysql> 
mysql> CREATE TABLE `t` (
    ->   `id` bigint unsigned NOT NULL AUTO_INCREMENT,
    ->   `foo` varchar(32) DEFAULT NULL,
    ->   UNIQUE KEY `id` (`id`)
    -> ) ENGINE=InnoDB;
Query OK, 0 rows affected (0.02 sec)

mysql> 
mysql> INSERT INTO `t` VALUES (1,'foo');
Query OK, 1 row affected (0.01 sec)

mysql> 
mysql> BEGIN;
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> SELECT foo FROM t FOR UPDATE INTO @x;
Query OK, 1 row affected (0.00 sec)

mysql> 
mysql> SELECT * FROM performance_schema.metadata_locks WHERE object_schema='test';
+-------------+---------------+-------------+-------------+-----------------------+--------------+---------------+-------------+-------------------+-----------------+----------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | COLUMN_NAME | OBJECT_INSTANCE_BEGIN | LOCK_TYPE    | LOCK_DURATION | LOCK_STATUS | SOURCE            | OWNER_THREAD_ID | OWNER_EVENT_ID |
+-------------+---------------+-------------+-------------+-----------------------+--------------+---------------+-------------+-------------------+-----------------+----------------+
| TABLE       | test          | t           | NULL        |       140352095361648 | SHARED_WRITE | TRANSACTION   | GRANTED     | sql_parse.cc:6008 |              52 |          20540 |
+-------------+---------------+-------------+-------------+-----------------------+--------------+---------------+-------------+-------------------+-----------------+----------------+
1 row in set (0.00 sec)

mysql> 
mysql> SELECT CONNECTION_ID(), PS_CURRENT_THREAD_ID();
+-----------------+------------------------+
| CONNECTION_ID() | PS_CURRENT_THREAD_ID() |
+-----------------+------------------------+
|              12 |                     52 |
+-----------------+------------------------+
1 row in set (0.00 sec)

mysql> 
mysql> SELECT THREAD_ID, NAME, PROCESSLIST_ID
    ->    FROM performance_schema.threads
    ->   WHERE PROCESSLIST_ID = CONNECTION_ID();
+-----------+---------------------------+----------------+
| THREAD_ID | NAME                      | PROCESSLIST_ID |
+-----------+---------------------------+----------------+
|        52 | thread/sql/one_connection |             12 |
+-----------+---------------------------+----------------+
1 row in set (0.00 sec)

mysql> 
mysql> SELECT THREAD_ID, NAME, PROCESSLIST_ID
    ->    FROM performance_schema.threads
    ->   WHERE THREAD_ID = PS_CURRENT_THREAD_ID();
+-----------+---------------------------+----------------+
| THREAD_ID | NAME                      | PROCESSLIST_ID |
+-----------+---------------------------+----------------+
|        52 | thread/sql/one_connection |             12 |
+-----------+---------------------------+----------------+
1 row in set (0.00 sec)

mysql> 
mysql> ROLLBACK;
Query OK, 0 rows affected (0.00 sec)

mysql> 
mysql> DROP TABLE IF EXISTS t;
Query OK, 0 rows affected (0.01 sec)
[14 Apr 2022 10:09] Marc ALFF
To clarify,

The following are all 'PROCESSLIST_ID':
- Column ID in INFORMATION_SCHEMA.PROCESSLIST
- Column ID in SHOW PROCESSLIST
- Column ID in performance_schema.processlist
- native function CONNECTION_ID()
- Column PROCESSLIST_ID in performance_schema.threads;

The following are all 'THREAD_ID':
- Column THREAD_ID in performance_schema.threads
- Column THREAD_ID in performance_schema tables in general
- Column OWNER_THREAD_ID in performance_schema.metadata_locks
- native function PS_CURRENT_THREAD_ID()

THREAD_ID and PROCESSLIST_ID are different, and can not be compared or joined.

See also the native function PS_THREAD_ID(connection_id)

Instead of joining:
- column OWNER_THREAD_ID in performance_schema.metadata_locks
- column ID in information_schema.processlist
which compares a THREAD_ID with a PROCESSLIST_ID (incorrect),
use:
- column OWNER_THREAD_ID in performance_schema.metadata_locks
- column THREAD_ID in performance_schema.threads

Instead of using:
- native function CONNECTION_ID()
use:
- native function PS_CURRENT_THREAD_ID()
to get the thread_id of the current session.

Closing as not a bug, since the server works as expected.

Thanks for the detailed report and test case.