3

It was suggested I post here as opposed to StackOverflow. I'm new to debugging mysql/innodb issues so here is the best I have:

I'm trying to run an integration test so these results are near identical each time, the test is consistently hanging at the same spot while trying to execute the same update. I'm getting a conflicting process that has locked the table the update is trying to use. If I just let it run I get a lock timeout exceeded exception, and when i kill the troubling process things do start moving again, though an exception is thrown in my test - "Caused by: org.mariadb.jdbc.internal.util.dao.QueryException: Could not send query: Last stream not finished".

Relevant information I can find from,

SHOW ENGINE INNODB STATUS;

------------
TRANSACTIONS
------------

---TRANSACTION 2609485, ACTIVE 36 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 9 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 2
MySQL thread id 231, OS thread handle 162200, query id 10577 localhost 127.0.0.1 root updating
/* update com.ipl.inspire.imp.radio.entities.entity.circuit.Circuit */ 
update abstract_asset_network
    set lastUpdated='2016-01-14 15:34:10.2', leg=0, networkStatus_id=4,
        parent_id=NULL, xCoordinate=0, yCoordinate=0 where id=33
Trx read view will not see trx with id >= 2609485, sees < 2609468
------- TRX HAS BEEN WAITING 35 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 89945 page no 3 n bits 72 index PRIMARY
  of table `imptest`.`abstract_asset_network` trx id 2609485
  lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 9; compact format; info bits 0
 0: len 4; hex 80000021; asc    !;;
 1: len 6; hex 00000027d0f8; asc    '  ;;
 2: len 7; hex 6e0000019b2827; asc n    (';;
 3: len 7; hex 99985cf88a07d0; asc   \    ;;
 4: len 1; hex 00; asc  ;;
 5: len 4; hex 80000000; asc     ;;
 6: len 4; hex 80000000; asc     ;;
 7: len 4; hex 80000003; asc     ;;
 8: SQL NULL;

------------------
---TRANSACTION 2609468, ACTIVE 38 sec
10 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 3
MySQL thread id 228, OS thread handle 162260, query id 10138 localhost 127.0.0.1 root cleaning up
Trx read view will not see trx with id >= 2609468, sees < 2609468

Two transactions here, and it seems that trx 2609468 has caused a lock on the query update is trying to execute (trx 2609485) 2 seconds afterwards. The lock seems to last forever (or until innodb_lock_wait_timeout gets hit, which I have tried increasing).

SELECT * FROM INFORMATION_SCHEMA.INNODB_TRX

trx_id  trx_state   trx_started         trx_requested_lock_id  trx_wait_started     trx_weight  trx_mysql_thread_id   trx_query                                                                                                                                                                                                                         trx_operation_state    trx_tables_in_use    trx_tables_locked   trx_lock_structs   trx_locks_memory_bytes    trx_rows_locked   trx_rows_modified   trx_concurrency_tickets    trx_isolation_level
2609485 LOCK WAIT   2016-01-14 15:34:17 2609485:89945:3:3      2016-01-14 15:34:18  11          231                   update abstract_asset_network set lastUpdated='2016-01-14 15:34:10.2', leg=0, networkStatus_id=4, parent_id=NULL, xCoordinate=0, yCoordinate=0 where id=33                                                                        starting index read    1                    5                   9                  1136                      4                 2                   0                          REPEATABLE READ
2609468 RUNNING     2016-01-14 15:34:15                                             13          228                                                                                                                                                                                                                                                                            0                    6                   10                 1136                      4                 3                   0                          REPEATABLE READ

Which suggests pretty much what is explained from the innodb status query I believe, though maybe someone else can make more sense of it.

The last query that was executed on process id 228 was (from the general_log)

228 Query   /* select generatedAlias0 from Imp as generatedAlias0 */
select imp0_.id as id1_67_, imp0_.black as black2_67_, imp0_.current as current3_67_,
       imp0_.name as name4_67_, imp0_.redMessageHost as redMessa5_67_,
       imp0_.redMessagePort as redMessa6_67_, imp0_.site_id as site_id7_67_
    from imp imp0_

and then later:

231 Query   update abstract_asset_network
     set lastUpdated='2016-01-14 15:34:10.2', leg=0, networkStatus_id=4,
         parent_id=NULL, xCoordinate=0, yCoordinate=0 where id=33
.
.
.
8 Query kill 228
231 Query   COMMIT
231 Query   set autocommit=1
231 Query   SELECT 1
231 Query   set autocommit=0
231 Query   /* select ...

But I don't think it's relevant and it's more to do with the process being re-used for "cleaning up" something else. However this same scenario with the same processes/timing/lock/queries happens the same every single time with the only things changing being just the ids.

  • What other statements were in the same transaction? Probably something earlier caused the lock. – Rick James Jan 14 '16 at 23:48
1

What is your MySQL version? I think it's maybe the bug of MySQL. MySQL bug cleaning up

It's fixed in version 5.6.17 MySQL 5.6.17 Release notes

InnoDB: SHOW ENGINE INNODB STATUS output showed a “cleaning up” state for > an idle thread. Thread state information was not reset after statement execution. (Bug #21974225, Bug #78777)

Hope it will help you.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.