7

I've googled and searched stackexchange, but can't find anything relevant to this particular issue (there are other error 11 issues, just not for this as far as I can tell).

We have a server that is not really doing a ton of reads or writes. The server is a VM with 16 cores and 16GB ram.

MySQL crashes after some unknown amount of time and the error log shows:

09:17:14 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.
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=21
max_threads=502
thread_count=12
connection_count=12
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1131343 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
hread pointer: 0x3329180
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 = 7f4a0043ee70 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x7cbffc]
/usr/sbin/mysqld(handle_fatal_signal+0x4a1)[0x699251]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f4a3278b340]
/lib/x86_64-linux-gnu/libc.so.6(+0x9818e)[0x7f4a3114b18e]
/usr/sbin/mysqld(_ZN8Protocol14net_store_dataEPKhm+0x47)[0x52e3b7]
/usr/sbin/mysqld[0x52fea4]
/usr/sbin/mysqld(_ZN8Protocol24send_result_set_metadataEP4ListI4ItemEj+0x52c)[0x52fbbc]
/usr/sbin/mysqld(_Z18mysqld_list_fieldsP3THDP10TABLE_LISTPKc+0x22a)[0x5e8d2a]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x2498)[0x5a6988]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x13a)[0x643a4a]
/usr/sbin/mysqld(handle_one_connection+0x4a)[0x643b3a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7f4a32783182]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f49d00078a0): is an invalid pointer
Connection ID (thread ID): 83475
Status: NOT_KILLED

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
150629  9:17:14 [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.
150629  9:17:14 [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.
150629  9:17:14 [Note] Plugin 'FEDERATED' is disabled.
150629  9:17:14 InnoDB: The InnoDB memory heap is disabled
150629  9:17:14 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150629  9:17:14 InnoDB: Compressed tables use zlib 1.2.3
150629  9:17:14 InnoDB: Using Linux native AIO
150629  9:17:14 InnoDB: Initializing buffer pool, size = 500.0M
150629  9:17:14 InnoDB: Completed initialization of buffer pool
150629  9:17:14 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 15732651240
150629  9:17:14  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 15737893888
InnoDB: Doing recovery: scanned up to log sequence number 15743136768
InnoDB: Doing recovery: scanned up to log sequence number 15748379648
InnoDB: Doing recovery: scanned up to log sequence number 15752740649
InnoDB: Transaction 986C1E8 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 986C300
150629  9:17:15  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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: Last MySQL binlog file position 0 89114508, file name /var/lib/mysql/mysql-bin.000057
InnoDB: Starting in background the rollback of uncommitted transactions
150629  9:17:16  InnoDB: Rollback of non-prepared transactions completed
150629  9:17:16  InnoDB: Waiting for the background threads to start
150629  9:17:17 Percona XtraDB (http://www.percona.com) 5.5.43-37.2 started; log sequence number 15752740649
150629  9:17:17 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
150629  9:17:17 [Note] Starting crash recovery...
150629  9:17:17  InnoDB: Starting recovery for XA transactions...
150629  9:17:17  InnoDB: Transaction 986C1E8 in prepared state after recovery
150629  9:17:17  InnoDB: Transaction contains changes to 1 rows
150629  9:17:17  InnoDB: 1 transactions in prepared state after recovery
150629  9:17:17 [Note] Found 1 prepared transaction(s) in InnoDB
150629  9:17:17 [Note] Crash recovery finished.
150629  9:17:17 [Warning] 'user' entry 'root@host' ignored in --skip-name-resolve mode.
150629  9:17:17 [Warning] 'proxies_priv' entry '@ root@host' ignored in --skip-name-resolve mode.
150629  9:17:17 [Note] Event Scheduler: Loaded 0 events
150629  9:17:17 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.43-37.2-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Percona Server (GPL), Release 37.2, Revision 6202fee

I don't think this is Percona related because it does it with regular MySQL as well (I loaded Percona to see if it would fix it).

The general.log only shows the following during this time:

150629  9:17:13 76946 Query     set autocommit=1
150629  9:17:14 76946 Query     UPDATE `api_dictionaryitem` SET `name` = '', `group_id` = 4, `count` = 2248844, `last_occurence` = NULL WHERE `api_dictionaryitem`.`id` = 8
150629  9:17:17     1 Connect   debian-sys-maint@localhost on
150629  9:17:18     4 Quit
150629  9:17:22    36 Connect   user@localhost on mydb

The entire database is only 5.3MB

I have spent hours trying to figure this out, but it's beyond me at this point.

EDIT: Yes, I know occurence is spelled wrong, it's in the ticket queue for a fix, but it is consistent throughout the code right now, so it is not the cause.

EDIT 2: Adding MySQL Config - which was generated using Percona's generation tool. I was using it as a "safe" config.

# Generated by Percona Configuration Wizard (http://tools.percona.com/) version REL5-20120208

[mysql]

# CLIENT #
port                           = 3306
socket                         = /var/run/mysqld/mysqld.sock

[mysqld]

# GENERAL #
user                           = mysql
default-storage-engine         = InnoDB
socket                         = /var/run/mysqld/mysqld.sock
pid-file                       = /var/run/mysqld/mysqld.pid

# MyISAM #
key-buffer-size                = 32M
myisam-recover                 = FORCE,BACKUP

# SAFETY #
max-allowed-packet             = 16M
max-connect-errors             = 1000000
skip-name-resolve
sql-mode                       = STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_AUTO_VALUE_ON_ZERO,NO_ENGINE_SUBSTITUTION,NO_ZERO_DATE,NO_ZERO_IN_DATE,ONLY_FULL_GROUP_BY
sysdate-is-now                 = 1
innodb                         = FORCE
innodb-strict-mode             = 1

# DATA STORAGE #
datadir                        = /var/lib/mysql/

# BINARY LOGGING #
log-bin                        = /var/lib/mysql/mysql-bin
expire-logs-days               = 14
sync-binlog                    = 1

# CACHES AND LIMITS #
tmp-table-size                 = 32M
max-heap-table-size            = 32M
query-cache-type               = 0
query-cache-size               = 0
max-connections                = 500
thread-cache-size              = 50
open-files-limit               = 65535
table-definition-cache         = 1024
table-open-cache               = 2048

# INNODB #
innodb-flush-method            = O_DIRECT
innodb-log-files-in-group      = 2
innodb-log-file-size           = 64M
innodb-flush-log-at-trx-commit = 1
innodb-file-per-table          = 1
innodb-buffer-pool-size        = 500M

# LOGGING #
log-error                      = /var/log/mysql/error.log
slow-query-log                 = 1
slow-query-log-file            = /var/log/mysql/slow.log
log=/var/log/mysql/general.log

# Autoextend
innodb_data_file_path           = ibdata1:128M;ibdata2:10M:autoextend
  • Why are you using XA transactions? – winmutt Jul 3 '15 at 18:12
  • @winmutt, I asked my dev team about why they are using autocommit=1, they said they are using Django to manage these things and supposed that it was Django doing it. – Clayton Dukes Jul 6 '15 at 9:19
  • @winmutt, here's the reference for that: https://docs.djangoproject.com/en/1.8/topics/db/transactions/#autocommit-details - they are also using this: https://docs.djangoproject.com/en/1.8/topics/db/transactions/#tying-transactions-to-http-requests – Clayton Dukes Jul 6 '15 at 9:25
  • @ClaytonDukes what vm solution was this on? – winmutt Jul 8 '15 at 15:03
  • @winmutt, Amazon EC2 (Ubuntu 14 LTS) and also at Digital Ocean as well as in-house KVM/Qemu – Clayton Dukes Jul 8 '15 at 19:18
11
+50

What catches my eye is the Query recorded in the general log

150629  9:17:14 76946 Query     UPDATE `api_dictionaryitem` SET `name` = '', `group_id` = 4, `count` = 2248844, `last_occurence` = NULL WHERE `api_dictionaryitem`.`id` = 8

when you got signal 11

09:17:14 UTC - mysqld got signal 11 ;

I would suspect you hit some weird bug when running the table api_dictionaryitem in this instance. Why ?

Look at the response to the signal 11 you got which I will itemize

  • 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.

Let's see what mysqld was doing before it had to resort to a stack trace

stack_bottom = 7f4a0043ee70 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x7cbffc]
/usr/sbin/mysqld(handle_fatal_signal+0x4a1)[0x699251]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f4a3278b340]
/lib/x86_64-linux-gnu/libc.so.6(+0x9818e)[0x7f4a3114b18e]
/usr/sbin/mysqld(_ZN8Protocol14net_store_dataEPKhm+0x47)[0x52e3b7]
/usr/sbin/mysqld[0x52fea4]
/usr/sbin/mysqld(_ZN8Protocol24send_result_set_metadataEP4ListI4ItemEj+0x52c)[0x52fbbc]
/usr/sbin/mysqld(_Z18mysqld_list_fieldsP3THDP10TABLE_LISTPKc+0x22a)[0x5e8d2a]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x2498)[0x5a6988]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x13a)[0x643a4a]
/usr/sbin/mysqld(handle_one_connection+0x4a)[0x643b3a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7f4a32783182]

