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