Yii2 yii-queue: I am getting deadlocks on deleting rows in the queue table

Yii 2.0 General Discussions
1

I am getting regular errors in my yii2 app about deadlocks specific to yii-queue. I am not seeing any problems being caused by this in the app fortunately, but I suspect I have a growing table of already-processed tasks because of this.

Here is an example of the error:

Next yii\db\Exception: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
The SQL being executed was: DELETE FROM `rtm_queue` WHERE `id`='10782631' in /home/appHome/vendor/yiisoft/yii2/db/Schema.php:676
Stack trace:
#0 /home/appHome/vendor/yiisoft/yii2/db/Command.php(1307): yii\db\Schema->convertException()
#1 /home/appHome/vendor/yiisoft/yii2/db/Command.php(1102): yii\db\Command->internalExecute()
#2 /home/appHome/vendor/yiisoft/yii2-queue/src/drivers/db/Queue.php(226): yii\db\Command->execute()
#3 /home/appHome/vendor/yiisoft/yii2-queue/src/drivers/db/Queue.php(85): yii\queue\db\Queue->release()
#4 [internal function]: yii\queue\db\Queue->yii\queue\db\{closure}()
#5 /home/appHome/vendor/yiisoft/yii2-queue/src/cli/Queue.php(117): call_user_func()
#6 /home/appHome/vendor/yiisoft/yii2-queue/src/drivers/db/Queue.php(93): yii\queue\cli\Queue->runWorker()
#7 /home/appHome/vendor/yiisoft/yii2-queue/src/drivers/db/Command.php(76): yii\queue\db\Queue->run()
#8 [internal function]: yii\queue\db\Command->actionListen()
#9 /home/appHome/vendor/yiisoft/yii2/base/InlineAction.php(57): call_user_func_array()
#10 /home/appHome/vendor/yiisoft/yii2/base/Controller.php(178): yii\base\InlineAction->runWithParams()
#11 /home/appHome/vendor/yiisoft/yii2/console/Controller.php(180): yii\base\Controller->runAction()
#12 /home/appHome/vendor/yiisoft/yii2/base/Module.php(552): yii\console\Controller->runAction()
#13 /home/appHome/vendor/yiisoft/yii2/console/Application.php(180): yii\base\Module->runAction()
#14 /home/appHome/vendor/yiisoft/yii2/console/Application.php(147): yii\console\Application->runAction()
#15 /home/appHome/vendor/yiisoft/yii2/base/Application.php(384): yii\console\Application->handleRequest()
#16 /home/appHome/yii(23): yii\base\Application->run()
#17 {main}
Additional Information:
Array
(
    [0] => 40001
    [1] => 1213
    [2] => Deadlock found when trying to get lock; try restarting transaction
)

Notice that yii-queue is having issues deleting a row from the queue table. From what I can see, this is 100% the situation. I am not seeing errors about inserts, updates, etc.

Here is what I have installed that is related:

yiisoft/yii2-queue                       dev-master 4408839               Yii2 Queue Extension which supported DB, Redis, RabbitMQ, Beanstalk, SQS and Gearman
zhuravljov/yii2-queue-monitor            dev-master fa5246b               Yii2 Queue Analytics Module

I thought maybe yii2-queue-monitor was locking the row for some reason, although I don’t know why it would, but to be safe I tried turned it off as you will see in the config below. It did not have any impact on this.

After some reading, I also wanted to rule out MysqlMutex causing an issue, so I updated to use yii\redis\Mutex. That also had no impact.

Note, this is a r5-xlarge box in AWS and the load can sometimes get a little high but in reality the queue itself is usually around 200-2000 queued tasks. So, it could be performance issue but I’m struggling to see how that could be the case. Alas, I don’t know how to actually test for that.

How should I proceed in solving and/or debugging this? Any help is appreciated.

