Percona mysqld hat Signal 11 erhalten

7

Ich habe den Stapelaustausch gegoogelt und durchsucht, kann jedoch nichts Relevantes für dieses spezielle Problem finden (es gibt andere Fehler 11-Probleme, nur nicht, soweit ich das beurteilen kann).

Wir haben einen Server, der nicht wirklich viele Lese- oder Schreibvorgänge ausführt. Der Server ist eine VM mit 16 Kernen und 16 GB RAM.

MySQL stürzt nach einer unbekannten Zeit ab und das Fehlerprotokoll zeigt:

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

Ich glaube nicht, dass dies mit Percona zusammenhängt, da es auch mit normalem MySQL funktioniert (ich habe Percona geladen, um zu sehen, ob es das Problem beheben würde).

Das general.log zeigt während dieser Zeit nur Folgendes:

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

Die gesamte Datenbank ist nur 5,3 MB groß

Ich habe Stunden damit verbracht, dies herauszufinden, aber es ist mir an diesem Punkt ein Rätsel.

BEARBEITEN: Ja, ich weiß, dass das Vorkommen falsch geschrieben ist. Es befindet sich in der Ticketwarteschlange für eine Korrektur, aber es ist derzeit im gesamten Code konsistent, daher ist es nicht die Ursache.

BEARBEITEN 2: Hinzufügen der MySQL-Konfiguration - die mit dem Generierungswerkzeug von Percona generiert wurde. Ich habe es als "sichere" Konfiguration verwendet.

# 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
Clayton Dukes
quelle
Warum verwenden Sie XA-Transaktionen?
Winmutt
@winmutt, ich habe mein Entwicklerteam gefragt, warum sie autocommit=1Django verwenden, um diese Dinge zu verwalten, und angenommen, dass es Django war, der es tut.
Clayton Dukes
@winmutt, hier ist die Referenz dafür: https://docs.djangoproject.com/en/1.8/topics/db/transactions/#autocommit-details- Sie verwenden auch diese:https://docs.djangoproject.com/en/1.8/topics/db/transactions/#tying-transactions-to-http-requests
Clayton Dukes
@ClaytonDukes auf welcher VM-Lösung war das?
Winmutt
@winmutt, Amazon EC2 (Ubuntu 14 LTS) und auch bei Digital Ocean sowie inhouse KVM / Qemu
Clayton Dukes

Antworten:

11

Was mir auffällt, ist die Abfrage, die im allgemeinen Protokoll aufgezeichnet ist

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

wenn du Signal 11 hast

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

Ich würde vermuten, dass Sie api_dictionaryitemin diesem Fall einen seltsamen Fehler beim Ausführen der Tabelle festgestellt haben. Warum ?

Schauen Sie sich die Antwort auf das Signal 11 an, das Sie erhalten haben und das ich auflisten werde

  • Dies könnte daran liegen, dass Sie einen Fehler gefunden haben.
  • Es ist auch möglich, dass diese Binärdatei oder eine der Bibliotheken, mit denen sie verknüpft wurde, beschädigt, nicht ordnungsgemäß erstellt oder falsch konfiguriert ist.
  • Dieser Fehler kann auch durch eine fehlerhafte Hardware verursacht werden.
  • Wir werden unser Bestes geben, um einige Informationen zu sammeln, die hoffentlich bei der Diagnose des Problems helfen. Da wir jedoch bereits abgestürzt sind, stimmt definitiv etwas nicht, und dies kann fehlschlagen.

Mal sehen, was mysqld tat, bevor es auf einen Stack-Trace zurückgreifen musste

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]

Schauen Sie sich die Zeile an, in der steht

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

Die Abfrage zum Zeitpunkt des Aufpralls war

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

Was machte net_store_data in diesem Moment?

Das Buch zu verstehen MySQL Internals sagt etwas über net_store_data und NULL - Werte auf den Seiten 74,75 unter der Rubrik Server Responses Unterposition Datenfelder

MySQL-Interna

Datenfelder sind wichtige Komponenten in vielen Serverantwortpaketen. Ein Datenfeld besteht aus einer Längenangabesequenz, gefolgt vom tatsächlichen Datenwert. Die Längenangabenfolge kann durch Studium von net_store_length () ... verstanden werden.

