Description:
I'm running my production sites in Google Cloud and in one particular instance I've been having persistent service restarts at random times. I can't associate the events with anything that is being done in the application.
I've had the instance relocated multiple times (to rule out hardware issues), but the problem persists. Here's a sample log:
07:08:36 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=41
max_threads=1000
thread_count=33
connection_count=33
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 405567 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7f1fcc223c30
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...
stack_bottom = 7f204a21de80 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xe9139c]
/usr/sbin/mysqld(handle_fatal_signal+0x459)[0x7afc29]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f2274274890]
/lib/x86_64-linux-gnu/libc.so.6(+0x92020)[0x7f2272cda020]
/usr/sbin/mysqld(pfs_start_statement_v1+0x91)[0xea9911]
/usr/sbin/mysqld(_Z20net_after_header_psiP6st_netPvmc+0xc7)[0xd23327]
/usr/sbin/mysqld[0xbbab3b]
/usr/sbin/mysqld(my_net_read+0x2fc)[0xbbb8fc]
/usr/sbin/mysqld(_ZN16Protocol_classic11get_commandEP8COM_DATAP19enum_server_command+0x3c)[0xbc74cc]
/usr/sbin/mysqld(_Z10do_commandP3THD+0xaa)[0xc62daa]
/usr/sbin/mysqld(handle_connection+0x270)[0xd22820]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xea8e94]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x7f227426d064]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f2272d3062d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 1952
Status: NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2018-10-15T07:08:37.421264Z 0 [Warning] Could not increase number of max_open_files to more than 5000 (request: 1048576)
2018-10-15T07:08:37.421421Z 0 [Warning] Changed limits: table_open_cache: 1995 (requested 2000)
2018-10-15T07:08:37.621296Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-10-15T07:08:37.623417Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.23-log) starting as process 24177 ...
2018-10-15T07:08:37.627695Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-10-15T07:08:37.627724Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-10-15T07:08:37.627728Z 0 [Note] InnoDB: Uses event mutexes
2018-10-15T07:08:37.627732Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-10-15T07:08:37.627735Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-10-15T07:08:37.627739Z 0 [Note] InnoDB: Using Linux native AIO
2018-10-15T07:08:37.628414Z 0 [Note] InnoDB: Number of pools: 1
2018-10-15T07:08:37.628530Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-10-15T07:08:37.631415Z 0 [Note] InnoDB: Initializing buffer pool, total size = 8G, instances = 8, chunk size = 128M
2018-10-15T07:08:38.230678Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-10-15T07:08:38.353980Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-10-15T07:08:38.375528Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-10-15T07:08:38.474896Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 80922414664
2018-10-15T07:08:38.562645Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 80922707790
2018-10-15T07:08:38.563348Z 0 [Note] InnoDB: Database was not shutdown normally!
2018-10-15T07:08:38.563356Z 0 [Note] InnoDB: Starting crash recovery.
2018-10-15T07:08:39.003026Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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
2018-10-15T07:08:40.001299Z 0 [Note] InnoDB: Apply batch completed
2018-10-15T07:08:40.001365Z 0 [Note] InnoDB: Last MySQL binlog file position 0 48575275, file name mysql-bin.000522
2018-10-15T07:08:40.178941Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-10-15T07:08:40.178966Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-10-15T07:08:40.179004Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-10-15T07:08:40.230672Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-10-15T07:08:40.231701Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-10-15T07:08:40.231717Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-10-15T07:08:40.232187Z 0 [Note] InnoDB: 5.7.23 started; log sequence number 80922707790
2018-10-15T07:08:40.232471Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2018-10-15T07:08:40.232630Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-10-15T07:08:40.256129Z 0 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
2018-10-15T07:08:40.520738Z 0 [Note] Starting crash recovery...
2018-10-15T07:08:40.520845Z 0 [Note] Crash recovery finished.
2018-10-15T07:08:40.714196Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2018-10-15T07:08:40.714456Z 0 [Warning] CA certificate ca.pem is self signed.
2018-10-15T07:08:40.715694Z 0 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2018-10-15T07:08:40.715724Z 0 [Note] - '0.0.0.0' resolves to '0.0.0.0';
2018-10-15T07:08:40.715767Z 0 [Note] Server socket created on IP: '0.0.0.0'.
2018-10-15T07:08:40.753901Z 0 [Note] Event Scheduler: Loaded 0 events
2018-10-15T07:08:40.754214Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.23-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 MySQL Community Server (GPL)
2018-10-15T07:08:52.561179Z 0 [Note] InnoDB: Buffer pool(s) load completed at 181015 7:08:52
How to repeat:
Happens randomly, I don't really know what triggers this.
