5

I am having an issue where, for no apparent reason, my MySQL server crashes and has to restart.

Essentially, the error log has entries like this:

131128 12:16:35 mysqld_safe Number of processes running now: 0
131128 12:16:35 mysqld_safe mysqld restarted
131128 12:16:36 [Note] Plugin 'FEDERATED' is disabled.
131128 12:16:37 InnoDB: The InnoDB memory heap is disabled
131128 12:16:37 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131128 12:16:37 InnoDB: Compressed tables use zlib 1.2.3
131128 12:16:37 InnoDB: Using Linux native AIO
131128 12:16:37 InnoDB: Initializing buffer pool, size = 768.0M
131128 12:16:37 InnoDB: Completed initialization of buffer pool
131128 12:16:37 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 5922117901
131128 12:16:37  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...
InnoDB: Doing recovery: scanned up to log sequence number 5922118503
131128 12:16:41  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
131128 12:16:41  InnoDB: Waiting for the background threads to start
131128 12:16:42 InnoDB: 5.5.32 started; log sequence number 5922118503
131128 12:16:42 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131128 12:16:42 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131128 12:16:42 [Note] Server socket created on IP: '0.0.0.0'.
131128 12:16:43 [Note] Event Scheduler: Loaded 0 events
131128 12:16:43 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.32-cll'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131128 13:26:34 mysqld_safe Number of processes running now: 0
131128 13:26:34 mysqld_safe mysqld restarted
131128 13:26:35 [Note] Plugin 'FEDERATED' is disabled.
131128 13:26:35 InnoDB: The InnoDB memory heap is disabled
131128 13:26:35 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131128 13:26:35 InnoDB: Compressed tables use zlib 1.2.3
131128 13:26:35 InnoDB: Using Linux native AIO
131128 13:26:35 InnoDB: Initializing buffer pool, size = 768.0M
131128 13:26:35 InnoDB: Completed initialization of buffer pool
131128 13:26:35 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 5922607951
131128 13:26:35  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...
InnoDB: Doing recovery: scanned up to log sequence number 5922608207
131128 13:26:39  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
131128 13:26:41 InnoDB: 5.5.32 started; log sequence number 5922608207
131128 13:26:41 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131128 13:26:41 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131128 13:26:41 [Note] Server socket created on IP: '0.0.0.0'.
131128 13:26:42 [Note] Event Scheduler: Loaded 0 events
131128 13:26:42 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.32-cll'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131128 19:17:10 mysqld_safe Number of processes running now: 0
131128 19:17:10 mysqld_safe mysqld restarted
131128 19:17:10 [Note] Plugin 'FEDERATED' is disabled.
131128 19:17:10 InnoDB: The InnoDB memory heap is disabled
131128 19:17:10 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131128 19:17:10 InnoDB: Compressed tables use zlib 1.2.3
131128 19:17:10 InnoDB: Using Linux native AIO
131128 19:17:10 InnoDB: Initializing buffer pool, size = 768.0M
131128 19:17:10 InnoDB: Completed initialization of buffer pool
131128 19:17:10 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
131128 19:17:10  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...
131128 19:17:22  InnoDB: Waiting for the background threads to start
131128 19:17:23 InnoDB: 5.5.32 started; log sequence number 5923508470
131128 19:17:23 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131128 19:17:23 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131128 19:17:23 [Note] Server socket created on IP: '0.0.0.0'.
131128 19:17:23 [Note] Event Scheduler: Loaded 0 events
131128 19:17:23 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.32-cll'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131128 23:48:32 mysqld_safe Number of processes running now: 0
131128 23:48:32 mysqld_safe mysqld restarted
131128 23:48:33 [Note] Plugin 'FEDERATED' is disabled.
131128 23:48:33 InnoDB: The InnoDB memory heap is disabled
131128 23:48:33 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131128 23:48:33 InnoDB: Compressed tables use zlib 1.2.3
131128 23:48:33 InnoDB: Using Linux native AIO
131128 23:48:33 InnoDB: Initializing buffer pool, size = 768.0M
131128 23:48:33 InnoDB: Completed initialization of buffer pool
131128 23:48:33 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 5925065422
131128 23:48:33  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...
InnoDB: Doing recovery: scanned up to log sequence number 5925065795
131128 23:48:38  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
131128 23:48:39  InnoDB: Waiting for the background threads to start
131128 23:48:40 InnoDB: 5.5.32 started; log sequence number 5925065795
131128 23:48:40 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131128 23:48:40 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131128 23:48:40 [Note] Server socket created on IP: '0.0.0.0'.
131128 23:48:41 [Note] Event Scheduler: Loaded 0 events
131128 23:48:41 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.32-cll'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131129 02:06:39 mysqld_safe Number of processes running now: 0
131129 02:06:39 mysqld_safe mysqld restarted
131129  2:06:44 [Note] Plugin 'FEDERATED' is disabled.
131129  2:06:45 InnoDB: The InnoDB memory heap is disabled
131129  2:06:45 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131129  2:06:45 InnoDB: Compressed tables use zlib 1.2.3
131129  2:06:45 InnoDB: Using Linux native AIO
131129  2:06:45 InnoDB: Initializing buffer pool, size = 768.0M
131129  2:06:45 InnoDB: Completed initialization of buffer pool
131129  2:06:45 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 5925464870
131129  2:06:45  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...
InnoDB: Doing recovery: scanned up to log sequence number 5925465752
131129  2:06:49  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
131129  2:06:52  InnoDB: Waiting for the background threads to start
131129  2:06:53 InnoDB: 5.5.32 started; log sequence number 5925465752
131129  2:06:54 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131129  2:06:54 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131129  2:06:54 [Note] Server socket created on IP: '0.0.0.0'.
131129  2:06:55 [Note] Event Scheduler: Loaded 0 events
131129  2:06:55 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.32-cll'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131129 06:23:13 mysqld_safe Number of processes running now: 0
131129 06:23:14 mysqld_safe mysqld restarted
131129  6:23:30 [Note] Plugin 'FEDERATED' is disabled.
131129  6:23:33 InnoDB: The InnoDB memory heap is disabled
131129  6:23:33 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131129  6:23:33 InnoDB: Compressed tables use zlib 1.2.3
131129  6:23:33 InnoDB: Using Linux native AIO
131129  6:23:33 InnoDB: Initializing buffer pool, size = 768.0M
131129  6:23:33 InnoDB: Completed initialization of buffer pool
131129  6:23:34 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 5926929016
131129  6:23:34  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...
InnoDB: Doing recovery: scanned up to log sequence number 5926968418
131129  6:23:38  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
131129  6:23:39  InnoDB: Waiting for the background threads to start
131129  6:23:40 InnoDB: 5.5.32 started; log sequence number 5926968418
131129  6:23:40 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131129  6:23:40 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131129  6:23:40 [Note] Server socket created on IP: '0.0.0.0'.
131129  6:23:41 [Note] Event Scheduler: Loaded 0 events
131129  6:23:41 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.32-cll'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
131129 06:28:05 mysqld_safe Number of processes running now: 0
131129 06:28:05 mysqld_safe mysqld restarted
131129  6:28:06 [Note] Plugin 'FEDERATED' is disabled.
131129  6:28:06 InnoDB: The InnoDB memory heap is disabled
131129  6:28:06 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131129  6:28:06 InnoDB: Compressed tables use zlib 1.2.3
131129  6:28:06 InnoDB: Using Linux native AIO
131129  6:28:06 InnoDB: Initializing buffer pool, size = 768.0M
131129  6:28:06 InnoDB: Completed initialization of buffer pool
131129  6:28:06 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
131129  6:28:06  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...
131129  6:28:07  InnoDB: Waiting for the background threads to start
131129  6:28:08 InnoDB: 5.5.32 started; log sequence number 5926985672
131129  6:28:08 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
131129  6:28:08 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
131129  6:28:08 [Note] Server socket created on IP: '0.0.0.0'.
131129  6:28:11 [Note] Event Scheduler: Loaded 0 events
131129  6:28:11 [Note] /usr/sbin/mysqld: ready for connections.