FYI, I have 6 queue runners: 4 instances of queue and 2 instances of queue-sync. Tasks pushed into ‘queue’ are relatively light and impact users interactively, so that’s the “move quickly” queue. ‘queue-sync’ is for jobs that may last several minutes. They all run out of the same table but are separate channels.

My configuration:

<?php

/**
 * configures our work queue system; currently based on yii2-queue
 */

$config['bootstrap'][] = 'queue';
$config['components']['queue'] = [
    'as log' => \yii\queue\LogBehavior::class,
    'class' => \yii\queue\db\Queue::class,
    'db' => 'db',
    'tableName' => '{{%queue}}',
    'channel' => 'default',
    'mutex' => [
        'class' => \yii\redis\Mutex::class,
        'keyPrefix' => 'queue-',
        'redis' => [
            'hostname' => $_SERVER['REDIS_HOSTNAME'],
            'port' => $_SERVER['REDIS_PORT'],
            'database' => $_SERVER['REDIS_QUEUE_MUTEX'],
        ],
    ],
    'ttr' => 5 * 60, // 5 min

    // https://github.com/zhuravljov/yii2-queue-monitor
    //'as jobMonitor' => \zhuravljov\yii\queue\monitor\JobMonitor::class,
    //'as workerMonitor' => \zhuravljov\yii\queue\monitor\WorkerMonitor::class,
];

$config['bootstrap'][] = 'queue_sync';
$config['components']['queue_sync'] = [
    'as log' => \yii\queue\LogBehavior::class,
    'class' => \yii\queue\db\Queue::class,
    'db' => 'db',
    'tableName' => '{{%queue}}',
    'channel' => 'sync',
    'mutex' => [
        'class' => \yii\redis\Mutex::class,
        'keyPrefix' => 'queue_sync-',
        'redis' => [
            'hostname' => $_SERVER['REDIS_HOSTNAME'],
            'port' => $_SERVER['REDIS_PORT'],
            'database' => $_SERVER['REDIS_QUEUE_MUTEX'],
        ],
    ],
    'ttr' => 15 * 60, // 15 min

    // https://github.com/zhuravljov/yii2-queue-monitor
    //'as jobMonitor' => \zhuravljov\yii\queue\monitor\JobMonitor::class,
    //'as workerMonitor' => \zhuravljov\yii\queue\monitor\WorkerMonitor::class,
];

// https://github.com/zhuravljov/yii2-queue-monitor
/*
$config['container']['singletons'] = [
    \zhuravljov\yii\queue\monitor\Env::class => [
        'cache' => 'cache',
        'db' => 'db',
        'pushTableName' => '{{%queue_push}}',
        'execTableName' => '{{%queue_exec}}',
        'workerTableName' => '{{%queue_worker}}',
    ],
];
*/

My CPU to map to the # of queue runners I have:

$ lscpu
Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Byte Order:                      Little Endian
Address sizes:                   46 bits physical, 48 bits virtual
CPU(s):                          4
On-line CPU(s) list:             0-3
Thread(s) per core:              2
Core(s) per socket:              2
Socket(s):                       1
NUMA node(s):                    1

I realize I have 6 queue runners for 4 cores, but jobs in ‘queue-sync’ are very network IO bound for a lot of the time, so my thinking was it was okay to have 1.5 queue runners per core.

2

Quick note about the database:

$ mysql -V
mysql  Ver 8.0.30 for Linux on x86_64 (MySQL Community Server - GPL)

I am using innodb tables.

3

Would you please get output from SHOW ENGINE INNODB STATUS?

4

Sure @samdark, here you go:


