Update with WHERE primary key clause getting slower and getting hang for minutes then return error lock wait timeout

canhnm · July 16, 2023, 5:43pm

Hello,

I am using: mysql Ver 8.0.33-25 for Linux on x86_64 (Percona Server (GPL), Release ‘25’, Revision ‘60c9e2c5’)

Server specs:
OS: Ubuntu 20.04.6 LTS x86_64
CPU(s): 16
Memory: 32GB

innodb_buffer_pool_size: 25769803776; //24GB
innodb_lock_wait_timeout=600 // I tried to set to this number from 50 of default Mysql config when the issue started happening

Create Table Script:

CREATE TABLE `customers` (
  `id` bigint unsigned NOT NULL AUTO_INCREMENT,
  `customer_id` varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL,
  `shop_id` bigint unsigned NOT NULL,
  `email` varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL,
  `points` bigint NOT NULL DEFAULT '0',
  `points_earned` bigint NOT NULL DEFAULT '0',
  `state` varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL,
  `birthday` date DEFAULT NULL,
  `referral_code` varchar(255) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
  `referral_from` bigint unsigned DEFAULT NULL,
  `app_status` tinyint(1) NOT NULL DEFAULT '1',
  `created_at` timestamp NULL DEFAULT NULL,
  `updated_at` timestamp NULL DEFAULT NULL,
  `first_name` varchar(255) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
  `last_name` varchar(255) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `shop_id_index` (`shop_id`),
  KEY `customers_id_index` (`customer_id`)
) ENGINE=InnoDB AUTO_INCREMENT=43658157 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci

The total records of customers table is: 15.724.564

Update Query:
UPDATE customers set points= 70, points_earned= 10000000000470, updated_at= '2023-07-14 10:03:17' WHERE id = 26209133;

The issue is:
The update query hang more than 10 minutes as I tried to set innodb_lock_wait_timeout to 600 and return error query lock wait timeout.

Event tried with simple query:
UPDATE customers set points= 70 WHERE id = 26209133;
It still getting lock wait timeout error;

The update query just run well when I do restart or reload: service mysql reload, just after reload the query takes only about 300ms to finish. But after some hours up and running the update getting hang as describe above.

Any suggestion?

Many thanks,
Canh

Mauricio_Cacho · July 17, 2023, 12:11am

Hello @canhnm . Welcome to the Percona Forums!

Could you please share the exact error you’re getting?
If I understood properly, you’re getting something like “Lock wait timeout exceeded; try restarting transaction”

If that’s the case, then the issue is not really with your update query, but with other transactions running in your database server.

Basically, this would mean the query is trying to update the record, but there’s another transaction holding a lock for that same record; so the update can be executed until the lock is released by the other transaction.

This would also explain why you’re able to execute the UPDATE after a reboot; whichever transaction was holding the lock is no longer running in the server; thus update is able to acquire the lock and complete.

If this is something recurring and you can duplicate it; I would suggest you retry like that, with the innodb_lock_wait_timeout set as 10 minutes (or even greater), and you can try to debug and pinpount the transaction holding the lock using one of the approaches mentioned here (Check mainly the Tracking the Blocking Transaction section).

I hope this helps, and if this is indeed what you’re facing, next step would be to ensure your application is handling the transactions properly.

canhnm · July 17, 2023, 4:27am

Hello Mauricio, Yes exactly the error is “Lock wait timeout exceeed, try restarting transaction” event I have increased to 600.

At the same time when executing the query I also run Show processlist on mysql console and saw no other transaction running.

Thanks you,
Canh

kedarpercona · July 17, 2023, 4:39am

Hi @canhnm,

Would you try following the steps from the link shared by Mauricio earlier? While you’re executing this, would you also capture SHOW ENGINE INNODB STATUS and share here?
You can obfuscate any sensitive data.

Thanks,
K

canhnm · July 17, 2023, 4:59am

Hello @kedarpercona ,

I have just create track lock wait bash to monitor in background and will share more information if any.

Show engine innodb status data after the query error with Query 1 ERROR: Lock wait timeout exceeded; try restarting transaction:

