| Bug #91743 | performance_schema.data_locks not working correctly | ||
|---|---|---|---|
| Submitted: | 20 Jul 2018 15:23 | Modified: | 13 Nov 2018 15:09 |
| Reporter: | chen chen (OCA) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Documentation | Severity: | S2 (Serious) |
| Version: | 8.0.11 | OS: | Red Hat (7.4) |
| Assigned to: | CPU Architecture: | Any | |
[20 Jul 2018 15:33]
chen chen
furthermore,i killed the session2 session3> kill 101; Query OK, 0 rows affected (0.02 sec) session3> show processlist; +-----+-----------------+-----------+------+---------+--------+------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-----------------+-----------+------+---------+--------+------------------------+------------------+ | 4 | event_scheduler | localhost | NULL | Daemon | 311456 | Waiting on empty queue | NULL | | 39 | root | localhost | NULL | Sleep | 139 | | NULL | | 123 | root | localhost | NULL | Query | 0 | starting | show processlist | +-----+-----------------+-----------+------+---------+--------+------------------------+------------------+ 3 rows in set (0.00 sec) check the result again # mysql -e "show engine innodb status\G" | awk '/TRANSACTIONS/,/FILE/' && mysql -e "select engine_lock_id,thread_id,event_id,object_name,inde x_name,lock_type,lock_mode,lock_status,lock_data from performance_schema.data_locks;"TRANSACTIONS ------------ Trx id counter 213931 Purge done for trx's n:o < 213929 undo n:o < 0 state: running but idle History list length 44 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421812853168888, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 213929, ACTIVE 839 sec 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 39, OS thread handle 140337863264000, query id 560 localhost root Trx read view will not see trx with id >= 213931, sees < 213931 TABLE LOCK table `slowtech`.`t1` trx id 213929 lock mode IX RECORD LOCKS space id 205 page no 4 n bits 72 index PRIMARY of table `slowtech`.`t1` trx id 213929 lock_mode X locks rec but not gap Record lock, heap no 5 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 8000000b; asc ;; 1: len 6; hex 0000000343a9; asc C ;; 2: len 7; hex 820000014e0110; asc N ;; 3: len 4; hex 80000029; asc );; 4: len 4; hex 8000002a; asc *;; -------- FILE I/O +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | engine_lock_id | thread_id | event_id | object_name | index_name | lock_type | lock_mode | lock_status | lock_data | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | 213929:1262 | 76 | 68 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 213929:205:4:5 | 138 | 13 | t1 | PRIMARY | RECORD | X | GRANTED | 11 | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ well,the session2 disappeared,but performance_schema.data_locks still displayed than session2 granted the lock,different form the output of "show engine innodb status" I believe the session1 should grant the lock,not session2.
[23 Jul 2018 8:24]
Jakub Lopuszanski
Thank you for report! Here are my notes from my attempt at replication. 1. remember to add `set global innodb_status_output_locks = ON;` as otherwise the output of show enginge innodb status does not contain details about particular locks. 2. it helps to set `set innodb_lock_wait_timeout = 1000000;` to avoid timeout while investigating 3. I used e35a454ae20 which was a commit on which my fix for Bug #28176805 PERFORMANCE_SCHEMA.DATA_LOCKS.LOCK_MODE DOES NOT RECOGNIZE LOCK_REC_NOT_GAP was based. My intention was to check if this bugfix introduced the problem or not (probably not, as reporter set Version to 8.0.11 and my bugfix was in 8.0.13, but one can not be too sure). 4. The output I've got was something like this: +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | engine_lock_id | thread_id | event_id | object_name | index_name | lock_type | lock_mode | lock_status | lock_data | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | 2127:1061 | 62 | 6 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 2127:3:4:5 | 62 | 8 | t1 | PRIMARY | RECORD | S | WAITING | 11 | | 2126:1061 | 51 | 10 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 2126:3:4:5 | 62 | 6 | t1 | PRIMARY | RECORD | X | GRANTED | 11 | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ which is similar to the original report. My interpretation is that if you look at the `engine_lock_id` column and try to interpret it, then it looks like there are two transactions 2127 and 2126 involved and each has 2 locks, which are exactly the locks one would expect (except for the fact that before fixing BUG#28176805 we have reported X,REC_NOT_GAP as X). The problem is only with column thread_id as it looks like there are 3 locks created by one thread. In fact this is quite accurate because the implicit-to-explicit conversion happens in the thread which is interested in adding the new lock, and not necessarily by the owner of implicit lock. So perhaps what is confusing here is the semantic of `thread_id` column: is it the thread owning the lock, or the thread which performed the event? I'll investigate it further.
[23 Jul 2018 8:31]
Jakub Lopuszanski
The documentation for data_locks table https://dev.mysql.com/doc/refman/8.0/en/data-locks-table.html does not help to clear the confusion, as description for THREAD_ID might suggest to the reader that THREAD_ID is the owner of the lock, but description for EVENT_ID suggests that THREAD_ID is simply a first element of a pair identifying the event and thus says more about the event of creating the lock, and not about ownership of the lock itself: THREAD_ID The thread ID of the that owns the lock. To obtain details about the thread, join this column with the THREAD_ID column of the Performance Schema threads table. EVENT_ID The Performance Schema event that caused the lock. Tuples of (THREAD_ID, EVENT_ID) values implicitly identify a parent event in other Performance Schema tables: The parent wait event in events_waits_xxx tables The parent stage event in events_stages_xxx tables The parent statement event in events_statements_xxx tables The parent transaction event in events_transactions_xxx tables To obtain details about the parent event, join the THREAD_ID and EVENT_ID columns with the columns of like name in the appropriate parent event table.
[23 Jul 2018 8:40]
Jakub Lopuszanski
It seems to me that the column `THREAD_ID` is populated by `Innodb_data_lock_iterator::scan_trx` which uses `lock_get_psi_event(lock, &thread_id, &event_id)` to extract the information about `thread_id` from instance of `lock`. The `lock_get_psi_event` uses:
*thread_id = lock->m_psi_internal_thread_id;
to extract this information. This field is described in terms of creator, not the owner:
/** Performance schema thread that created the lock. */
ulonglong m_psi_internal_thread_id;
and indeed it is filled with current thread id during lock creation in `RecLock::lock_add` using `pfs_get_thread_event_id_v1` which uses `my_thread_get_THR_PFS()->m_thread_internal_id` which has nothing to do with the `lock` instance itself, and more with the currently running thread.
So, one could argue that the problem is in documentation or naming of the column, as they suggest that the column stores the owner of the lock, while in fact this is merely the thread which happened to create the lock (in this case: on behalf of the implicit owner)
[23 Jul 2018 8:44]
Jakub Lopuszanski
I've verified that the code which contains a fix for BUG#28176805 produces output like this: +----------------+-----------+----------+-------------+------------+-----------+---------------+-------------+-----------+ | engine_lock_id | thread_id | event_id | object_name | index_name | lock_type | lock_mode | lock_status | lock_data | +----------------+-----------+----------+-------------+------------+-----------+---------------+-------------+-----------+ | 2570:1061 | 52 | 4 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 2570:3:4:5 | 52 | 4 | t1 | PRIMARY | RECORD | S | WAITING | 11 | | 2569:1061 | 49 | 7 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 2569:3:4:5 | 52 | 4 | t1 | PRIMARY | RECORD | X,REC_NOT_GAP | GRANTED | 11 | +----------------+-----------+----------+-------------+------------+-----------+---------------+-------------+-----------+ so the `LOCK_MODE` is shown as X,REC_NOT_GAP, but the `THREAD_ID` is still the thread which created the lock, not the one who owns it.
[23 Jul 2018 8:55]
Jakub Lopuszanski
I've realized that my description is still confusing in that I've used term "thread which created the lock" without specifying further that in InnoDB a single record lock structure can hold information about several rows, and thus it is not clear if I meant "creator of the structure which holds multiple locks" or "creator of the lock on a particular record". From my understanding of the code, we store the thread_id at the moment of creation of the data structure, so THREAD_ID is the thread which happened to be the first one to create the struct. This can mean that in some more complicated scenarios there might be 3 threads involved: A) the owner of the record lock B) the thread which performed the implicit to explicit conversion for the given record lock C) the thread which created the struct instance My understanding is that THREAD_ID column stores C.
[23 Jul 2018 13:00]
MySQL Verification Team
HI, Based on the discussion, it is evident that this is a documentation bug, that requires much more verbose explanation of the meaning of each column in those P_S tables. Verified.
[30 Jul 2018 15:29]
Jakub Lopuszanski
If one is interested in the transaction which is the requester of the particular lock (in other words: lock->trx->id) then one can use column ENGINE_TRANSACTION_ID. In case of the transaction has not performed any write operation (is still considered read-only) this column contains some internal data one should not try to interpret, but in other cases this is simply the id of transaction, which I believe is what the filer of the bug was looking for.
[13 Nov 2018 15:09]
Paul DuBois
Posted by developer: At https://dev.mysql.com/doc/refman/8.0/en/data-locks-table.html I updated the ENGINE_TRANSACTION_ID and THREAD_ID column descriptions with info from: [30 Jul 15:29] Jakub Lopuszanski From that comment, it sounds like you want ENGINE_TRANSACTION_ID.
Description: The newly introduced performance_schema.data_locks can't get the desired result. Here it is mysql> show create table slowtech.t1\G *************************** 1. row *************************** Table: t1 Create Table: CREATE TABLE `t1` ( `id` int(11) NOT NULL, `c1` int(11) DEFAULT NULL, `c2` int(11) DEFAULT NULL, PRIMARY KEY (`id`), KEY `c1` (`c1`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci 1 row in set (0.00 sec) mysql> select * from slowtech.t1; +----+------+------+ | id | c1 | c2 | +----+------+------+ | 1 | 11 | 12 | | 5 | 21 | 22 | | 10 | 31 | 32 | +----+------+------+ 3 rows in set (0.00 sec) set global innodb_table_locks=1; session1> begin; Query OK, 0 rows affected (0.00 sec) session1> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 39 | +-----------------+ 1 row in set (0.00 sec) session1> insert into slowtech.t1 values(11,41,42); Query OK, 1 row affected (0.00 sec) then i check the "TRANSACTIONS" section in "show engine innodb status" and performance_schema.data_locks. ------------------------------------------- [root@slowtech ~]# mysql -e "show engine innodb status\G" | awk '/TRANSACTIONS/,/FILE/' && mysql -e "select engine_lock_id,thread_id,event_id,object_name,inde x_name,lock_type,lock_mode,lock_status,lock_data from performance_schema.data_locks;"TRANSACTIONS ------------ Trx id counter 213929 Purge done for trx's n:o < 213929 undo n:o < 0 state: running but idle History list length 44 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421812853169808, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421812853168888, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 213924, ACTIVE 161 sec 1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1 MySQL thread id 39, OS thread handle 140337863264000, query id 529 localhost root TABLE LOCK table `slowtech`.`t1` trx id 213924 lock mode IX -------- FILE I/O +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | engine_lock_id | thread_id | event_id | object_name | index_name | lock_type | lock_mode | lock_status | lock_data | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | 213924:1262 | 76 | 52 | t1 | NULL | TABLE | IX | GRANTED | NULL | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ ----------------------------------------------- it seems the insert get a implicit lock. then i tried to insert another record session2> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 101 | +-----------------+ 1 row in set (0.00 sec) session2> insert into slowtech.t1 values(11,41,42); it blocked ... check related info again ------------------------------------------ [root@slowtech ~]# mysql -e "show engine innodb status\G" | awk '/TRANSACTIONS/,/FILE/' && mysql -e "select engine_lock_id,thread_id,event_id,object_name,inde x_name,lock_type,lock_mode,lock_status,lock_data from performance_schema.data_locks;"TRANSACTIONS ------------ Trx id counter 213931 Purge done for trx's n:o < 213929 undo n:o < 0 state: running but idle History list length 44 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421812853169808, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 213930, ACTIVE 7 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 101, OS thread handle 140337721857792, query id 550 localhost root update insert into slowtech.t1 values(11,41,42) ------- TRX HAS BEEN WAITING 7 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 205 page no 4 n bits 72 index PRIMARY of table `slowtech`.`t1` trx id 213930 lock mode S waiting Record lock, heap no 5 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 8000000b; asc ;; 1: len 6; hex 0000000343a9; asc C ;; 2: len 7; hex 820000014e0110; asc N ;; 3: len 4; hex 80000029; asc );; 4: len 4; hex 8000002a; asc *;; ------------------ TABLE LOCK table `slowtech`.`t1` trx id 213930 lock mode IX RECORD LOCKS space id 205 page no 4 n bits 72 index PRIMARY of table `slowtech`.`t1` trx id 213930 lock mode S waiting Record lock, heap no 5 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 8000000b; asc ;; 1: len 6; hex 0000000343a9; asc C ;; 2: len 7; hex 820000014e0110; asc N ;; 3: len 4; hex 80000029; asc );; 4: len 4; hex 8000002a; asc *;; ---TRANSACTION 213929, ACTIVE 99 sec 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 39, OS thread handle 140337863264000, query id 547 localhost root TABLE LOCK table `slowtech`.`t1` trx id 213929 lock mode IX RECORD LOCKS space id 205 page no 4 n bits 72 index PRIMARY of table `slowtech`.`t1` trx id 213929 lock_mode X locks rec but not gap Record lock, heap no 5 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 8000000b; asc ;; 1: len 6; hex 0000000343a9; asc C ;; 2: len 7; hex 820000014e0110; asc N ;; 3: len 4; hex 80000029; asc );; 4: len 4; hex 8000002a; asc *;; -------- FILE I/O +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | engine_lock_id | thread_id | event_id | object_name | index_name | lock_type | lock_mode | lock_status | lock_data | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ | 213930:1262 | 138 | 13 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 213930:205:4:5 | 138 | 13 | t1 | PRIMARY | RECORD | S | WAITING | 11 | | 213929:1262 | 76 | 68 | t1 | NULL | TABLE | IX | GRANTED | NULL | | 213929:205:4:5 | 138 | 13 | t1 | PRIMARY | RECORD | X | GRANTED | 11 | +----------------+-----------+----------+-------------+------------+-----------+-----------+-------------+-----------+ ---------------------------------- it seems "show engine innodb status\G" and performance_schema.data_locks get the different results For "show engine innodb status\G" MySQL thread id 39,session 1 granted the "lock_mode X locks rec but not gap" But for performance_schema.data_locks，it showed the session2 granted the x lock Here is the relation between thread_id and processlist_id session1> select THREAD_ID,PROCESSLIST_ID from performance_schema.threads where thread_id in (76,138); +-----------+----------------+ | THREAD_ID | PROCESSLIST_ID | +-----------+----------------+ | 76 | 39 | | 138 | 101 | +-----------+----------------+ 2 rows in set (0.00 sec) How to repeat: As stated above,