=====================================
2023-05-03 14:20:57 140038267397888 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 33 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 202179 srv_active, 0 srv_shutdown, 24495 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 213965
OS WAIT ARRAY INFO: signal count 273166
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
------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-05-03 14:20:44 140040118851328
*** (1) TRANSACTION:
TRANSACTION 1266131778, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1128, 4 row lock(s)
MySQL thread id 847221, OS thread handle 140039926208256, query id 468795985 localhost forge Searching rows for update
UPDATE `rtm_queue` SET `reserved_at`=NULL WHERE `reserved_at` is not null and `reserved_at` < 1683123644 - `ttr` and `done_at` is null

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 157 page no 7 n bits 544 index reserved_at of table `forge`.`rtm_queue` trx id 1266131778 lock_mode X
Record lock, heap no 326 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex e4526cb7; asc  Rl ;;
 1: len 4; hex 80a589cc; asc     ;;

Record lock, heap no 449 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex e4526da4; asc  Rm ;;
 1: len 4; hex 80a581b7; asc     ;;


*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 157 page no 57 n bits 88 index PRIMARY of table `forge`.`rtm_queue` trx id 1266131778 lock_mode X locks rec but not gap waiting
Record lock, heap no 21 PHYSICAL RECORD: n_fields 12; compact format; info bits 32
 0: len 4; hex 80a581b7; asc     ;;
 1: len 6; hex 00004b77a33e; asc   Kw >;;
 2: len 7; hex 01000001f20b91; asc        ;;
 3: len 4; hex 73796e63; asc sync;;
 4: len 30; hex 4f3a35313a22636f6d6d6f6e5c636f6d6d616e644275735c636f6d6d616e; asc O:51:"common\commandBus\comman; (total 665 bytes);
 5: len 4; hex e45264aa; asc  Rd ;;
 6: len 4; hex 80000384; asc     ;;
 7: len 4; hex 80000000; asc     ;;
 8: len 4; hex 00000400; asc     ;;
 9: len 4; hex e4526da4; asc  Rm ;;
 10: len 4; hex 80000001; asc     ;;
 11: SQL NULL;


*** (2) TRANSACTION:
TRANSACTION 1266131774, ACTIVE 1 sec updating or deleting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
MySQL thread id 830680, OS thread handle 140039928317696, query id 468795942 localhost forge updating
DELETE FROM `rtm_queue` WHERE `id`='10846647'

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 157 page no 57 n bits 88 index PRIMARY of table `forge`.`rtm_queue` trx id 1266131774 lock_mode X locks rec but not gap
Record lock, heap no 21 PHYSICAL RECORD: n_fields 12; compact format; info bits 32
 0: len 4; hex 80a581b7; asc     ;;
 1: len 6; hex 00004b77a33e; asc   Kw >;;
 2: len 7; hex 01000001f20b91; asc        ;;
 3: len 4; hex 73796e63; asc sync;;
 4: len 30; hex 4f3a35313a22636f6d6d6f6e5c636f6d6d616e644275735c636f6d6d616e; asc O:51:"common\commandBus\comman; (total 665 bytes);
 5: len 4; hex e45264aa; asc  Rd ;;
 6: len 4; hex 80000384; asc     ;;
 7: len 4; hex 80000000; asc     ;;
 8: len 4; hex 00000400; asc     ;;
 9: len 4; hex e4526da4; asc  Rm ;;
 10: len 4; hex 80000001; asc     ;;
 11: SQL NULL;


*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 157 page no 7 n bits 544 index reserved_at of table `forge`.`rtm_queue` trx id 1266131774 lock_mode X locks rec but not gap waiting
Record lock, heap no 449 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex e4526da4; asc  Rm ;;
 1: len 4; hex 80a581b7; asc     ;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 1266132210