| InnoDB |      |
=====================================
2023-07-17 04:58:04 140360814651136 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 45 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2052 srv_active, 0 srv_shutdown, 2680 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4310
OS WAIT ARRAY INFO: signal count 4025
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 161756626
Purge done for trx's n:o < 161749871 undo n:o < 0 state: running but idle
History list length 1432
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421864460602888, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460609672, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460602040, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460619848, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460619000, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460618152, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460624088, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460623240, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460614760, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460612216, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460621544, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460617304, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460613912, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460611368, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460610520, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460607976, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460613064, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460607128, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460608824, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460605432, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460601192, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460603736, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460604584, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460606280, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460599496, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460597800, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421864460596952, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 161756624, ACTIVE 4 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MySQL thread id 55965, OS thread handle 140360691758848, query id 5043741 localhost 127.0.0.1 root updating
update `customers` set `points` = '71', `points_earned` = '10000000000470', `shopify_customers`.`updated_at` = '2023-07-14 10:03:17' where `id` = 26209133
------- TRX HAS BEEN WAITING 4 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 424 page no 194755 n bits 152 index PRIMARY of table `loyalty`.`customers` trx id 161756624 lock_mode X locks rec but not gap waiting
Record lock, heap no 63 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
 0: len 8; hex 00000000018feb6d; asc        m;;
 1: len 6; hex 000009a41b75; asc      u;;
 2: len 7; hex 02000005802873; asc      (s;;
 3: len 13; hex 36373530333636393235303837; asc 6750366925087;;
 4: len 8; hex 0000000000004240; asc       B@;;
 5: len 30; hex 626f6e5f4c41686831553039695830507739614a3837764462426c42455a; asc bon_LAhh1U09iX0Pw9aJ87vDbBlBEZ; (total 48 bytes);
 6: len 8; hex 800000000000005a; asc        Z;;
 7: len 8; hex 800009184e72a1ea; asc     Nr  ;;
 8: len 7; hex 656e61626c6564; asc enabled;;
 9: len 3; hex 8f64a3; asc  d ;;
 10: len 8; hex 577a705846493747; asc WzpXFI7G;;
 11: SQL NULL;
 12: len 1; hex 81; asc  ;;
 13: len 4; hex 63d07a1f; asc c z ;;
 14: len 4; hex 64b4bced; asc d   ;;
 15: len 28; hex 626f6e5f4751517a5a49686e326238597968306a2f79377555413d3d; asc bon_GQQzZIhn2b8Yyh0j/y7uUA==;;
 16: len 28; hex 626f6e5f2b4675744e534274342f6c34576f44625050563149673d3d; asc bon_+FutNSBt4/l4WoDbPPV1Ig==;;

------------------
---TRANSACTION 161756608, ACTIVE 56 sec
1 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 1
MySQL thread id 63540, OS thread handle 140354002941696, query id 5016724 10.136.244.65 loyalty
Trx read view will not see trx with id >= 161756577, sees < 161749877
---TRANSACTION 161749877, ACTIVE 3478 sec
201 lock struct(s), heap size 24696, 423 row lock(s), undo log entries 684
MySQL thread id 17630, OS thread handle 140367990978304, query id 1444856 10.136.244.66 loyalty
Trx read view will not see trx with id >= 161749869, sees < 161749869
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests ((null))
I/O thread 1 state: waiting for completed aio requests (insert buffer thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
462014 OS file reads, 362430 OS file writes, 53674 OS fsyncs
1.09 reads/s, 16384 avg bytes/read, 7.16 writes/s, 6.32 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 3093, seg size 3095, 1069 merges
merged operations:
 insert 1788, delete mark 11, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 6375037, node heap has 701 buffer(s)
Hash table size 6375037, node heap has 12 buffer(s)
Hash table size 6375037, node heap has 8081 buffer(s)
Hash table size 6375037, node heap has 2899 buffer(s)
Hash table size 6375037, node heap has 32 buffer(s)
Hash table size 6375037, node heap has 96 buffer(s)
Hash table size 6375037, node heap has 261 buffer(s)
Hash table size 6375037, node heap has 1892 buffer(s)
5434.50 hash searches/s, 796.27 non-hash searches/s
---
LOG
---
Log sequence number          137236257890
Log buffer assigned up to    137236257890
Log buffer completed up to   137236257890
Log written up to            137236257890
Log flushed up to            137236257890
Added dirty pages up to      137236257890
Pages flushed up to          137236257469
Last checkpoint at           137236257469
Log minimum file id is       3209
Log maximum file id is       3211
Modified age no less than    137236257890
Checkpoint age               421
Max checkpoint age           87391744
25544 log i/o's done, 2.18 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 1054559
Buffer pool size   1572672
Buffer pool size, bytes 25766658048
Free buffers       986716
Database pages     571981
Old database pages 211149
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 227685, not young 3580178
0.35 youngs/s, 1.11 non-youngs/s
Pages read 461881, created 110965, written 322146
1.09 reads/s, 0.00 creates/s, 2.95 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 571981, unzip_LRU len: 0
I/O sum[1648]:cur[8], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       121348
Database pages     73490
Old database pages 27108
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 56111, not young 1088562
0.09 youngs/s, 0.18 non-youngs/s
Pages read 59787, created 13895, written 41015
0.04 reads/s, 0.00 creates/s, 0.33 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 73490, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       126717
Database pages     68123
Old database pages 25127
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 49959, not young 887349
0.11 youngs/s, 0.33 non-youngs/s
Pages read 56245, created 12001, written 35460
0.07 reads/s, 0.00 creates/s, 0.11 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 68123, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       123102
Database pages     71724
Old database pages 26467
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 62796, not young 964619
0.11 youngs/s, 0.60 non-youngs/s
Pages read 56367, created 15549, written 42521
0.51 reads/s, 0.00 creates/s, 0.44 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 71724, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       125308
Database pages     69525
Old database pages 25644
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 58796, not young 639648
0.04 youngs/s, 0.00 non-youngs/s
Pages read 55315, created 14568, written 45431
0.02 reads/s, 0.00 creates/s, 0.69 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 69525, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       123308
Database pages     71528
Old database pages 26423
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 6, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 57064, created 14464, written 40665
0.13 reads/s, 0.00 creates/s, 0.29 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 71528, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       122716
Database pages     72125
Old database pages 26644
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 5, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 58464, created 13661, written 38753
0.09 reads/s, 0.00 creates/s, 0.27 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 72125, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       122052
Database pages     72787
Old database pages 26888
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 60298, created 12489, written 37825
0.18 reads/s, 0.00 creates/s, 0.27 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 72787, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   196584
Buffer pool size, bytes 3220832256
Free buffers       122165
Database pages     72679
Old database pages 26848
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 58341, created 14338, written 40476
0.04 reads/s, 0.00 creates/s, 0.55 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 72679, unzip_LRU len: 0
I/O sum[206]:cur[1], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
3 RW transactions active inside InnoDB
---OLDEST VIEW---
Read view low limit trx n:o 161749869
Trx read view will not see trx with id >= 161749869, sees < 161749869
Read view individually stored trx ids:
-----------------
Process ID=85705, Main thread ID=140360881792768 , state=sleeping
Number of rows inserted 28345211, updated 2696, deleted 542, read 142329738
0.27 inserts/s, 0.36 updates/s, 0.00 deletes/s, 6595.68 reads/s
Number of system rows inserted 8, updated 332, deleted 55, read 13013
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Thank you,
Canh

canhnm · July 17, 2023, 5:31am

Hello @Mauricio_Cacho and @kedarpercona,

I am adding some more information from the steps recommended by Mauricio below:

SELECT * FROM performance_schema.data_lock_waits;
=>

±-------±----------------------------------------------±---------------------------------±---------------------±--------------------±---------------------------------±----------------------------------------------±-------------------------------±-------------------±------------------±-------------------------------+
| ENGINE | REQUESTING_ENGINE_LOCK_ID | REQUESTING_ENGINE_TRANSACTION_ID | REQUESTING_THREAD_ID | REQUESTING_EVENT_ID | REQUESTING_OBJECT_INSTANCE_BEGIN | BLOCKING_ENGINE_LOCK_ID | BLOCKING_ENGINE_TRANSACTION_ID | BLOCKING_THREAD_ID | BLOCKING_EVENT_ID | BLOCKING_OBJECT_INSTANCE_BEGIN |
±-------±----------------------------------------------±---------------------------------±---------------------±--------------------±---------------------------------±----------------------------------------------±-------------------------------±-------------------±------------------±-------------------------------+
| INNODB | 140389483889688:424:194755:63:140389394740912 | 161758304 | 56039 | 181 | 140389394740912 | 140389483905800:424:194755:63:140384584193848 | 161749877 | 17680 | 12852 | 140384584193848 |
±-------±----------------------------------------------±---------------------------------±---------------------±--------------------±---------------------------------±----------------------------------------------±-------------------------------±-------------------±------------------±-------------------------------+
1 row in set (0.00 sec)

SELECT * FROM performance_schema.events_statements_history WHERE THREAD_ID = 17680;

=>

±----------±---------±-------------±-------------------------±---------------------------------±-----------------±-----------------±-----------±----------±---------±-------±------------±---------------±------------±--------------±------------±----------------------±------------±------------------±-------------±-------±---------±--------------±----------±--------------±------------------------±-------------------±-----------------±-----------------------±-------------±-------------------±------------±------------------±-----------±----------±----------±--------------±-------------------±-----------------±-------------------±--------------------±-------------±---------±----------------------±-----------------±-----------------+
| THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | LOCK_TIME | SQL_TEXT | DIGEST | DIGEST_TEXT | CURRENT_SCHEMA | OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | OBJECT_INSTANCE_BEGIN | MYSQL_ERRNO | RETURNED_SQLSTATE | MESSAGE_TEXT | ERRORS | WARNINGS | ROWS_AFFECTED | ROWS_SENT | ROWS_EXAMINED | CREATED_TMP_DISK_TABLES | CREATED_TMP_TABLES | SELECT_FULL_JOIN | SELECT_FULL_RANGE_JOIN | SELECT_RANGE | SELECT_RANGE_CHECK | SELECT_SCAN | SORT_MERGE_PASSES | SORT_RANGE | SORT_ROWS | SORT_SCAN | NO_INDEX_USED | NO_GOOD_INDEX_USED | NESTING_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_LEVEL | STATEMENT_ID | CPU_TIME | MAX_CONTROLLED_MEMORY | MAX_TOTAL_MEMORY | EXECUTION_ENGINE |
±----------±---------±-------------±-------------------------±---------------------------------±-----------------±-----------------±-----------±----------±---------±-------±------------±---------------±------------±--------------±------------±----------------------±------------±------------------±-------------±-------±---------±--------------±----------±--------------±------------------------±-------------------±-----------------±-----------------------±-------------±-------------------±------------±------------------±-----------±----------±----------±--------------±-------------------±-----------------±-------------------±--------------------±-------------±---------±----------------------±-----------------±-----------------+
| 17680 | 20360 | 20360 | statement/com/Close stmt | init_net_server_extension.cc:102 | 1334316535872000 | 1334316539656000 | 3784000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444850 | 0 | 57592 | 147308 | PRIMARY |
| 17680 | 20361 | 20361 | statement/com/Prepare | init_net_server_extension.cc:102 | 1334316819109000 | 1334316854883000 | 35774000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444851 | 0 | 57592 | 147308 | PRIMARY |
| 17680 | 20362 | 20362 | statement/com/Execute | init_net_server_extension.cc:102 | 1334317102261000 | 1334317318378000 | 216117000 | 1000000 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 61 | 61 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444852 | 0 | 183368 | 273324 | PRIMARY |
| 17680 | 20363 | 20363 | statement/com/Close stmt | init_net_server_extension.cc:102 | 1334317755341000 | 1334317760034000 | 4693000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444853 | 0 | 39112 | 128828 | PRIMARY |
| 17680 | 20364 | 20364 | statement/com/Prepare | init_net_server_extension.cc:102 | 1334319141327000 | 1334319190574000 | 49247000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444854 | 0 | 28872 | 118588 | PRIMARY |
| 17680 | 20365 | 20365 | statement/com/Execute | init_net_server_extension.cc:102 | 1334319419353000 | 1334319555955000 | 136602000 | 1000000 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | 00000 | NULL | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444855 | 0 | 49448 | 139774 | PRIMARY |
| 17680 | 20366 | 20366 | statement/com/Close stmt | init_net_server_extension.cc:102 | 1334319813545000 | 1334319817688000 | 4143000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444856 | 0 | 28872 | 118588 | PRIMARY |
| 17680 | 20357 | 20357 | statement/com/Close stmt | init_net_server_extension.cc:102 | 1334315503335000 | 1334315507365000 | 4030000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444847 | 0 | 57592 | 147308 | PRIMARY |
| 17680 | 20358 | 20358 | statement/com/Prepare | init_net_server_extension.cc:102 | 1334315863004000 | 1334315901056000 | 38052000 | 0 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444848 | 0 | 57592 | 147308 | PRIMARY |
| 17680 | 20359 | 20359 | statement/com/Execute | init_net_server_extension.cc:102 | 1334316173662000 | 1334316242355000 | 68693000 | 1000000 | NULL | NULL | NULL | loyalty | NULL | NULL | NULL | NULL | 0 | NULL | NULL | 0 | 0 | 0 | 1 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 399 | TRANSACTION | 0 | 1444849 | 0 | 96648 | 186484 | PRIMARY |
±----------±---------±-------------±-------------------------±---------------------------------±-----------------±-----------------±-----------±----------±---------±-------±------------±---------------±------------±--------------±------------±----------------------±------------±------------------±-------------±-------±---------±--------------±----------±--------------±------------------------±-------------------±-----------------±-----------------------±-------------±-------------------±------------±------------------±-----------±----------±----------±--------------±-------------------±-----------------±-------------------±--------------------±-------------±---------±----------------------±-----------------±-----------------+
10 rows in set (0.00 sec)

SELECT min(THREAD_ID), max(THREAD_ID) FROM performance_schema.events_statements_history;

=>

±-----------------±-----------------+
| min(THREAD_ID) | max(THREAD_ID) |
±-----------------±-----------------+
| 163 | 82838 |
±-----------------±-----------------+
1 row in set (0.00 sec)

SELECT @@performance_schema_events_statements_history_size;

=>

±----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
±----------------------------------------------------+
| 10 |
±----------------------------------------------------+
1 row in set (0.00 sec)

SELECT @@performance_schema_events_statements_history_long_size;

±---------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
±---------------------------------------------------------+
| 10000 |
±---------------------------------------------------------+
1 row in set (0.00 sec)

SELECT * FROM performance_schema.setup_consumers;
=>
±---------------------------------±--------+
| NAME | ENABLED |
±---------------------------------±--------+
| events_stages_current | NO |
| events_stages_history | NO |
| events_stages_history_long | NO |
| events_statements_cpu | NO |
| events_statements_current | YES |
| events_statements_history | YES |
| events_statements_history_long | YES |
| events_transactions_current | YES |
| events_transactions_history | YES |
| events_transactions_history_long | NO |
| events_waits_current | NO |
| events_waits_history | NO |
| events_waits_history_long | NO |
| global_instrumentation | YES |
| thread_instrumentation | YES |
| statements_digest | YES |
±---------------------------------±--------+

SELECT count(THREAD_ID) FROM performance_schema.events_statements_history_long;

=>

±-------------------+
| count(THREAD_ID) |
±-------------------+
| 10000 |
±-------------------+
1 row in set (0.01 sec)

SELECT * FROM performance_schema.data_lock_waits\G;

=>

*************************** 1. row ***************************
ENGINE: INNODB
REQUESTING_ENGINE_LOCK_ID: 140389483889688:424:194755:63:140389394740912
REQUESTING_ENGINE_TRANSACTION_ID: 161758304
REQUESTING_THREAD_ID: 56039
REQUESTING_EVENT_ID: 181
REQUESTING_OBJECT_INSTANCE_BEGIN: 140389394740912
BLOCKING_ENGINE_LOCK_ID: 140389483905800:424:194755:63:140384584193848
BLOCKING_ENGINE_TRANSACTION_ID: 161749877
BLOCKING_THREAD_ID: 17680
BLOCKING_EVENT_ID: 12852
BLOCKING_OBJECT_INSTANCE_BEGIN: 140384584193848
1 row in set (0.00 sec)

SELECT THREAD_ID,EVENT_ID,EVENT_NAME, CURRENT_SCHEMA,SQL_TEXT from events_statements_history_long WHERE THREAD_ID IN (SELECT BLOCKING_THREAD_ID FROM data_lock_waits) ORDER BY EVENT_ID;

=>

Empty set (0.02 sec)

All of above was running while I was running UPDATE query with lock wait timeout set to 600;

Thank you,

canhnm · July 17, 2023, 10:32am

Hello,

I am adding update report log from tracking_lockwait.sh

94050 34 statement/com/Prepare loyalty NULL
94050 35 statement/com/Execute loyalty NULL
94050 36 statement/com/Close stmt loyalty NULL
94050 37 statement/com/Prepare loyalty NULL
94050 38 statement/com/Execute loyalty NULL
94050 39 statement/com/Close stmt loyalty NULL
94050 40 statement/com/Prepare loyalty NULL
94050 41 statement/com/Execute loyalty NULL
94050 42 statement/com/Close stmt loyalty NULL
94050 43 statement/sql/savepoint loyalty SAVEPOINT trans2
94050 44 statement/com/Prepare loyalty NULL
94050 45 statement/com/Execute loyalty NULL
94050 46 statement/com/Close stmt loyalty NULL
94050 47 statement/com/Prepare loyalty NULL
94050 48 statement/com/Execute loyalty NULL
94050 49 statement/com/Close stmt loyalty NULL
94050 50 statement/com/Prepare loyalty NULL
94050 51 statement/com/Execute loyalty NULL
94050 52 statement/com/Close stmt loyalty NULL
94050 53 statement/com/Prepare loyalty NULL
94050 54 statement/com/Execute loyalty NULL
94050 55 statement/com/Close stmt loyalty NULL

Thanks you,
Canh

matthewb · July 17, 2023, 2:40pm

You have some other transaction that is still open, holding many row locks and many undo pages. This is an ACTIVE transaction. Just because SHOW PROCESSLIST is “empty” doesn’t mean that there are no open transactions.

This transaction, 161749877, must already be holding the PK locks that your UPDATE is needing. COMMIT/ROLLBACK this transaction and your UPDATE will succeed.

matthewb · July 17, 2023, 2:42pm

You should never have to change this. Changing this is a direct 100% indication that you have something else wrong. In your case, you have another open/idle transaction which is blocking your UPDATE. This is further evidenced by the output of performance_schema.data_lock_waits

canhnm · July 17, 2023, 3:17pm

Hello @matthewb

These struct(s), I guess come from the application connection which not handle well with transaction commit/rollback.

Is there any way to check the idle transaction to remove/release the lock?

Thank you,
Canh

matthewb · July 17, 2023, 9:22pm

Correlate the transaction id (161749877) of the blocking transaction with it’s process ID using performance_schema.data_lock_waits. Then you can KILL <connectionId> to release that connection.

You should lower wait_timeout to prevent idle connections from remaining connected and idle. You should also review your application code an ensure all connection handlers are properly closed.

canhnm · July 18, 2023, 2:15am

Hello @matthewb,

Thank you for your suggestion, I am currently doing kill process manually and also push the devs to update code to handle transaction better.

Thank you guys for your support.
Canh

kedarpercona · July 18, 2023, 5:17am

@canhnm ,
Just FYI there is pt-kill.

Thanks,
K

Topic		Replies	Views
percona server 5.5 query end status Percona Server for MySQL 5.6	2	615	July 15, 2019
Semaphore wait timeouts Percona Server for MySQL 8.0	2	1456	July 13, 2022
Innodb Mutex Error?? Other MySQL® Questions	2	652	February 4, 2015
Xa transaction questions Percona Server for MySQL 5.6	1	737	July 3, 2019
Percona Server Other MySQL® Questions	2	471	December 11, 2012

Update with WHERE primary key clause getting slower and getting hang for minutes then return error lock wait timeout

Related Topics