Strange mysql shutdown - help diagnosing

Discussion in 'Server Operation' started by tfboy, Apr 4, 2016.

  1. tfboy

    tfboy Member

    Hi.
    I've been running my instance of ISPconfig3 for a year or so and everything's been great.
    However, I did have a strange issue last night: all of a sudden, I couldn't pick up / send mail. I tried using Roundcube which I have installed and that gave me a clue: error connecting to database.
    So I checked status of MySQL and it wasn't running.
    I attempted to (re)start MySQL and it started fine, email has since returned, all my websites are working, etc.
    I was worried that it might be linked to a lot of wordpress comment spam I started receiving over the last few days (despite having Akismet up and running). the comments database fields in the error messages below are concerning...
    DB appears to have shut down around 19:51:43. I restarted it at 22:32:28.
    Code:
    160403 19:51:43 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
    160403 19:51:43 [Note] Plugin 'FEDERATED' is disabled.
    160403 19:51:43 InnoDB: The InnoDB memory heap is disabled
    160403 19:51:43 InnoDB: Mutexes and rw_locks use GCC atomic builtins
    160403 19:51:43 InnoDB: Compressed tables use zlib 1.2.8
    160403 19:51:43 InnoDB: Using Linux native AIO
    160403 19:51:43 InnoDB: Initializing buffer pool, size = 128.0M
    InnoDB: mmap(137363456 bytes) failed; errno 12
    160403 19:51:43 InnoDB: Completed initialization of buffer pool
    160403 19:51:43 InnoDB: Fatal error: cannot allocate memory for the buffer pool
    160403 19:51:43 [ERROR] Plugin 'InnoDB' init function returned error.
    160403 19:51:43 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
    160403 19:51:43 [ERROR] Unknown/unsupported storage engine: InnoDB
    160403 19:51:43 [ERROR] Aborting
    
    160403 19:51:46 [Note] /usr/sbin/mysqld: Shutdown complete
    
    This is repeated several times.

    Then restarting:
    Code:
    160403 22:32:28 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
    160403 22:32:28 [Note] Plugin 'FEDERATED' is disabled.
    160403 22:32:28 InnoDB: The InnoDB memory heap is disabled
    160403 22:32:28 InnoDB: Mutexes and rw_locks use GCC atomic builtins
    160403 22:32:28 InnoDB: Compressed tables use zlib 1.2.8
    160403 22:32:28 InnoDB: Using Linux native AIO
    160403 22:32:28 InnoDB: Initializing buffer pool, size = 128.0M
    160403 22:32:28 InnoDB: Completed initialization of buffer pool
    160403 22:32:28 InnoDB: highest supported file format is Barracuda.
    InnoDB: Log scan progressed past the checkpoint lsn 10478085720
    160403 22:32:28  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 10478098390
    160403 22:32:28  InnoDB: Starting an apply batch of log records to the database...
    InnoDB: Progress in percents: 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
    160403 22:32:29  InnoDB: Waiting for the background threads to start
    160403 22:32:30 InnoDB: 5.5.47 started; log sequence number 10478098390
    160403 22:32:30 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
    160403 22:32:30 [Note]  - '0.0.0.0' resolves to '0.0.0.0';
    160403 22:32:30 [Note] Server socket created on IP: '0.0.0.0'.
    160403 22:32:30 [Note] Event Scheduler: Loaded 0 events
    160403 22:32:30 [Note] /usr/sbin/mysqld: ready for connections.
    Version: '5.5.47-0ubuntu0.14.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)
    160403 22:32:30 [ERROR] /usr/sbin/mysqld: Table './c1aps1/wp_commentmeta' is marked as crashed and should be repaired
    160403 22:32:30 [Warning] Checking table:  './c1aps1/wp_commentmeta'
    160403 22:32:30 [ERROR] /usr/sbin/mysqld: Table './c1aps1/wp_comments' is marked as crashed and should be repaired
    160403 22:32:30 [Warning] Checking table:  './c1aps1/wp_comments'
    160403 22:32:30 [ERROR] /usr/sbin/mysqld: Table './c1aps1/wp_options' is marked as crashed and should be repaired
    160403 22:32:30 [Warning] Checking table:  './c1aps1/wp_options'
    160403 22:32:30 [ERROR] /usr/sbin/mysqld: Table './c1aps1/wp_posts' is marked as crashed and should be repaired
    160403 22:32:30 [Warning] Checking table:  './c1aps1/wp_posts'
    160403 22:32:30 [ERROR] /usr/sbin/mysqld: Table './c1aps1/wp_usermeta' is marked as crashed and should be repaired
    160403 22:32:30 [Warning] Checking table:  './c1aps1/wp_usermeta'
    160403 22:32:30 [ERROR] /usr/sbin/mysqld: Table './c1aps2/wp_commentmeta' is marked as crashed and should be repaired
    160403 22:32:30 [Warning] Checking table:  './c1aps2/wp_commentmeta'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c1aps2/wp_comments' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c1aps2/wp_comments'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c1aps2/wp_options' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c1aps2/wp_options'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c1aps3/wp_options' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c1aps3/wp_options'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c1aps3/wp_posts' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c1aps3/wp_posts'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c1aps3/wp_usermeta' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c1aps3/wp_usermeta'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c2aps1/wp_options' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c2aps1/wp_options'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c3aps4/wp_options' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c3aps4/wp_options'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './c3aps7/wp_postmeta' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './c3aps7/wp_postmeta'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './dbispconfig/mail_traffic' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './dbispconfig/mail_traffic'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './dbispconfig/monitor_data' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './dbispconfig/monitor_data'
    160403 22:32:31 [ERROR] /usr/sbin/mysqld: Table './dbispconfig/sys_datalog' is marked as crashed and should be repaired
    160403 22:32:31 [Warning] Checking table:  './dbispconfig/sys_datalog'
    160403 22:32:32 [ERROR] /usr/sbin/mysqld: Table './dbispconfig/web_traffic' is marked as crashed and should be repaired
    160403 22:32:32 [Warning] Checking table:  './dbispconfig/web_traffic'
    
    The only other thing I can think of is a potential update - I'll see if I can figure out my apt-get upgrade logs and see if anything there might be at cause.

    Memory is fine, and hard disk space is OK too, so it's not a resources thing.

    Thanks for any suggestions. :)
     
  2. till

    till Super Moderator Staff Member ISPConfig Developer

    Seems as if there is not enough ram. Check e.g. with top command. You can also try to add a swap file so your system can offload some data from memory.
     
  3. tfboy

    tfboy Member

    Hi Till,
    Thanks, but I don't think it's a RAM problem.
    The VPS has 2GB of RAM and to be safe, I added a 768MB Swap partition.
    Currently:
    Code:
    KiB Mem:  2047224 total,  1804952 used,  242272 free,  25952 buffers
    KiB Swap:  786428 total,  264000 used,  522428 free.  780812 cached Mem
    
    Of course, there might have been a bug / temporary issue which might have provoked a shortage of memory that crashed MySQL, but in nominal operation, the server is fine.
    It was silly of me, but I didn't think to grab a shot of usage at the time. I have Longview running, but have missed the window to save the data at that time. The MySQL-specific Longview shows nothing abnormal.

    I think I'll have to leave it at that, it might be there's no logged data now that's of use. If the problem happens again in the future, I'll be a bit more proactive and save as much info as possible to help a future debug / analysis.

    Thanks :)
     
  4. florian030

    florian030 Well-Known Member HowtoForge Supporter

    2 GB RAM is not very much for a mysql-server. ;) You can decrease at least the innodb_buffer_pool_size (see InnoDB: Fatal error: cannot allocate memory for the buffer pool in your log).
     
  5. till

    till Super Moderator Staff Member ISPConfig Developer

    You can use a tool like mysqltuner to check if your mysql memory settings match the available RAM.
     

Share This Page