Reading about on this issue on the internet, I saw that this could happen because data in one of the server's database is corrupted.

So I did this:

  • added innodb_force_recovery = 4 to /etc/my.cnf
  • restarted the mysql service
  • dumped the data in the database using mysqldump
  • stopped the mysql service
  • backed up existing InnoDB log/data files
  • removed the innodb_force_recovery = 4 line from /etc/my.cnf
  • restarted the mysql service
  • re-created the database and added table objects and data to it, using the dump created earlier

But the crashes still continue.

Here is a copy of my /etc/my.cnf file:

[mysqld]
tmp_table_size=192M
query_cache_limit=16M
join_buffer_size=64M
max_heap_table_size=192M
query_cache_size=64M
max_allowed_packet=256M
sort_buffer_size=64M
myisam_sort_buffer_size=64M
key_buffer=32M
read_buffer_size=64M
sort_buffer_size=64M

open_files_limit=2090
max_connections=32
wait_timeout=1800
table_cache=6400
thread_cache_size=16
max_connect_errors=999999
query_cache_type=1
max_user_connections=200
interactive_timeout=180
connect_timeout=30
net_read_timeout = 600
net_write_timeout = 600
socket="/var/lib/mysql/mysql.sock"
port=3306
default-storage-engine=InnoDB

