MySQL Forums
Forum List  »  Performance

Terrible performance of a specific query with lots of connections
Posted by: Ben Dowling
Date: September 08, 2009 12:17PM

I have a PHP/MySQL website, and a certain query usually takes around 1 second. However, during times of high load the when several of these queries run at the same time then seem to lock, and never complete, meaning I have to manually kill them. Could this be a thrashing issue? How can I diagnose it, and what steps could I take to resolve the problem?

Here is the output of explain for the problem query:

EXPLAIN SELECT dr.referenced_document_id FROM document_references dr JOIN profile_documents pd ON (pd.document_id = dr.document_id) WHERE pd.profile_id = '23890' AND dr.referenced_document_id NOT IN (SELECT document_id FROM profile_documents WHERE profile_id = '23890'):

*** row 1 ***
table: pd
type: ref
possible_keys: idx_profile_document,profile_documents_fk_Document_id
key: idx_profile_document
key_len: 9
ref: const
rows: 123
Extra: Using where; Using index
*** row 2 ***
table: dr
type: ref
possible_keys: PRIMARY
key: PRIMARY
key_len: 8
ref: DB.pd.document_id
rows: 34
Extra: Using where; Using index
*** row 3 ***
table: profile_documents
type: ref_or_null
possible_keys: idx_profile_document,profile_documents_fk_Document_id
key: idx_profile_document
key_len: 18
ref: const,func
rows: 2
Extra: Using where; Using index

And here is the output so SHOW INNODB STATUS:

=====================================
090908 17:29:50 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 27 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 21545250, signal count 20335199
--Thread 1154787664 has waited at btr0cur.c line 366 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7f29a45e4520 created in file dict0dict.c line 3706
a writer (thread id 1154111824) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0cur.c line 366
Last time write locked in file btr0cur.c line 359
Mutex spin waits 0, rounds 1153969353, OS waits 15539552
RW-shared spins 3927231, OS waits 1804581; RW-excl spins 2723700, OS waits 591414
------------------------
LATEST FOREIGN KEY ERROR
------------------------
090908 17:24:03 Transaction:
TRANSACTION 1 1718385385, ACTIVE 0 sec, process no 8496, OS thread id 1157896528 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
3 lock struct(s), heap size 368
MySQL thread id 7486285, query id 1291789616 mysql.db_user.internal 10.0.6.1 db_user update

...
,
CONSTRAINT `document_details_fk_Document_id` FOREIGN KEY (`document_id`) REFERENCES `documents` (`id`) ON DELETE CASCADE
Trying to add in child table, in index `PRIMARY` tuple:
DATA TUPLE: 24 fields;
0: len 8; hex 00000000073d26ae; asc =& ;; 1: len 6; hex 0001666c7ae9; asc flz ;; 2: len 7; hex 80004580230e4c; asc E # L;; 3: len 4; hex 312d3130; asc 1-10;; 4: SQL NULL; 5: len 2; hex 3232; asc 22;; 6: SQL NULL; 7: SQL NULL; 8: SQL NULL; 9: SQL NULL; 10: SQL NULL; 11: SQL NULL; 12: SQL NULL; 13: SQL NULL; 14: SQL NULL; 15: SQL NULL; 16: SQL NULL; 17: SQL NULL; 18: SQL NULL; 19: SQL NULL; 20: len 1; hex 01; asc ;; 21: SQL NULL; 22: SQL NULL; 23: SQL NULL;

But in parent table `DB/documents`, in index `PRIMARY`,
the closest match we can find is record:
PHYSICAL RECORD: n_fields 17; compact format; info bits 0
0: len 8; hex 00000000073d26af; asc =& ;; 1: len 6; hex 0001666c053f; asc fl ?;; 2: len 7; hex 800045801e02da; asc E ;; 3: len 30; hex 64366562393630322d396163622d346337622d616461332d323634323438; asc d6eb9602-9acb-4c7b-ada3-264248;...(truncated); 4: SQL NULL; 5: len 1; hex 01; asc ;; 6: SQL NULL; 7: SQL NULL; 8: len 30; hex 412062616374657269616c206d6574686f6420666f7220746865206e6974; asc A bacterial method for the nit;...(truncated); 9: len 1; hex 80; asc ;; 10: len 8; hex 80001245c7719188; asc E q ;; 11: len 4; hex 4368656d; asc Chem;; 12: len 4; hex 800007d1; asc ;; 13: SQL NULL; 14: SQL NULL; 15: SQL NULL; 16: len 4; hex 4aa69326; asc J &;;

