Error No. 1205 – Lock Wait Timeout Exceeded

[robvas]

Any ideas? Every time I have a table with over a couple hundred rows, I get the error:

Code:

SQLyog Job Agent Version 9.10 Copyright(c) Webyog Softworks Pvt. Ltd. All Rights Reserved.

Sync started at Thu Jul 14 14:40:45 2011

Table SrcRows TgtRows Inserted Updated Deleted
========================= ======= ======= ======== ======= =======
`activities` 0 0 0 0 0
`addresses` 8054 8054 There was an error while executing a query. The query and the error has been logged in the log file.
0 0 0
`award_eligibilities` 0 0 0 0 0
`awards` 0 0 0 0 0
`competitions` 25 25 0 0 0
`contacts` 8062 8062 There was an error while executing a query. The query and the error has been logged in the log file.
0 0 0
`custom_prompts` 34 34 0 0 0
`destinations` 0 0 0 0 0
`edge_points` 925 925 0 0 0
`eligibilities` 54590 54590 There was an error while executing a query. The query and the error has been logged in the log file.
0 0 0
`entries` 378087 378087 There was an error while executing a query. The query and the error has been logged in the log file.
0 0 0
`evaluations` 1205 1205 There was an error while executing a query. The query and the error has been logged in the log file.
0 0 0
`evaluations_udfs` 307 307 0 0 0
`flag_defs` 38 38 0 0 0
`follows` 107 107 0 0 0
`friendships` 3955 3955 There was an error while executing a query. The query and the error has been logged in the log file.
0 0 0
`maps` 0 0 0 0 0

My log file gives the following:

Error No. 1205 Lock wait timeout exceeded; try restarting transaction

Both servers are on my LAN, CentOS 5.6, x86_64, mysql Ver 14.12 Distrib 5.0.77, for redhat-linux-gnu (x86_64) using readline 5.1

I have tried increasing the innodb_lock_wait_timeout (from 50 to 100), but it just takes longer to get the errors. The goal is to re-sync our test database with the mirror of our production database. Right now we use mysqldump then drop the database and import it. Most of these we can do it in a few minutes but our larger ones take a half an hour, which of course we would always like to do faster.

I told my boss we need to buy a faster server with faster disks and more RAM. But they are last-gen i7 so they aren't exactly slow.

[peterlaursen]

I believe this is not a a problem wiht hardware. It looks like there is some other application that has LOCKED a lot of tables because of open transactions. Maybe there is a backup job or similar running? Or some app (or user!) that just START TRANSACTION and does not commit for very long time. Or execute SELECT * FOR UPDATE? Try to get details from SHOW FULL PROCESSLIST and SHOW ENGINE INNODB STATUS about what is happening.

Maybe (?) I could also suggest to try restart the server (just in case).

Also tell: Are you using SJA for the first time. Or are you an old user that have been using it for long and only now this happens?

[robvas]

'peterlaursen' wrote:

I believe this is not a a problem wiht hardware. It looks like there is some other application that has LOCKED a lot of tables because of open transactions. Maybe there is a backup job or similar running? Or some app (or user!) that just START TRANSACTION and does not commit for very long time. Or execute SELECT * FOR UPDATE? Try to get details from SHOW FULL PROCESSLIST and SHOW ENGINE INNODB STATUS about what is happening.

The server I am using for a source is replicating from a server on the internet (as a slave). I stopped replication and still get the error.

Here is the output you requested from the target server. The source didn't show anything interesting.

http://pastebin.us/643

'peterlaursen' wrote:

Maybe (?) I could also suggest to try restart the server (just in case).

I restarted both and had no effect.

'peterlaursen' wrote:

Also tell: Are you using SJA for the first time. Or are you an old user that have been using it for long and only now this happens?

This is the first time i have used SJA

[peterlaursen]

OK .. we will check tomorrow if we can find something.

[robvas]

Thanks for the fast reply.

[Rituparna Kashyap]

Hi,

The snapshot of INNODB STATUS, clearly show that there is another transaction going on the source database that is blocking SJA.

Code:

