What do I wrong with INNODB Lock?

Question

I working on a System with handels a lot of Update, Insert and Delete Requests. That's why I choosed INNODB as my Storage Engine cause of the Row Locks. We are updating 60.000 Records every 10 Minutes. And we are using Gearman to parallise our Work on different Servers. Code is in PHP and we are using Zend Framework.

So lets beginn with the description of our problem. We are logging the Errors and nearly every 5 - 20 Minutes one Error occurs.

SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

Simple expand the "lock wait timeout" isnt helpfull for us, because we try to update as fast as possible.

To get more information i done SHOW INNODB STATUS\G. One thing made me asking - what the hack?

---TRANSACTION 0 18126657, ACTIVE 54 sec, process no 16154, 
OS thread id 47956454176512 fetching rows, thread declared inside InnoDB 68 mysql tables in use 1, 
locked 1 1204 lock struct(s), heap size 112624, 65338 row lock(s), undo log entries 44 
MySQL thread id 3331522, query id 103362521 [ServerIP] [USER] Updating 
UPDATE userproducts SET lowest_price=16.96, last_lowest_price_update='2012-09-09 20:07:30' WHERE product_id LIKE 'XXX'

65388 Rows are locked, because of this simple Update? Or do i just missanderstand something? Following the PHP Code which has done this UPDATE.

$this->db->beginTransaction();

    try {
        for($i = 0; $i < count($products); $i++)
        {
            if(isset($products[$i]['price_total_end']))
            {
                if(count($products[$i]['price_total_end']) > 1)
                {
                    $this->db->query("UPDATE userproducts SET lowest_price=".$products[$i]['price_total_end'][1].", last_lowest_price_update='".date("Y-m-d H:i:s", time())."' WHERE product_id LIKE '".$products[$i]['p_id']."'");
                } elseif(count($asin[$i]['price_total_end']) == 1) {
                    $this->db->query("UPDATE userproducts SET lowest_price=-1, last_lowest_price_update='".date("Y-m-d H:i:s", time())."' WHERE product_id LIKE '".$products[$i]['p_id']."'");
                }
            }
        }
        $this->db->commit();
    } catch (Exception $e) {
        $this->db->rollBack();
        echo $e->getMessage();
    }

The Array $products has in his first Level 50 Entries. So the count counts until 50 which shouldn't be that much, or is this absolutly unifficient? Next thing which schould be not forgotten is, that wie have 20 Workers which can execude this Query simultainesly.

The last important info - i think - is the mysql_report.

MySQL 5.1.63-0+squeeze1  uptime 13 9:11:39      Sun Sep  9 20:44:50 2012

__ Key ___
Buffer used    55.00k of  16.00M  %Used:   0.34
  Current       2.92M            %Usage:  18.28
Write hit      99.95%
Read hit      100.00%


__ Questions ___
Total         103.61M    89.6/s
  DMS          90.73M    78.5/s  %Total:  87.57
  Com_          8.57M     7.4/s            8.27
  COM_QUIT      3.34M     2.9/s            3.22
  QC Hits     922.81k     0.8/s            0.89
  +Unknown     46.70k     0.0/s            0.05
Slow 2 s        9.33M     8.1/s            9.00  %DMS:  10.28  Log:  ON
DMS            90.73M    78.5/s           87.57
  INSERT       60.63M    52.4/s           58.51         66.82  
  UPDATE       17.80M    15.4/s           17.17         19.61
  DELETE        9.55M     8.3/s            9.22         10.53
  SELECT        2.76M     2.4/s            2.66          3.04
  REPLACE           0       0/s            0.00          0.00
Com_            8.57M     7.4/s            8.27
  set_option    3.40M     2.9/s            3.28
  show_fields   2.88M     2.5/s            2.78
  begin         1.13M     1.0/s            1.09


__ SELECT and Sort ____
Scan            3.60M     3.1/s %SELECT: 130.54
Range              47     0.0/s            0.00
Full join          24     0.0/s            0.00
Range check         0       0/s            0.00
Full rng join       1     0.0/s            0.00
Sort scan      24.32k     0.0/s
Sort range      1.69M     1.5/s
Sort mrg pass       0       0/s


__ Query Cache ___

Memory usage    1.05M of  16.00M  %Used:   6.57   
Block Fragmnt   4.55%   
Hits          922.81k     0.8/s   
Inserts         2.11M     1.8/s   
Insrt:Prune   2.36k:1     1.8/s   
Hit:Insert     0.44:1


__ Table Locks ____  
Waited            658     0.0/s  %Total:   0.00   
Immediate      90.73M    78.5/s


__ Tables ___   
Open              128 of  128    %Cache: 100.00  
Opened          3.95k     0.0/s


__ Connections __   
Max used          301 of  300      %Max: 100.33  
Total           3.34M     2.9/s