------------------------
LATEST DETECTED DEADLOCK
------------------------
090908 17:24:00
*** (1) TRANSACTION:
TRANSACTION 1 1718374972, ACTIVE 27 sec, process no 8496, OS thread id 1157896528 inserting
mysql tables in use 1, locked 1
LOCK WAIT 109 lock struct(s), heap size 30704, undo log entries 498
MySQL thread id 7486285, query id 1291770744 mysql.db_user.internal 10.0.6.1 db_user update
I
...

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 4327111 n bits 352 index `PRIMARY` of table `DB/document_identifiers` trx id 1 1718374972 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) TRANSACTION:
TRANSACTION 1 1718342021, ACTIVE 285 sec, process no 8496, OS thread id 1159653712 inserting, thread declared inside InnoDB 1
mysql tables in use 1, locked 1
332 lock struct(s), heap size 47088, undo log entries 922
MySQL thread id 7485576, query id 1291761364 live2.local 10.0.1.2 db_user update

...

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 4327111 n bits 352 index `PRIMARY` of table `DB/document_identifiers` trx id 1 1718342021 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 4327111 n bits 352 index `PRIMARY` of table `DB/document_identifiers` trx id 1 1718342021 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 1 1718463159
Purge done for trx's n:o < 1 1718113147 undo n:o < 0 0
History list length 11207
Total number of lock structs in row lock hash table 902
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 8496, OS thread id 1162357072
MySQL thread id 7487540, query id 1292003912 localhost root
SHOW INNODB STATUS
---TRANSACTION 0 0, not started, process no 8496, OS thread id 1157761360
MySQL thread id 7487527, query id 1291996472 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718460223, not started, process no 8496, OS thread id 1156274512
MySQL thread id 7487516, query id 1291996374 live2.local 10.0.1.2 db_user
---TRANSACTION 1 1718460251, not started, process no 8496, OS thread id 1163979088
MySQL thread id 7487503, query id 1291996433 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718463125, not started, process no 8496, OS thread id 1151408464 waiting in InnoDB queue
mysql tables in use 5, locked 3
MySQL thread id 7485728, query id 1292003904 mysql.db_user.internal 10.0.6.1 db_user init
DELETE FROM document_references

WHERE referenced_document_id = '118084217'

OR document_id = '118084217'
---TRANSACTION 1 1718463007, not started, process no 8496, OS thread id 1184524624
MySQL thread id 7485672, query id 1292003606 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718454697, not started, process no 8496, OS thread id 1169115472
MySQL thread id 7485557, query id 1291979067 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718454448, not started, process no 8496, OS thread id 1166141776
MySQL thread id 7485289, query id 1291978168 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718463124, not started, process no 8496, OS thread id 1152354640 waiting in InnoDB queue
mysql tables in use 3, locked 3
MySQL thread id 7484723, query id 1292003882 mysql.db_user.internal 10.0.6.1 db_user update
INSERT INTO document_references (document_id, referenced_document_id, position)

VALUES ('105634175', '105633300', 24)
---TRANSACTION 1 1718447434, not started, process no 8496, OS thread id 1157626192
MySQL thread id 7484598, query id 1291963794 live2.local 10.0.1.2 db_user
---TRANSACTION 1 1718459460, not started, process no 8496, OS thread id 1161005392
MySQL thread id 7483715, query id 1291993530 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718459133, not started, process no 8496, OS thread id 1178577232
MySQL thread id 7481841, query id 1291992310 live2.local 10.0.1.2 db_user
---TRANSACTION 1 1718405116, not started, process no 8496, OS thread id 1184119120
MySQL thread id 7481643, query id 1291846123 live2.local 10.0.1.2 db_user
---TRANSACTION 1 1718417989, not started, process no 8496, OS thread id 1183578448
MySQL thread id 7481057, query id 1291881569 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718418004, not started, process no 8496, OS thread id 1179523408
MySQL thread id 7479240, query id 1291881592 mysql.db_user.internal 10.0.6.1 db_user
---TRANSACTION 1 1718427785, not started, process no 8496, OS thread id 1148164432
MySQL thread id 1407, query id 1291987849 live2.local 10.0.1.2 db_user
---TRANSACTION 1 1718463158, ACTIVE 0 sec, process no 8496, OS thread id 1153435984 waiting in InnoDB queue
mysql tables in use 2, locked 0
MySQL thread id 7486110, query id 1292003902 live2.local 10.0.1.2 db_user Sorting result

...