Look at the line that says

/usr/sbin/mysqld(_ZN8Protocol14net_store_dataEPKhm+0x47)[0x52e3b7]

The query at the moment of impact was

UPDATE `api_dictionaryitem` SET
`name` = '',
`group_id` = 4,
`count` = 2248844,
`last_occurence` = NULL
WHERE `api_dictionaryitem`.`id` = 8

What was net_store_data doing at that moment ?

The book Understanding MySQL Internals says something about net_store_data and NULL values on Pages 74,75 under the heading Server Responses subheading Data Fields

MySQL Internals

Data fields are critical components in many of the server response packets. A data field consists of a length specifier sequence followed by the actual data value. The length specifier sequence can be understood by studying of net_store_length() ...

What is interesting is that net_store_data() calls net_store_length() on line 482 in protocol.cc. That code looks like this

{
  to=net_store_length_fast(to,length);
  memcpy(to,from,length);
  return to+length;
}

On line 489, another version of net_store_data() looks like this:

{
  char buff[20];
  uint length=(uint) (int10_to_str(from,buff,10)-buff);
  to=net_store_length_fast(to,length);
  memcpy(to,buff,length);
  return to+length;
}

On line 498, another version of net_store_data() looks like this:

{
  char buff[22];
  uint length=(uint) (longlong10_to_str(from,buff,10)-buff);
  to=net_store_length_fast(to,length);
  memcpy(to,buff,length);
  return to+length;
}

