Bug #36525 Mysql Server becomes very slow.
Submitted: 6 May 2008 10:34 Modified: 12 Aug 2008 16:27
Reporter: Rajesh Jha Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.0.45 OS:Linux (EDT 2007 x86_64 x86_64 x86_64 GNU/Linux )
Assigned to: CPU Architecture:Any

[6 May 2008 10:34] Rajesh Jha
Description:
Once Mysql server is up and running for few days, suddenly it becomes very slow.
Re-starting the server resolve the issue for few days and the problem appears again.

All the tables are of type INNoDB.

Below is an example to see how slow it becomes. brand is a table with 10 columns:- 
 
mysql> select count(1) from brand;
+----------+
| count(1) |
+----------+
|     2064 |
+----------+
1 row in set (22.11 sec).

Was investigating it for couple of weeks. Today noticed some information in the error.log file.

InnoDB: Warning: a long semaphore wait: 
--Thread 25543770134 has waited at trx0trx.c line 715 for 402.00 seconds the semaphore:
Mutex at 0x2a959892b8 created file srv0srv.c line 872, lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 25631965242 has waited at btr0sea.c line 1127 for 401.00 seconds the semaphore:
S-lock on RW-latch at 0x2a9598c0b8 created in file btr0sea.c line 139
a writer (thread id 25618677825) has reserved it in mode  wait exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0sea.c line 746
Last time write locked in file btr0sea.c line 489
InnoDB: Warning: a long semaphore wait:
--Thread 25632145461 has waited at trx0trx.c line 213 for 392.00 seconds the semaphore:
Mutex at 0x2a959892b8 created file srv0srv.c line 872, lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 25630441592 has waited at trx0trx.c line 371 for 375.00 seconds the semaphore:
Mutex at 0x2a959892b8 created file srv0srv.c line 872, lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 25577521190 has waited at btr0sea.c line 1301 for 433.00 seconds the semaphore:
S-lock on RW-latch at 0x2a9598c0b8 created in file btr0sea.c line 139
a writer (thread id 25618677825) has reserved it in mode  wait exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0sea.c line 746
Last time write locked in file btr0sea.c line 489
InnoDB: Warning: a long semaphore wait:
--Thread 25630785655 has waited at btr0sea.c line 916 for 433.00 seconds the semaphore:
S-lock on RW-latch at 0x2a9598c0b8 created in file btr0sea.c line 139
a writer (thread id 25618677825) has reserved it in mode  wait exclusive
number of readers 0, waiters flag 1
Last time read locked in file btr0sea.c line 746
Last time write locked in file btr0sea.c line 489
InnoDB: Warning: a long semaphore wait:
InnoDB: Warning: a long semaphore wait:
--Thread 25630441592 has waited at trx0trx.c line 371 for 759.00 seconds the semaphore:
Mutex at 0x2a959892b8 created file srv0srv.c line 872, lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
080506  8:33:54InnoDB: Assertion failure in thread 114696 in file srv0srv.c line 2093
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
080506  8:33:54 - mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=195
max_connections=500
threads_connected=136
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 336380 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=(nil)
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
frame pointer is NULL, did you compile with
-fomit-frame-pointer? Aborting backtrace!
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Number of processes running now: 0
080506 08:33:54  mysqld restarted
080506  8:33:56  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
080506  8:34:37  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 272 3753834339.
InnoDB: Doing recovery: scanned up to log sequence number 272 3755233681
InnoDB: 3 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 14449 row operations to undo
InnoDB: Trx id counter is 0 724420352
080506  8:34:37  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 

35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 

77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 235, file name mysql-bin.000107
InnoDB: Last MySQL binlog file position 0 498236194, file name /home/mysql/iplayer/binlogs/mysql-bin.000521
InnoDB: Starting in background the rollback of uncommitted transactions
080506  8:34:43  InnoDB: Rolling back trx with id 0 724419404, 15 rows to undo
080506  8:34:43  InnoDB: Started; log sequence number 272 3755233681
080506  8:34:43 [Note] Recovering after a crash using /home/mysql/iplayer/binlogs/mysql-bin

InnoDB: Rolling back of trx id 0 724419404 completed
080506  8:34:43  InnoDB: Rolling back trx with id 0 724419360, 14419 rows to undo

InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 

36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 

78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100
InnoDB: Rolling back of trx id 0 724419360 completed
080506  8:34:44  InnoDB: Rolling back trx with id 0 724418950, 15 rows to undo

InnoDB: Rolling back of trx id 0 724418950 completed
080506  8:34:44  InnoDB: Rollback of non-prepared transactions completed
080506  8:34:44 [Note] Starting crash recovery...
080506  8:34:44 [Note] Crash recovery finished.
080506  8:34:45 [Note] /usr/local/mysql-5.0.45/libexec/mysqld: ready for connections.
Version: '5.0.45-log'  socket: '/home/mysql/iplayer/socket/mysql.socket'  port: 3306  Source distribution

How to repeat:
Don't know
[6 May 2008 10:59] Rajesh Jha
Error Log File

Attachment: db_error_log.txt (text/plain), 83.96 KiB.

[6 May 2008 12:47] Valeriy Kravchuk
Thank you for a problem report. Please, try to repeat with a newer version, 5.0.51a at least. In case of the same problem, please, send your my.cnf file content and describe your hardware (how many CPUs/cores do you have, at least).
[6 May 2008 14:36] Rajesh Jha
For some time it would not be possible for us to upgrade to 5.0.51a. 

We have got 8 cores Intel Xeon CPU E5310 1.60 GHz.

my.cnf  has the following settings:-

innodb_buffer_pool_size=3072M

set-variable = key_buffer=16M
set-variable = max_allowed_packet=1M
set-variable = table_cache=64
set-variable = sort_buffer=512K
set-variable = net_buffer_length=8K
set-variable = net_read_timeout=86400
set-variable = myisam_sort_buffer_size=8M
set-variable = innodb_log_files_in_group=2
set-variable = max_connections=500
set-variable = open_files_limit=0
set-variable = innodb_log_file_size=50M

long_query_time       = 2
innodb_file_per_table = 1

port=3306
skip-slave-start
[9 Aug 2008 7:21] Valeriy Kravchuk
Please, try to repeat with a newer version, 5.0.67, and inform about the results.
[12 Aug 2008 10:39] Rajesh Jha
It is resolved now. It was related to Bug 30193. The database patch 32012 has been applied to resolve this issue. 

The development team members were running scripts to create and drop databases and while the scripts were dropping the databases these scripts were being terminated using CTRL-X (which we were not aware of). It took us some time to figure out what action was causing the problem.  

In this process, locks were obtained on the tables and were not released even after the databases and the tables were already dropped. 

On creating the databases and tables again with the same names, all the DML statements were running slow due to the table locks obtained earlier.
[12 Aug 2008 11:41] Susanne Ebrecht
When it is solved in newer version. Can we close this bug report?
[12 Aug 2008 11:45] Rajesh Jha
The bug report can be closed now.
[12 Aug 2008 11:46] Rajesh Jha
The bug report can be closed now.
[12 Aug 2008 16:27] Rajesh Jha
The applied resolution is on the same version 5.0.45 with the patch 32012.