—TRANSACTION 0 411490, ACTIVE 99 sec, process no 4030, OS thread id 1167542592
#
12 LOCK struct(s), heap size 3024
#
MySQL thread id 5, query id 426 localhost 127.0.0.1 deploy
#
Trx READ VIEW will NOT see trx WITH id >= 0 411491, sees < 0 411491

Now as SJA use SELECT …. LOCK IN SHARE MODE, so if there is any other transaction updating(or inserting) or uncommitted update (or insert) the select query will wait to hold the lock on the resource.

Now the interesting point is that both the transaction (one that of SJA and another that of the blocking transaction) are active from same time interval i.e 99 sec.

Code:

—TRANSACTION 0 411494, ACTIVE 99 sec, process no 4030, OS thread id 1167276352 starting index read

Code:

—TRANSACTION 0 411490, ACTIVE 99 sec, process no 4030, OS thread id 1167542592

Can you give me a few details.

1. Result of SHOW OPEN TABLES before executing SJA

2. Result of SHOW OPEN TABLES while in lockstate

** Note : For both 1 & 2 it will be enough to give the output of the scheduled database

3. Result of SHOW ENGINE INNODB STATUS while in lockstate

4. Result of SHOW PROCESSLIST while in lockstate

5. The xml files that you are using to execute SJA.

6. Is there any other application/backup job/replication running which use the user deploy.

[robvas]

Source DB:

Before lock state: http://pastebin.us/1602

During lock state: http://pastebin.us/1601

Target DB:

Before lock state: http://pastebin.us/1604

During lock state: http://pastebin.us/1603

[robvas]

XML file I am using:

localhost

deploy

secret

3309

0

0

cc

mysql-prod-test

deploy

secret

3306

0

0

cc

(we use ssh tunnel from target machine to source machine, sja is executed on target machine)

[Rituparna Kashyap]

Hello,

As there is no ssh information in the xml file and as you said that your are using ssh tunneling, is that for security reason you have removed the lines from the xml file?

Now, we tried reproducing your case but there was no LOCK WAIT issue. But in another test case we made the source same as the target and we got same issue as yours.

By any chance is yours source and the target database are same, as we saw in your SHOW ENGINE INNODB STATUS of your target during the synchronization process both the locking and locked transaction start at the same time and the process id is same. The same is seen in our case when the source and target are same.

Please find the attach file and comment.

[peterlaursen]

It looks to me like your are using the same local port for SSH tunnel to two different servers. This is not possible. You will eventually try to 'sync a server with itself'.

[robvas]

'peterlaursen' wrote:

It looks to me like your are using the same local port for SSH tunnel to two different servers. This is not possible. You will eventually try to 'sync a server with itself'.

You guys are right, I was trying to sync the database with itself. I suspected this was the problem last week, but when I did 'show databases' on the test server, it showed 19, and then connect to the mirror server through the ssh tunnel, it showed 41. I have it working now. The problem was either in the creation of SSH tunnel or not connecting through it properly. This is the line I was using to connect:

ssh -fN mysql-prod-mirror -L 3309:127.0.0.1:3306

This is the new line I connect with:

ssh -fN -L 3309:127.0.0.1:3306 deploy@mysql-prod-mirror

I then connect to mysql using this to test:

mysql -h 127.0.0.1 -P 3309 -u deploy -p

The problem was, before I was not using the -h option to specify the host. I didn't think I needed to, I thought it would connect by default.

sja appears to be running as it should now:

Sync started at Tue Jul 19 11:21:35 2011

Table SrcRows TgtRows Inserted Updated Deleted

========================= ======= ======= ======== ======= =======

`activities` 0 0 0 0 0

`addresses` 8632 8334 298 0 0

`award_eligibilities` 0 0 0 0 0

`awards` 0 0 0 0 0

`competitions` 28 28 0 0 0

`contacts` 8640 8342 298 2 0

`custom_prompts` 38 36 3 0 1

`destinations` 0 0 0 0 0

`edge_points` 925 925 0 0 0

`eligibilities` 66805 66805 0 277 0

`entries` 401825 389598 12227 1523 0

`evaluations` 1228 1226 2 0 0

Thanks for the help, dumb mistake on my part. I ended up changing the XML file from 'localhost' to '127.0.0.1'

[Author]

Posts