Purge done for trx's n:o < 1266132197 undo n:o < 0 state: running but idle
History list length 17
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421535188530768, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188531576, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188529152, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188533192, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188534808, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188529960, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188535616, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188534000, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188532384, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188528344, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188527536, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421535188526728, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log 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)
I/O thread 9 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:, log i/o's:
Pending flushes (fsync) log: 0; buffer pool: 4815
446487 OS file reads, 14804755 OS file writes, 11181035 OS fsyncs
0.03 reads/s, 16384 avg bytes/read, 63.93 writes/s, 50.05 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 2073, seg size 2075, 7044 merges
merged operations:
 insert 4493, delete mark 943236, delete 14550
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 4515689, node heap has 968 buffer(s)
Hash table size 4515689, node heap has 1191 buffer(s)
Hash table size 4515689, node heap has 506 buffer(s)
Hash table size 4515689, node heap has 939 buffer(s)
Hash table size 4515689, node heap has 250 buffer(s)
Hash table size 4515689, node heap has 50 buffer(s)
Hash table size 4515689, node heap has 923 buffer(s)
Hash table size 4515689, node heap has 2692 buffer(s)
15667.31 hash searches/s, 1021.70 non-hash searches/s
---
LOG
---
Log sequence number          578202415352
Log buffer assigned up to    578202415352
Log buffer completed up to   578202415352
Log written up to            578202415352
Log flushed up to            578202415352
Added dirty pages up to      578202415352
Pages flushed up to          578196761415
Last checkpoint at           578196717906
Log minimum file id is       365
Log maximum file id is       393
7324590 log i/o's done, 30.06 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 3149188
Buffer pool size   1114012
Free buffers       635472
Database pages     471021
Old database pages 173528
Modified db pages  785
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1361422, not young 12254265
0.84 youngs/s, 0.42 non-youngs/s
Pages read 442867, created 34513, written 4261242
0.03 reads/s, 0.00 creates/s, 19.61 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: 471021, unzip_LRU len: 0
I/O sum[14688]:cur[255], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   65528
Free buffers       35673
Database pages     29423
Old database pages 10841
Modified db pages  65
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 25596, not young 328120
0.06 youngs/s, 0.00 non-youngs/s
Pages read 27386, created 2165, written 294671
0.00 reads/s, 0.00 creates/s, 1.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: 29423, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   65536
Free buffers       38796
Database pages     26301
Old database pages 9688
Modified db pages  106
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 94288, not young 701839
0.03 youngs/s, 0.00 non-youngs/s
Pages read 24850, created 2029, written 330573
0.00 reads/s, 0.00 creates/s, 1.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: 26301, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   65529
Free buffers       38278
Database pages     26811
Old database pages 9877
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 98876, not young 934125
0.00 youngs/s, 0.00 non-youngs/s
Pages read 25352, created 1671, written 209841
0.00 reads/s, 0.00 creates/s, 1.05 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: 26811, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   65529
Free buffers       37240
Database pages     27834
Old database pages 10254
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 102780, not young 832243
0.00 youngs/s, 0.00 non-youngs/s
Pages read 25924, created 2292, written 153445
0.00 reads/s, 0.00 creates/s, 0.66 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: 27834, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   65530
Free buffers       38571
Database pages     26498
Old database pages 9761
Modified db pages  19
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 95334, not young 988940
0.03 youngs/s, 0.00 non-youngs/s
Pages read 24710, created 2484, written 254666
0.00 reads/s, 0.00 creates/s, 1.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: 26498, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   65529
Free buffers       38447
Database pages     26622
Old database pages 9807
Modified db pages  13
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 97457, not young 976084
0.00 youngs/s, 0.42 non-youngs/s
Pages read 24887, created 2126, written 229384
0.03 reads/s, 0.00 creates/s, 1.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: 26622, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   65528
Free buffers       37117
Database pages     27965
Old database pages 10303
Modified db pages  11
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 110319, not young 354366
0.30 youngs/s, 0.00 non-youngs/s
Pages read 26815, created 1799, written 264165
0.00 reads/s, 0.00 creates/s, 1.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: 27965, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   65533
Free buffers       37637
Database pages     27465
Old database pages 10118
Modified db pages  28
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 76596, not young 909601
0.00 youngs/s, 0.00 non-youngs/s
Pages read 25931, created 2026, written 252026
0.00 reads/s, 0.00 creates/s, 1.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: 27465, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 8
Buffer pool size   65531
Free buffers       36573
Database pages     28512
Old database pages 10504
Modified db pages  150
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 60, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 26767, created 1745, written 345914
0.00 reads/s, 0.00 creates/s, 1.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: 28512, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 9
Buffer pool size   65529
Free buffers       37068
Database pages     28015
Old database pages 10321
Modified db pages  55
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 94676, not young 716582
0.00 youngs/s, 0.00 non-youngs/s
Pages read 26887, created 1512, written 279754
0.00 reads/s, 0.00 creates/s, 1.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: 28015, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 10
Buffer pool size   65530
Free buffers       37039
Database pages     28058
Old database pages 10337
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 107524, not young 1006483
0.00 youngs/s, 0.00 non-youngs/s
Pages read 26184, created 2122, written 157350
0.00 reads/s, 0.00 creates/s, 0.51 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: 28058, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 11
Buffer pool size   65530
Free buffers       39017
Database pages     26073
Old database pages 9604
Modified db pages  52
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 80893, not young 1045030
0.36 youngs/s, 0.00 non-youngs/s
Pages read 24417, created 1848, written 238239
0.00 reads/s, 0.00 creates/s, 1.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: 26073, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 12
Buffer pool size   65533
Free buffers       36579
Database pages     28511
Old database pages 10504
Modified db pages  100
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 74800, not young 1058384
0.00 youngs/s, 0.00 non-youngs/s
Pages read 26687, created 2826, written 298427
0.00 reads/s, 0.00 creates/s, 1.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: 28511, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 13
Buffer pool size   65531
Free buffers       37723
Database pages     27366
Old database pages 10081
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 103151, not young 705192
0.06 youngs/s, 0.00 non-youngs/s
Pages read 25733, created 1908, written 145413
0.00 reads/s, 0.00 creates/s, 0.57 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: 27366, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 14
Buffer pool size   65528
Free buffers       36441
Database pages     28660
Old database pages 10562
Modified db pages  41
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 163, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 27101, created 1559, written 235022
0.00 reads/s, 0.00 creates/s, 1.32 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: 28660, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 15
Buffer pool size   65528
Free buffers       36181
Database pages     28906
Old database pages 10650
Modified db pages  64
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 104302, not young 1004737
0.00 youngs/s, 0.00 non-youngs/s
Pages read 27502, created 1788, written 263074
0.00 reads/s, 0.00 creates/s, 1.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: 28906, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
---BUFFER POOL 16
Buffer pool size   65530
Free buffers       37092
Database pages     28001
Old database pages 10316
Modified db pages  81
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 94607, not young 692539
0.00 youngs/s, 0.00 non-youngs/s
Pages read 25734, created 2613, written 309278
0.00 reads/s, 0.00 creates/s, 1.32 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: 28001, unzip_LRU len: 0
I/O sum[864]:cur[15], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=2930003, Main thread ID=140040085280512 , state=sleeping
Number of rows inserted 4956820, updated 1458064, deleted 1784431, read 60938990418
2.39 inserts/s, 6.03 updates/s, 1.03 deletes/s, 82081.30 reads/s
Number of system rows inserted 657, updated 6404, deleted 584, read 1404932
0.00 inserts/s, 3.12 updates/s, 0.00 deletes/s, 35.18 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 Like
5

Hey there!

In looking through things, I noticed that we have a custom lock timeout for innodb. Could this be causing the issue?

    'on afterOpen' => function ($event) {
        $event->sender
            ->createCommand('SET innodb_lock_wait_timeout=:waitTimeout', [
                'waitTimeout' => $_SERVER['DB_WAIT_INNODB_LOCK_TIMEOUT'] ?? 15,
            ])
            ->execute();
    },

I may experiment and comment this out and watch for the impact.

In reviewing this, we are setting the timeout to 15 for the innodb engine itself…

1 Like