Interessant ist, dass net_store_data () net_store_length () in Zeile 482 in aufruft protocol.cc. Dieser Code sieht so aus

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

In Zeile 489 sieht eine andere Version von net_store_data () folgendermaßen aus:

{
  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;
}

In Zeile 498 sieht eine andere Version von net_store_data () folgendermaßen aus:

{
  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;
}

Diese Codeausschnitte finden Sie in SourceCodeBrowser

Der Code für 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 }

finden Sie hier

Da net_store_data der einzige Fehlerpunkt in der Stapelverfolgung ist, was in der SQL hätte einen solchen Fehler ausgelöst?

Schauen Sie zurück auf die SQL

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

Das einzige, was mir fehl am Platz erscheint, ist das

`last_occurence` = NULL

Schauen Sie sich den Code für net_store_length noch einmal an. Beachten Sie die Zeile

00452   if (length < 251)

Was ist das Besondere an der Nummer 251? Laut dem Buch Grundlegendes zu MySQL-Interna heißt es im letzten Absatz auf Seite 74:

Man kann sich fragen, warum die 1-Byte-Länge auf 251 begrenzt ist, wenn der erste reservierte Wert in net_store_length()252 ist. Der Code 251 hat eine besondere Bedeutung. Es zeigt an, dass dem Code kein Längenwert oder keine Daten folgen und der Wert des Felds SQL NULL ist.

Aha !!! Der NULL-Wert wird in net_store_length () beim Umgang mit dem last_occurenceFeld falsch behandelt . Wenn last_occurencees sich um DATETIME oder TIMESTAMP handelt, ist die Verwendung von NULL höchstwahrscheinlich nicht zulässig.

Vielleicht ändern

`last_occurence` = NULL

zu einem falschen, aber legitimen Datumswert

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

würde dieses Problem wahrscheinlich direkt auf den Kopf treffen.

Die erste Antwort des Stack-Trace war richtig: This could be because you hit a bug.

Bitte lesen Sie die MySQL-Dokumentation zur Verwendung eines Stack-Trace .

UPDATE 2015-07-06 10:47 EST

Zuvor haben Sie die Definition der Tabelle kommentiert

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)

Sie erwähnten , dass last_occurenceist BIGINT. Überlegen Sie sich BIGINT, NULLwas das bewirkt , da es 8 Bytes sind und auf eingestellt werden .

Das erste Byte hat 0xFB (251), gefolgt von 7 Bytes undefinierten Materials. Der Code für net_store_lengthIch habe Ihnen in meiner Antwort etwas für eine Ganzzahl ab Zeile 458 gezeigt

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 }

Die Funktion wird aufgerufen int2store. Ich denke nicht, dass es mit einem BIGINT richtig umgehen kann, da die 7 Bytes nach dem NULL-Flag alles sein könnten. Bitte beachten Sie, dass Signal 11 ein Segmentierungsfehler ist. In diesem Fall ist dies auf den Prozess von Bytes zurückzuführen, die unbekannt oder falsch sind.

RolandoMySQLDBA
quelle
1
Erstaunliche Antwort @rolando! Ich war mir sicher, dass Sie Recht hatten, aber ich habe gerade meine Entwickler danach gefragt. und ihre Antwort war, dass die Spalte keine datetime-Spalte ist, sondern als bigint definiert ist und ts.msec-Werte speichertmysql> desc api_dictionaryitem; | last_occurence | bigint(20) | YES | | NULL | |
Clayton Dukes
Hallo @ClaytonDukes, konnten Sie die Lösung finden. Ich hatte einen ähnlichen Absturz: dba.stackexchange.com/questions/155863/…
Shrey
1
@Shrey, wir konnten es nie lösen. Es hat tatsächlich so viele Probleme verursacht, dass wir zu PostgreSQL gewechselt sind.
Clayton Dukes
@ClaytonDukes: Wir hatten Swap auf dem Server deaktiviert und Oom Killer gestoppt. Wir haben jetzt Swap aktiviert (20% Swapiness), in der Hoffnung, dass Segfault auf nicht zugewiesene Speicherbeschränkungen zurückzuführen ist.
Shrey