log-error="/var/lib/mysql/error.log"
slow_query_log_file="/var/lib/mysql/slow-query.log"
slow_query_log=1
long_query_time=5
general_log_file="/var/lib/mysql/general.log"
general_log=1

innodb_buffer_pool_size=768M
innodb_log_buffer_size=32M
innodb_log_file_size=192M
innodb_additional_mem_pool_size=20M
innodb_data_file_path="ibdata1:32M:autoextend"
innodb_data_home_dir="/var/lib/mysql/"
innodb_fast_shutdown=0
innodb_thread_concurrency=8
innodb_file_per_table=1
innodb_flush_method=O_DIRECT
innodb_flush_log_at_trx_commit=0
;innodb_force_recovery=4

[client]
socket="/var/lib/mysql/mysql.sock"
port=3306

I have the general log enabled, but I don't see any special query consistently being run at the time of the crash.

Does anyone have any further suggestions? I have been told it might be a hardware issue, but my hosting provider says they cannot see any problems.

Improve this question
5
  • It would be very unusual if these logs actually indicate that mysql is what is actually crashing. When mysql crashes, it will almost certainly say something about what happened. These messages seems to indicate that mysql isn't dying -- it is being killed. Check your syslogs to see if you don't have a memory shortage causing mysql to be killed by the system: dba.stackexchange.com/questions/25077/…
    – Michael - sqlbot
    Commented Dec 1, 2013 at 0:18
  • Try this: egrep -i 'killed process' /var/log/messages
    – Craig Efrein
    Commented Dec 2, 2013 at 9:46
  • @Michael-sqlbot, craig-efrein, unfortunately, the messages log has no information on this. I'm going to try to enable process accounting on the machine to see if I can find any additional information.
    – Tola Odejayi
    Commented Dec 2, 2013 at 18:27
  • Unfortunately, process accounting wasn't able to yield any useful information either. Is there any other tool that I can use to find out what might have killed mysql? I have asked over at serverfault.com here (serverfault.com/questions/558955/…) to see how I could check whether I have misconfigured syslog to ensure that it captures all process action (including mysql-killing actions), but at least one person feels that the problem is that my data is corrupt.
    – Tola Odejayi
    Commented Dec 3, 2013 at 18:31
  • 1
    I had hoped that I would be able to enable core dumps to see what was happening when MySQL crashed, but the hosting provider won't let me do that. It looks like the only option I have left here is to install a debug version of MySQL so that I can get trace information about what happens at the point of crashing. Does anyone know how I would be able to do this? The documentation on the official MySQL site mentions this, but it doesn't go into any detail about how it might be done.
    – Tola Odejayi
    Commented Dec 25, 2013 at 6:29

2 Answers 2

Reset to default
5

In the end, it was only after changing my hosting plan (and moving away from cPanel, which seemed to obscure some of the logging) that I was able to see the issue. Turns out that from time to time, memory usage would spike (I'm guessing that this was because of a dramatic spike in apache child processes) and this would cause memory pressure. The out-of-memory killer would choose mysql to close down, because it was (usually) the biggest memory user in the system.

So to fix, I

  • got more memory
  • fine tuned Apache to control the number of child processes that were spun up.
Improve this answer
4
  • 3
    it had been wonderful if you had wrote how you fine tuned Apache
    – sites
    Commented Jan 21, 2015 at 19:40
  • What was your memory before and after the issue?
    – Daniel Tate
    Commented Jun 2, 2015 at 2:46
  • 2048MB before, 3072GB after.
    – Tola Odejayi
    Commented Aug 5, 2015 at 20:22
  • 1
    You can follow this post to see how to do this: stackoverflow.com/questions/501205/…
    – Tola Odejayi
    Commented Dec 24, 2016 at 22:27
0

I had the same experience today. In my.cnf I had:

innodb_doublewrite = 0

I removed that entry, restarted mysql and it was able to recover.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.