Re: MySQL performance issues
As far as we can tell ORM is checking the tables to make sure the structure is what it expects, and I think it is querying the schema to check the structure. For a database with around 89 tables we see around 330 schema queries all of which take up to 5 seconds to run.
We see these the following states and queries multiple times when showing the processlist in workbench while we are trying to load our app.
Query 1 checking permissions SELECT A.REFERENCED_TABLE_SCHEMA AS PKTABLE_CAT,NULL AS PKTABLE_SCHEM, A.REFERENCED_TABLE_NAME AS PK
Query 4 Sending data SELECT A.REFERENCED_TABLE_SCHEMA AS PKTABLE_CAT,NULL AS PKTABLE_SCHEM, A.REFERENCED_TABLE_NAME AS PK
I’ve also included the dump of the show engine innodb status below.
=====================================
2020-03-27 09:03:08 0x2b7d20782700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 54 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 286 srv_active, 0 srv_shutdown, 58880 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 44
OS WAIT ARRAY INFO: signal count 8818
RW-shared spins 1450, rounds 1452, OS waits 2
RW-excl spins 125, rounds 149, OS waits 37
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 1.00 RW-shared, 1.19 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 4029640
Purge done for trx's n:o < 4029639 undo n:o < 0 state: running but idle
History list length 12
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 329291394981864, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394980056, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394979152, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394977344, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394976440, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394988192, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394978248, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 329291394975536, not started
0 lock struct(s), heap size 1136, 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:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
20207 OS file reads, 5521 OS file writes, 3259 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 276707, node heap has 3 buffer(s)
Hash table size 276707, node heap has 62 buffer(s)
Hash table size 276707, node heap has 8 buffer(s)
Hash table size 276707, node heap has 7 buffer(s)
Hash table size 276707, node heap has 2 buffer(s)
Hash table size 276707, node heap has 3 buffer(s)
Hash table size 276707, node heap has 234 buffer(s)
Hash table size 276707, node heap has 696 buffer(s)
329831.48 hash searches/s, 2558.77 non-hash searches/s
---
LOG
---
Log sequence number 72488684561
Log buffer assigned up to 72488684561
Log buffer completed up to 72488684561
Log written up to 72488684561
Log flushed up to 72488684561
Added dirty pages up to 72488684561
Pages flushed up to 72488684561
Last checkpoint at 72488684561
1332 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 1098907648
Dictionary memory allocated 5217204
Buffer pool size 65536
Free buffers 44202
Database pages 20319
Old database pages 7576
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 233890, not young 2869
467.84 youngs/s, 0.00 non-youngs/s
Pages read 20174, created 154, written 2958
0.00 reads/s, 0.00 creates/s, 0.00 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: 20319, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 8192
Free buffers 5103
Database pages 2962
Old database pages 1113
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2957, created 5, written 551
0.00 reads/s, 0.00 creates/s, 0.00 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: 2962, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 8192
Free buffers 5684
Database pages 2381
Old database pages 858
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 60724, not young 9
251.50 youngs/s, 0.00 non-youngs/s
Pages read 2379, created 5, written 376
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 2 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 2381, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size 8192
Free buffers 5646
Database pages 2420
Old database pages 873
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 173166, not young 2860
216.35 youngs/s, 0.00 non-youngs/s
Pages read 2418, created 8, written 117
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 2 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 2420, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size 8192
Free buffers 5678
Database pages 2387
Old database pages 901
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2386, created 1, written 7
0.00 reads/s, 0.00 creates/s, 0.00 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: 2387, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size 8192
Free buffers 5592
Database pages 2473
Old database pages 932
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2472, created 1, written 57
0.00 reads/s, 0.00 creates/s, 0.00 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: 2473, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size 8192
Free buffers 5744
Database pages 2321
Old database pages 876
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2257, created 64, written 67
0.00 reads/s, 0.00 creates/s, 0.00 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: 2321, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size 8192
Free buffers 5295
Database pages 2770
Old database pages 1042
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2705, created 65, written 683
0.00 reads/s, 0.00 creates/s, 0.00 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: 2770, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size 8192
Free buffers 5460
Database pages 2605
Old database pages 981
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2600, created 5, written 1100
0.00 reads/s, 0.00 creates/s, 0.00 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: 2605, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Process ID=5843, Main thread ID=47817743668992 , state=sleeping
Number of rows inserted 177, updated 891, deleted 1, read 319058020
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 420843.84 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================