---TRANSACTION 2821395544, ACTIVE 212 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 3397, OS thread handle 139772570343168, query id 195064 10.0.5.128 appuser updating
UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'contact'
------- TRX HAS BEEN WAITING 212 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1087 page no 3 n bits 248 index PRIMARY of table `ccbuser`.`EO_PK_TABLE` trx id 2821395544 lock_mode X locks rec but not gap waiting
The processlist snap shot
There is a lock over the index , but what is causing the lock and why it happens ?
---TRANSACTION 2821458353, ACTIVE 135 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 2
MySQL thread id 5455, OS thread handle 139772578862848, query id 590796 10.0.5.128 appuser Searching rows for update
UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'service'
------- TRX HAS BEEN WAITING 135 SEC FOR THIS LOCK TO BE GRANTED:
It is noted that the transaction have UNDO log entries. While Updating the records from application perspective , the sequence generation was supposed to be the first step in the transaction. The UNDO entries further for the queries gives the hint that it is not start of the transaction or there is an open transaction.
1) Setting the ISOLATION LEVEL
2) Increment the EO_PK_TABLE based on NAME Column.
3)Fetch the next ID
4)Insert into relevant table
5)Commit.
Query Log for Analysis .
I have enabled the query log on this non-prod environment to get the query write pattern. But at cases the transactions are not committed by the application .After the UPDATE over EO_PK_TABLE it keeps on Updating the columns in EO_PK_TABLE.
Let us consider a transaction handled by Query ID 5068.
5068 Query commit
-- Transaction starts
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'contact'
5068 Query SELECT @next contactId
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'account_vod_thrsh'
5068 Query SELECT @next id
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'address'
5068 Query SELECT @next addrId
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'service'
5068 Query SELECT @next servId
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'customer_registration'
5068 Query SELECT @next id
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'location'
5068 Query SELECT @next locId
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'bill_delivery'
5068 Query SELECT @next billDelId
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'account'
5068 Query SELECT @next acctId
5068 Query set tx_isolation='READ-COMMITTED'
5068 Query UPDATE EO_PK_TABLE SET PK = (@next := PK + 100) WHERE NAME = 'bob'
5068 Query SELECT @next bobId
5068 Query INSERT INTO account(sales_person, do_not_auto_script, direct_acct, mso_id, parental_control, create_date, bu_id, sales_method, acct_id, cancel_reasons_id, tv_dma_id, tax_number, verified_date, status_change_date, external_creation_date, customer_id, attach_bill_cycle, contact_id, compliment_acct, acct_comment, acct_status_id, complaintmode_acct, bill_del_type_id, legacy_id, acct_type_id, tax_exempt, verified, psa_acct_id, bb_acct_id, anonymized, acct_reg_num, email_inv_format, mso_name, verified_channel, offer_type, external_id_suffix, external_id_prefix, active_logins_count, acct_bill_mode, shipping_add_id) VALUES (NULL, 'F', NULL, NULL, NULL, '2017-11-30 14:43:16', 65, 'Call Center', 42389538, NULL, '001', NULL, NULL, NULL, NULL, '171130144316899', 'F', 42391292, 'F', NULL, 1, NULL, NULL, NULL, 2, NULL, NULL, NULL, '171130144316899', NULL, '20171130144316912', NULL, NULL, NULL, NULL, '30144316912', '201711', NULL, 'Monthly', 4.4585868E+7)
5068 Query rollback
This makes sense the application is not closing the transaction perfectly. With persistent connection they use the same connection thread without a proper COMMIT. It causes the lock over the records and the dead lock arises. Now we have the root cause of the problem .
As it is non-prod environment I had the luxury to troubleshoot using Query log. But query log on production ENV will come with a high penalty on IO. So it is good to use the Performance Schema inbuilt with MySQL for trouble shooting.
Performance Schema to Troubleshoot:
The Performance schema is used to analyze the transaction history and its relevant info. Here the query ID = 5511 and Transaction ID = 2821461197
These information and stats were passed on to development team to fix the code. Once the issue is nailed down perfectly it can be fixed easily. The code was fixed, tested and shipped to production. Now the DB queries scales better .
.png)
.png)
.svg)