These snippets of code can be found in SourceCodeBrowser

The code for net_store_length

00450 {
00451   uchar *packet=(uchar*) pkg;
00452   if (length < 251)
00453   {
00454     *packet=(uchar) length;
00455     return (char*) packet+1;
00456   }
00457   *packet++=252;
00458   int2store(packet,(uint) length);
00459   return (char*) packet+2;
00460 }

can be found here

Since net_store_data is the single point of failure in the stack trace, what is in the SQL that would have triggered such a a failure ?

Look back at the SQL

UPDATE `api_dictionaryitem` SET
`name` = '',
`group_id` = 4,
`count` = 2248844,
`last_occurence` = NULL
WHERE `api_dictionaryitem`.`id` = 8

The only thing that looks out of place to me is the

`last_occurence` = NULL

Look back at the code for net_store_length. Note the line

00452   if (length < 251)

What is so special about the number 251 ? According the book Understanding MySQL Internals, the last paragraph on page 74 says:

One may ask why the 1 byte length is limited to 251, when the first reserved value in the net_store_length() is 252. The code 251 has a special meaning. It indicates that there is no length value or data following the code, and the value of the field is the SQL NULL.

Aha !!! The NULL value is being mishandled in net_store_length() when dealing with the last_occurence field. If the last_occurence is a DATETIME or TIMESTAMP, using NULL is most likely not being permitted.

Perhaps changing

`last_occurence` = NULL

to a bogus but legitimate date value

`last_occurence` = '1970-01-01 00:00:00'

would probably nail this problem right on the head.

The stack trace's first response was right : This could be because you hit a bug.

Please read the MySQL Documentation on Using a Stack Trace.

UPDATE 2015-07-06 10:47 EST

Earlier you commented on the definition of the table

mysql> desc api_dictionaryitem;
+----------------+--------------+------+-----+---------+----------------+
| Field          | Type         | Null | Key | Default | Extra          |
+----------------+--------------+------+-----+---------+----------------+
| id             | int(11)      | NO   | PRI | NULL    | auto_increment |
| name           | varchar(255) | NO   |     | NULL    |                |
| count          | bigint(20)   | YES  |     | NULL    |                |
| last_occurence | bigint(20)   | YES  |     | NULL    |                |
| group_id       | int(11)      | NO   | MUL | NULL    |                |
+----------------+--------------+------+-----+---------+----------------+
5 rows in set (0.00 sec)

You mentioned that last_occurence is BIGINT. Since it is BIGINT, which is 8 bytes, and it is being set to NULL, think of what that does.

The first byte has 0xFB (251) followed by 7 bytes of undefined stuff. The code for net_store_length I have shown you in my answer has something for integer starting at line 458

00450 {
00451   uchar *packet=(uchar*) pkg;
00452   if (length < 251)
00453   {
00454     *packet=(uchar) length;
00455     return (char*) packet+1;
00456   }
00457   *packet++=252;
00458   int2store(packet,(uint) length);
00459   return (char*) packet+2;
00460 }

The function is called int2store. I don't think it can handle a BIGINT correctly since the 7 bytes after the NULL flag could be anything. Please keep in mind that signal 11 is a Segmentation Fault. In this case, it is due to the process of bytes that are unknown or spurious.

| improve this answer | |
  • 1
    Amazing answer @rolando! I was certain you were correct, but I just asked my developers about this. and their response was that the column is not a datetime column, it is defined as bigint and is storing ts.msec values mysql> desc api_dictionaryitem; | last_occurence | bigint(20) | YES | | NULL | | – Clayton Dukes Jul 6 '15 at 9:07
  • Hi @ClaytonDukes , were you able to find the solution . I faced a similar crash : dba.stackexchange.com/questions/155863/… – Shrey Nov 21 '16 at 10:21
  • 1
    @Shrey, we were never able to solve it. It actually caused so much of a problem that we switched to PostgreSQL. – Clayton Dukes Dec 2 '16 at 19:33
  • @ClaytonDukes : We had disable swap on the server and stopped oom killer. We have enabled swap now ( 20% swapiness) hoping that segfault was due to out of (allocated)memory constraints. – Shrey Dec 4 '16 at 6:03

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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