__ Created Temp ___    
Disk table      2.88M     2.5/s   
Table           2.89M     2.5/s    Size:  32.0M   
File                5     0.0/s


__ Threads ___    
Running            21 of  168   
Cached              6 of    8      %Hit:  97.09  
Created        97.29k     0.1/s    
Slow                0       0/s


__ Aborted ___    
Clients         2.45k     0.0/s 
Connects        2.75k     0.0/s


__ Bytes ___    
Sent           11.04G    9.5k/s  
Received       23.13G   20.0k/s   

__ InnoDB Buffer Pool _____    
Usage          82.86M of   1.46G  %Used:   5.52    
Read hit      100.00%    
Pages    
  Free         90.70k            %Total:  94.48    
  Data          4.92k                      5.12 %Drty:   4.07    
  Misc            386                      0.40  
  Latched           0                      0.00    
Reads         610.88G  528.3k/s 
  From file       816     0.0/s            0.00   
  Ahead Rnd         3     0.0/s    
  Ahead Sql        27     0.0/s    
Writes        614.37M   531.3/s    
Flushes        10.07M     8.7/s   
Wait Free           0       0/s


__ InnoDB Lock ___
Waits          837060     0.7/s    
Current            19
Time acquiring   
  Total     157140176 ms
  Average       18772 ms  
  Max           59096 ms


__ InnoDB Data, Pages, Rows __    
Data 
  Reads           919     0.0/s 
  Writes       11.96M    10.3/s  
  fsync         6.26M     5.4/s    
  Pending
    Reads           0
    Writes          0
    fsync           0

Pages   
  Created      39.41k     0.0/s    
  Read          2.64k     0.0/s   
  Written      10.07M     8.7/s    

Rows
  Deleted      40.82M    35.3/s
  Inserted     42.90M    37.1/s
  Read        540.45G  467.4k/s    
  Updated      47.48M    41.1/s

So to come back to the over all Question. Why do we get always the 1205 Lock wait timeout error?

UPDATE: I tried now several other things. First, i changed the INSERT ... ON DUPLICATE KEY UPDATE to UPDATE and if nothing got effected the program should do the insert. Because of the following two reasons. 1. 99,9% of this operations are the UPDATE. 2. I thougt - not clear about that faked - that maybe a INSERT occurs an table lock.

But nothing changed. After that I tried the tipp with the uniquekey. Nothing changed.

Then I had the idea, that there were many "sleeping" processes at MySQL. I thing this get caused by the very very long running Gearman Scripts?? So I changed for example the Code for the UPDATE like i posted before.

$this->db->beginTransaction();

        try {
            for($i = 0; $i < count($asin); $i++)
            {
                if(isset($asin[$i]['price_total_end']))
                {
                    if(count($asin[$i]['price_total_end']) > 1)
                    {
                        // Es konnten Konkurrenten ausgemacht werden
                        if( $asin[$i]['price_total_end'][0] > 0 )
                        {
                            // Prüfe ob der eigene Preis der günstigste ist
                            if( $asin[$i]['merchant_end'][0] == $merchantId )
                            {
                                // Ja der eigene Preis ist der günstigste, deshalb soll der nächste Preis der lowest sein.
                                $this->db->query("UPDATE userproducts SET lowest_price=".$asin[$i]['price_total_end'][1].", last_lowest_price_update='".date("Y-m-d H:i:s", time())."' WHERE product_id LIKE '".$asin[$i]['asin']."'");
                            } else {
                                $this->db->query("UPDATE userproducts SET lowest_price=".$asin[$i]['price_total_end'][0].", last_lowest_price_update='".date("Y-m-d H:i:s", time())."' WHERE product_id LIKE '".$asin[$i]['asin']."'");
                            }
                        }
                    } elseif(count($asin[$i]['price_total_end']) == 1) {
                        if( $asin[$i]['price_total_end'][0] >= 0 )
                        {
                            $this->db->query("UPDATE userproducts SET lowest_price=-1, last_lowest_price_update='".date("Y-m-d H:i:s", time())."' WHERE product_id LIKE '".$asin[$i]['asin']."'");
                        }
                    }
                }
            }
            $this->db->commit();
        } catch (Exception $e) {
            $this->db->rollBack();
            echo $e->getMessage();
        }
        **$this->db->closeConnection();**

But nothing changed. Connections are still at 301 and Threads at 32. Did i something wrong with that Code.

I really can not face the problem.

We very welcome your ideas and tipps. Thanks Guys.

Answer 1

try first fetching primary keys for all products using:

SELECT primaryKey WHERE product_id LIKE '".$products[$i]['p_id']."'"

and then looping over the results and updating them using the primaryKey in the WHERE part.

repeat that for all your $products. and commit at the very end after all iterations.

my gut feelings / earlier experience tell that you should be able to avoid deadlocks in this way but sadly i cannot provide explanation why.