---TRANSACTION 1 1718463157, ACTIVE 0 sec, process no 8496, OS thread id 1153165648 waiting in InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 7408660, query id 1292003900 live2.local 10.0.1.2 db_user statistics

...

Trx read view will not see trx with id >= 1 1718463158, sees < 1 1718113094
---TRANSACTION 1 1718463156, ACTIVE 0 sec, process no 8496, OS thread id 1182361936 waiting in InnoDB queue
mysql tables in use 1, locked 0
MySQL thread id 7487483, query id 1292003899 live2.local 10.0.1.2 db_user Sending data

...

Trx read view will not see trx with id >= 1 1718463157, sees < 1 1718113094

... MANY MORE TRANSACTIONS REMOVED ...

---TRANSACTION 1 1718113094, ACTIVE 2227 sec, process no 8496, OS thread id 1095842128 waiting in InnoDB queue
mysql tables in use 3, locked 0
MySQL thread id 7480141, query id 1291156498 mysql.db_user.internal 10.0.6.1 db_user Sending data
SELECT dr.referenced_document_id FROM document_references dr

JOIN profile_documents pd ON (pd.document_id = dr.document_id)

WHERE pd.profile_id = '17850'

AND dr.referenced_document_id NOT IN (SELECT document_id FROM profile_documents WHERE profile_id = '17850')
Trx read view will not see trx with id >= 1 1718113130, sees < 1 1717825563
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
31091592 OS file reads, 450751812 OS file writes, 357154035 OS fsyncs
23.22 reads/s, 21975 avg bytes/read, 179.10 writes/s, 54.92 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 23639, free list len 25997, seg size 49637,
38385249 inserts, 36695967 merged recs, 6330679 merges
Hash table size 42499631, used cells 18594314, node heap has 36065 buffer(s)
1016.11 hash searches/s, 3652.12 non-hash searches/s
---
LOG
---
Log sequence number 140 590482397
Log flushed up to 140 590480036
Last checkpoint at 140 583393331
0 pending log writes, 0 pending chkp writes
354373167 log i/o's done, 51.29 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 23815355160; in additional pool allocated 1048576
Buffer pool size 1310720
Free buffers 0
Database pages 1274648
Modified db pages 13653
Pending reads 1
Pending writes: LRU 0, flush list 127, single page 0
Pages read 51021609, created 1272633, written 108211751
31.15 reads/s, 2.15 creates/s, 147.99 writes/s
Buffer pool hit rate 998 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 75 queries in queue
62 read views open inside InnoDB
Main thread process no. 8496, id 1147488592, state: sleeping
Number of rows inserted 168771716, updated 4141971, deleted 25464981, read 181401170686
201.77 inserts/s, 2.04 updates/s, 33.37 deletes/s, 7648.05 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

And here are my InnoDB variables:

+---------------------------------+------------------------+
| Variable_name | Value |
+---------------------------------+------------------------+
| innodb_additional_mem_pool_size | 1048576 |
| innodb_autoextend_increment | 8 |
| innodb_buffer_pool_awe_mem_mb | 0 |
| innodb_buffer_pool_size | 21474836480 |
| innodb_checksums | ON |
| innodb_commit_concurrency | 0 |
| innodb_concurrency_tickets | 500 |
| innodb_data_file_path | ibdata1:10M:autoextend |
| innodb_data_home_dir | |
| innodb_doublewrite | ON |
| innodb_fast_shutdown | 1 |
| innodb_file_io_threads | 4 |
| innodb_file_per_table | ON |
| innodb_flush_log_at_trx_commit | 1 |
| innodb_flush_method | |
| innodb_force_recovery | 0 |
| innodb_lock_wait_timeout | 50 |
| innodb_locks_unsafe_for_binlog | OFF |
| innodb_log_arch_dir | |
| innodb_log_archive | OFF |
| innodb_log_buffer_size | 1048576 |
| innodb_log_file_size | 5242880 |
| innodb_log_files_in_group | 2 |
| innodb_log_group_home_dir | ./ |
| innodb_max_dirty_pages_pct | 90 |
| innodb_max_purge_lag | 0 |
| innodb_mirrored_log_groups | 1 |
| innodb_open_files | 300 |
| innodb_rollback_on_timeout | OFF |
| innodb_support_xa | ON |
| innodb_sync_spin_loops | 20 |
| innodb_table_locks | ON |
| innodb_thread_concurrency | 8 |
| innodb_thread_sleep_delay | 10000 |
+---------------------------------+------------------------+

Many thanks in advance,

Ben

Options: ReplyQuote




Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.