Howdy, Stranger!

It looks like you're new here. If you want to get involved, click one of these buttons!

Welcome to the CollectiveAccess support forum! Here the developers and community answer questions related to use of the software. Please include the following information in every new issue posted here:

  1. Version of the software that is used, along with browser and version

  2. If the issue pertains to Providence, Pawtucket or both

  3. What steps you’ve taken to try to resolve the issue

  4. Screenshots demonstrating the issue

  5. The relevant sections of your installation profile or configuration including the codes and settings defined for your local elements.


If your question pertains to data import or export, please also include:

  1. Data sample

  2. Your mapping


Answers may be delayed for posts that do not include sufficient information.

Lock wait timeout exceeded Issue

edited January 2014 in Troubleshooting
Hi,
We are facing an issue with saving records in collectiveaccess. The save operation fails with "Lock wait timeout exceeded; try restarting transaction [250]" error. Any help on this?

Thanks.

Comments

  • How often does this happen? Is the server heavily loaded?
  • I created a new solr schema and indexed it, since then i am facing this issue. However, i found that saving operation for some records is successful.
  • This is happening while you're indexing?
  • Well, after indexing. Indexing went very well, we can search records, we can edit and save some of them but most of them give time out error.
  • The exact error message is:

    There are errors preventing information in specific fields from being saved as noted below.
    • Lock wait timeout exceeded; try restarting transaction [250]
  • Try restarting mysql. Does the problem persist after that?
  • We have tried restarting mysql many times. Also, we have tested it on multiple machines/installations but got the same error.

  • Something is locking tables in your database. Try running SHOW ENGINE INNODB STATUS  directly in the database after you get this error. That output should give you an idea of what's causing the lock. What version of mysql are you running?
  • We got this error on two different mysql version: 5.5.27 and 5.1.69-log.
    Please find below the output of running SHOW ENGINE INNODB STATUS after getting the time out error


    SQL result


    Host: 127.0.0.1

    Database:

    Generation Time: Jan 07, 2014 at 10:21 AM

    Generated by: phpMyAdmin 3.5.2.2 / MySQL 5.5.27

    SQL query: SHOW ENGINE INNODB STATUS;


    Rows: 1



    Type
    Name
    Status
    InnoDB

    =====================================
    140107 10:21:38 INNODB MONITOR OUTPUT
    =====================================
    Per second averages calculated from the last 25 seconds
    -----------------
    BACKGROUND THREAD
    -----------------
    srv_master_thread loops: 4351 1_second, 4350 sleeps, 425 10_second, 100 background, 100 flush
    srv_master_thread log flush and writes: 4361
    ----------
    SEMAPHORES
    ----------
    OS WAIT ARRAY INFO: reservation count 2473, signal count 2477
    Mutex spin waits 5462, rounds 14624, OS waits 54
    RW-shared spins 2335, rounds 67271, OS waits 2045
    RW-excl spins 476, rounds 12054, OS waits 368
    Spin rounds per wait: 2.68 mutex, 28.81 RW-shared, 25.32 RW-excl
    ------------
    TRANSACTIONS
    ------------
    Trx id counter 67CF98E
    Purge done for trx's n:o < 67C8193 undo n:o < 0
    History list length 324
    LIST OF TRANSACTIONS FOR EACH SESSION:
    ---TRANSACTION 0, not started
    MySQL thread id 464, OS thread handle 0x247c, query id 2003992 localhost 127.0.0.1 root
    SHOW ENGINE INNODB STATUS
    ---TRANSACTION 67C5ECE, ACTIVE 2806 sec
    14 lock struct(s), heap size 1024, 25 row lock(s), undo log entries 93
    MySQL thread id 281, OS thread handle 0x2690, query id 2003991 localhost 127.0.0.1 root
    Trx read view will not see trx with id >= 67C5ECF, sees < 67C5ECF
    --------
    FILE I/O
    --------
    I/O thread 0 state: wait Windows aio (insert buffer thread)
    I/O thread 1 state: wait Windows aio (log thread)
    I/O thread 2 state: wait Windows aio (read thread)
    I/O thread 3 state: wait Windows aio (read thread)
    I/O thread 4 state: wait Windows aio (read thread)
    I/O thread 5 state: wait Windows aio (read thread)
    I/O thread 6 state: wait Windows aio (write thread)
    I/O thread 7 state: wait Windows aio (write thread)
    I/O thread 8 state: wait Windows aio (write thread)
    I/O thread 9 state: wait Windows aio (write thread)
    Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
    ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
    Pending flushes (fsync) log: 0; buffer pool: 0
    98590 OS file reads, 2616 OS file writes, 1419 OS fsyncs
    8.60 reads/s, 16384 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
    -------------------------------------
    INSERT BUFFER AND ADAPTIVE HASH INDEX
    -------------------------------------
    Ibuf: size 1, free list len 647, seg size 649, 87 merges
    merged operations:
    insert 171, delete mark 14, delete 0
    discarded operations:
    insert 0, delete mark 0, delete 0
    Hash table size 69257, node heap has 78 buffer(s)
    1226.95 hash searches/s, 3497.98 non-hash searches/s
    ---
    LOG
    ---
    Log sequence number 17763910028
    Log flushed up to   17763910028
    Last checkpoint at  17763910028
    0 pending log writes, 0 pending chkp writes
    1083 log i/o's done, 0.00 log i/o's/second
    ----------------------
    BUFFER POOL AND MEMORY
    ----------------------
    Total memory allocated 17006592; in additional pool allocated 0
    Dictionary memory allocated 1157970
    Buffer pool size   1024
    Free buffers       0
    Database pages     946
    Old database pages 329
    Modified db pages  0
    Pending reads 0
    Pending writes: LRU 0, flush list 0, single page 0
    Pages made young 236069, not young 0
    39.16 youngs/s, 0.00 non-youngs/s
    Pages read 98451, created 85, written 1374
    8.60 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.68/s, Random read ahead 0.00/s
    LRU len: 946, unzip_LRU len: 0
    I/O sum[457]:cur[8], unzip sum[0]:cur[0]
    --------------
    ROW OPERATIONS
    --------------
    0 queries inside InnoDB, 0 queries in queue
    2 read views open inside InnoDB
    Main thread id 5516, state: sleeping
    Number of rows inserted 110, updated 200, deleted 6, read 964294834
    0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 256456.66 reads/s
    ----------------------------
    END OF INNODB MONITOR OUTPUT
    ============================
  • edited January 2014
    This is on Windows, right?

    Next time you get the error try running this query on the MySQL command line and tell me what you see:

    SELECT * FROM INFORMATION_SCHEMA.INNODB_TRX
  • Also, run this and let me know what the output is:

    SHOW VARIABLES WHERE Variable_name = 'autocommit';
  • edited January 2014
    We have the same issue on both windows and linux. The output of the previous query and the below given outputs are on windows though.

    SELECT * FROM INFORMATION_SCHEMA.INNODB_TRX

    SQL query: SELECT * FROM INFORMATION_SCHEMA.INNODB_TRX
    LIMIT 0, 30 ;


    Rows: 1



    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_lock_memory_bytes
    trx_rows_locked
    trx_rows_modified
    trx_concurrency_tickets
    trx_isolation_level
    trx_unique_checks
    trx_foreign_key_checks
    trx_last_foreign_key_error
    trx_adaptive_hash_latched
    trx_adaptive_hash_timeout
    6897A1C RUNNING 2014-01-09 12:03:54 NULLNULL103 2162 NULLNULL0 0 14 1024 24 89 0 REPEATABLE READ 1 1 NULL0 0

    SHOW VARIABLES WHERE Variable_name = 'autocommit';


    Generated by: phpMyAdmin 3.5.2.2 / MySQL 5.5.27

    SQL query: SHOW VARIABLES WHERE Variable_name = 'autocommit';


    Rows: 1



    Variable_name
    Value
    autocommit ON
  • Thanks for the info. So there is a transaction running that's locking rows. Now to figure out what it is. This sounds like it's pretty repeatable for you. When you restart MySQL does the error recur immediately, or only after CA has been used for a bit?
  • It is a quite repeatable and consistent issue. Actually, for those objects for whom we have this issue, it does not matter when the save operation is performed. It happens immediately for such objects.
  • Can you tell me if there is anything unusual about these objects? Can I see an example?
  • I can reproduce this now. It's something specific to the Solr indexer. Can you file a ticket for this on http://clangers.collectiveaccess.org/jira? We're looking into it.
  • Can you rebuild the hierarchical indices from the maintenance menu under "Manage" > "Administrate" ? The issue I was seeing was due to corrupt hierarchical indices, which can happen from time to time. I'm not sure if this is the same issue you're seeing though.
  • Thanks Seth, i will do the hierarchical indices and will inform you the outcome. Probably you have identified the right reason because problem started once we rebuild the indices, before that (with old indexing) there was no such issue.
  • Ticket number for this issue is PROV-767.

    Thanks.
  • edited February 2014
    The time out error while updating records surfaced again. Like
    previously, the search indexing went well, however the hierarchical and
    sort value indexing stopped half way. The rest of the information about
    this particular issue remains the same as given above in our previous
    discussions.

    I tried to solve this issue by setting a higher value for 'innodb_lock_wait_timeout' on mysql server, but in vain.

    Could you please look into this issue and suggest any way forward?

    Many thanks.
  • Your suggested patch had issues, but I think it was on the right trail. There's a patch in GitHub master for this now... give it another try and let me know how it works. Thanks.
  • I have logged some information, which you can find in the attached files. Could you please have a look on it and find if some thing is happening wrong.

    'object_updated.txt' file contains information about the object which i updated and got the time out error. In this case, it is an object with object_id 33000. This log was collected in 'update' of class 'BaseModelWithAttributes'

    'indexing_performed.txt' file contains information (table number and row id) about the records which were indexed through indexRow function. This log was collected in 'indexRow' function of class 'SearchIndexer'.


    You can observe in the 'indexing_performed.txt' file that following two strange things are happening:
    1. Many objects of ca_object table (table number 57) other than the actual updated object(33000 object id) are being indexed.
    2. Many records from a table with number '72' are also being indexed. This is 'ca_places' table, which contains information about places related to an object. In this particular case, the object 33000 has only one place related to it. However, as you can see, other non-related places are being indexed.

    Perhaps you can suggest a fix for this?

    Many thanks.
Sign In or Register to comment.