percona 5.6.21-70.0 crash on data import

[Damian Luszczymak]

141108 11:00:53 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
141108 11:00:53 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2014-11-08 11:00:54 0 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead.
2014-11-08 11:00:54 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-11-08 11:00:54 6628 [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.
2014-11-08 11:00:54 6628 [Note] Plugin 'FEDERATED' is disabled.
2014-11-08 11:00:54 6628 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-11-08 11:00:54 6628 [Note] InnoDB: The InnoDB memory heap is disabled
2014-11-08 11:00:54 6628 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-11-08 11:00:54 6628 [Note] InnoDB: Memory barrier is not used
2014-11-08 11:00:54 6628 [Note] InnoDB: Compressed tables use zlib 1.2.8
2014-11-08 11:00:54 6628 [Note] InnoDB: Using Linux native AIO
2014-11-08 11:00:54 6628 [Note] InnoDB: Using CPU crc32 instructions
2014-11-08 11:00:54 6628 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-11-08 11:00:54 6628 [Note] InnoDB: Completed initialization of buffer pool
2014-11-08 11:00:54 6628 [Note] InnoDB: Highest supported file format is Barracuda.
2014-11-08 11:00:54 6628 [Note] InnoDB: 128 rollback segment(s) are active.
2014-11-08 11:00:54 6628 [Note] InnoDB: Waiting for purge to start
2014-11-08 11:00:54 6628 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-70.0 started; log sequence number 1787080
2014-11-08 11:00:54 6628 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2014-11-08 11:00:54 6628 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2014-11-08 11:00:54 6628 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2014-11-08 11:00:54 6628 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2014-11-08 11:00:54 6628 [Note] Server socket created on IP: '127.0.0.1'.
2014-11-08 11:00:54 6628 [Note] Event Scheduler: Loaded 0 events
2014-11-08 11:00:54 6628 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.21-70.0' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release 70.0, Revision 688
10:01:01 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=16777216
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 77372 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f9c45e6c000
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 = 7f9c764d8e20 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0x8fff2b]
/usr/sbin/mysqld(handle_fatal_signal+0x369)[0x651369]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfc90)[0x7f9c74c41c90]
/usr/sbin/mysqld[0xabd1bd]
/usr/sbin/mysqld[0xab06a7]
/usr/sbin/mysqld[0xab1475]
/usr/sbin/mysqld[0xab3b9e]
/usr/sbin/mysqld[0xabe2e6]
/usr/sbin/mysqld[0xa421d0]
/usr/sbin/mysqld[0xa42f07]
/usr/sbin/mysqld[0xa43544]
/usr/sbin/mysqld[0xa4e4bb]
/usr/sbin/mysqld[0x9b89a1]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0xbf)[0x58ffaf]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x86)[0x6c1fb6]
/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xf0d)[0x6c530d]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x2334)[0x6dd4e4]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x640)[0x6e2680]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x21e5)[0x6e4ea5]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x245)[0x6aa855]
/usr/sbin/mysqld(handle_one_connection+0x39)[0x6aa8a9]
/usr/sbin/mysqld(pfs_spawn_thread+0x140)[0x944e80]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a5)[0x7f9c74c3a0a5]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f9c7435284d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f9c3ee79010): is an invalid pointer
Connection ID (thread ID): 37
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.
141108 11:01:01 mysqld_safe Number of processes running now: 0
141108 11:01:01 mysqld_safe mysqld restarted
2014-11-08 11:01:01 0 [Warning] Using unique option prefix key_buffer instead of key_buffer_size is deprecated and will be removed in a future release. Please use the full name instead.
2014-11-08 11:01:01 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-11-08 11:01:01 6749 [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.
2014-11-08 11:01:01 6749 [Note] Plugin 'FEDERATED' is disabled.
2014-11-08 11:01:01 6749 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-11-08 11:01:01 6749 [Note] InnoDB: The InnoDB memory heap is disabled
2014-11-08 11:01:01 6749 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-11-08 11:01:01 6749 [Note] InnoDB: Memory barrier is not used
2014-11-08 11:01:01 6749 [Note] InnoDB: Compressed tables use zlib 1.2.8
2014-11-08 11:01:01 6749 [Note] InnoDB: Using Linux native AIO
2014-11-08 11:01:01 6749 [Note] InnoDB: Using CPU crc32 instructions
2014-11-08 11:01:01 6749 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-11-08 11:01:01 6749 [Note] InnoDB: Completed initialization of buffer pool
2014-11-08 11:01:01 6749 [Note] InnoDB: Highest supported file format is Barracuda.
2014-11-08 11:01:01 6749 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1787090
2014-11-08 11:01:01 6749 [Note] InnoDB: Database was not shutdown normally!
2014-11-08 11:01:01 6749 [Note] InnoDB: Starting crash recovery.
2014-11-08 11:01:01 6749 [Note] InnoDB: Reading tablespace information from the .ibd files...
2014-11-08 11:01:01 6749 [Note] InnoDB: Restoring possible half-written data pages
2014-11-08 11:01:01 6749 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1835831
2014-11-08 11:01:01 6749 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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
2014-11-08 11:01:02 6749 [Note] InnoDB: 128 rollback segment(s) are active.
2014-11-08 11:01:02 6749 [Note] InnoDB: Waiting for purge to start
2014-11-08 11:01:02 6749 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-70.0 started; log sequence number 1835831
2014-11-08 11:01:02 6749 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2014-11-08 11:01:02 6749 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2014-11-08 11:01:02 6749 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2014-11-08 11:01:02 6749 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2014-11-08 11:01:02 6749 [Note] Server socket created on IP: '127.0.0.1'.
2014-11-08 11:01:02 6749 [Note] Event Scheduler: Loaded 0 events
2014-11-08 11:01:02 6749 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.21-70.0' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release 70.0, Revision 688

[Valerii Kravchuk (valerii-kravchuk)]

Please, send the output of SHOW CREATE TABLE for the table you are inserting into, and, if possible, the exact INSERT statement that leads to crash.

[Damian Luszczymak (daim1985)]

CREATE TABLE `admin_rule` (
  `rule_id` int(10) unsigned NOT NULL AUTO_INCREMENT COMMENT 'Rule ID',
  `role_id` int(10) unsigned NOT NULL DEFAULT '0' COMMENT 'Role ID',
  `resource_id` varchar(255) NOT NULL COMMENT 'Resource ID',
  `privileges` varchar(20) DEFAULT NULL COMMENT 'Privileges',
  `assert_id` int(10) unsigned NOT NULL DEFAULT '0' COMMENT 'Assert ID',
  `role_type` varchar(1) DEFAULT NULL COMMENT 'Role Type',
  `permission` varchar(10) DEFAULT NULL COMMENT 'Permission',
  PRIMARY KEY (`rule_id`),
  KEY `IDX_ADMIN_RULE_RESOURCE_ID_ROLE_ID` (`resource_id`,`role_id`),
  KEY `IDX_ADMIN_RULE_ROLE_ID_RESOURCE_ID` (`role_id`,`resource_id`),
  CONSTRAINT `FK_ADMIN_RULE_ROLE_ID_ADMIN_ROLE_ROLE_ID` FOREIGN KEY (`role_id`) REFERENCES `admin_role` (`role_id`) ON DELETE CASCADE ON UPDATE CASCADE
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='Admin Rule Table'

For the insert statement see the attached mysql.log

[Valerii Kravchuk (valerii-kravchuk)]

Do you run this on Ubuntu 14.10? I've just checked with statements from you general query log uploaded on CentOS 6.5 with the same Percona Server version and everything just works:

...
(27801,561,'admin/webforms/forms',NULL,0,'G','deny'),(27802,561,'admin/webforms/quickresponses',NULL,0,'G','deny'),(27803,561,'admin/webforms/settings',NULL,0,'G','deny'),(27804,561,'admin/webforms/webform_1',NULL,0,'G','deny');
Query OK, 3562 rows affected (1.49 sec)
Records: 3562 Duplicates: 0 Warnings: 0

mysql> select count(*) from admin_rule;
+----------+
| count(*) |
+----------+
| 3562 |
+----------+
1 row in set (0.05 sec)

mysql> select version();
+-------------+
| version() |
+-------------+
| 5.6.21-70.0 |
+-------------+
1 row in set (0.02 sec)

[Damian Luszczymak (daim1985)]

Yes ubuntu 14.10

I have this in my apt source.list

deb http://repo.percona.com/apt utopic main
deb-src http://repo.percona.com/apt utopic main

Attached you find a small part from the dump, but this one still crash :-(

[Valerii Kravchuk (valerii-kravchuk)]

No crash on Ubuntu 14.04.1 LTS. It seems binaries from trusty may work...

[Damian Luszczymak (daim1985)]

Yes, the binary from trusty work.

[Valerii Kravchuk (valerii-kravchuk)]

I was able to reproduce the crash by replaying your mysql.log uploaded on 32-bit Ubuntu 14.10:

01:57:11 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=16777216
read_buffer_size=131072
max_used_connections=2
max_threads=153
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 76654 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x9ff89e8
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 = ffffffff8db922f8 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x3c)[0x84fd2fc]
/usr/sbin/mysqld(handle_fatal_signal+0x33e)[0x826413e]
[0xb774cc58]
/usr/sbin/mysqld[0x863574b]
/usr/sbin/mysqld[0x8629b4a]
/usr/sbin/mysqld[0x862a7dc]
/usr/sbin/mysqld[0x862cc38]
/usr/sbin/mysqld[0x863672b]
/usr/sbin/mysqld[0x85c1930]
/usr/sbin/mysqld[0x85c1fb4]
/usr/sbin/mysqld[0x85c24fe]
/usr/sbin/mysqld[0x85cc4a3]
/usr/sbin/mysqld[0x853c0d3]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0x9f)[0x81ac93f]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x89)[0x82d14d9]
/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xf56)[0x82d4746]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x29cc)[0x82ebc3c]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5e9)[0x82f11a9]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x2109)[0x82f3949]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x11f)[0x82f452f]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x1f2)[0x82bab72]
/usr/sbin/mysqld(handle_one_connection+0x30)[0x82bac30]
/usr/sbin/mysqld(pfs_spawn_thread+0x188)[0x8708ec8]
/lib/i386-linux-gnu/libpthread.so.0(+0x6f16)[0xb7493f16]
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb72709fe]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (ffffffff8850adf8): is an invalid pointer
Connection ID (thread ID): 46
Status: NOT_KILLED

[Roel Van de Paar (roel11)]

Bug 1382738 has very similar, though shorter, stack

[Roel Van de Paar (roel11)]

Damian, btw, the sql traces you uploaded contain email addresses etc. - let us know if you want us to hide them (though they remain visible in full activity log). I am able to reproduce the issue on Ubuntu 14.10 32 bit and reducing testcase further.

[Roel Van de Paar (roel11)]

- Issue happens on INSERT
- Issue seems to be restricted to UTF8 (removing the 'DEFAULT CHARSET=utf8' clause from table creation makes the issue no longer reproducible)
- Issue seems to be restricted to a very specific table definition and subsequent very specific INSERTs
  - Making minor changes to inserts (in an effort to simplify data) makes issue no longer reproducible
- MS Optimized on Ubuntu 14.10 32 bit does not crash on optimized testcase in #11
- PS Debug on Ubuntu 14.10 32 bit DOES crash this testcase
- PS Debug x64 on Centos7 does on optimized testcase in #11

Even with reduced testcase, stack remains long;

(gdb) bt
#0 0xb770ac7c in __kernel_vsyscall ()
#1 0xb7447da3 in __pthread_kill (threadid=2743511872, signo=11) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#2 0x084fc93c in my_write_core ()
#3 0x08264100 in handle_fatal_signal ()
#4 <signal handler called>
#5 0x0863574b in ?? ()
#6 0x08629b4a in ?? ()
#7 0x0862a7dc in ?? ()
#8 0x0862cc38 in ?? ()
#9 0x0863672b in ?? ()
#10 0x085c1930 in ?? ()
#11 0x085c1fb4 in ?? ()
#12 0x085c24fe in ?? ()
#13 0x085cc4a3 in ?? ()
#14 0x0853c0d3 in ?? ()
#15 0x081ac93f in handler::ha_write_row(unsigned char*) ()
#16 0x082d14d9 in write_record(THD*, TABLE*, COPY_INFO*, COPY_INFO*) ()
#17 0x082d4746 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) ()
#18 0x082ebc3c in mysql_execute_command(THD*) ()
#19 0x082f11a9 in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()
#20 0x082f3949 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#21 0x082f452f in do_command(THD*) ()
#22 0x082bab72 in do_handle_one_connection(THD*) ()
#23 0x082bac30 in handle_one_connection ()
#24 0x08708ec8 in pfs_spawn_thread ()
#25 0xb7442f16 in start_thread (arg=0xa386ab40) at pthread_create.c:309
#26 0xb721f9fe in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129

It is unclear what is happening at frames 5-14 (this is a debug build). Lower and resolved part of stack matches Bug 1382738. Personal thought; this is same bug, with some extra OS-specific frames in between, not resolved because of using release OS code. However, in that I am not clear on why this particular issue only shows on 32 bit. Maybe some sort of address overflow/variable type issue.

[Roel Van de Paar (roel11)]

Minor correction; PS Debug x64 on Centos7 does NOT crash on optimized testcase in #11

[Damian Luszczymak (daim1985)]

Yes Roel if you can delete the file, you have now your own testcase. Didn't saw this :-(

[Roel Van de Paar (roel11)]

Damian, Re #10/#14/#15: as per our discussion/your request I have deleted the files. I actually was able to delete them completely so that should help with security. As it looks like there was email, username and hashed password in these files you may want to consider letting these people know. I was able to generate a testcase with hashed username, email and password. Uploaded to $15 and all other testcases deleted. Hope this helps!

[Roel Van de Paar (roel11)]

hashed; as in obfuscated (replaced most letters with 'a')

[Damian Luszczymak (daim1985)]

thanks

[Laurynas Biveinis (laurynas-biveinis)]

btr_cur_ins_lock_and_undo is compiled to, inlined into btr_cur_optimistic_insert:

if (thr == 0) goto L2;
if (thr->trx->fake_changes != 0) goto ...
L2:
if (lock_rec_insert_check_and_lock(flags, rec, tmp, index, thr, mtr, inherit) != DB_SUCCESS) goto ...
if (index->type & DICT_CLUSTERED) goto L1;
if (index->type & DICT_IBUF) goto ...
L1:
if (thr->trx->fake_changes != 0) goto ..

The check at L1 is what crashes. The source code it corresponds to is
line 1508 of btr0cur.cc:

if (UNIV_UNLIKELY(thr && thr_get_trx(thr)->fake_changes)) {

So, the thr != NULL check is getting optimized away. The incorrect
attribute((nonnull)) annotation on lock_rec_insert_check_and_lock
might be causing an incorrect thr != NULL assumption propagation
here.

[Laurynas Biveinis (laurynas-biveinis)]

Verified that fixing the incorrect attribute((nonnull)) annotations restored the lost thr != NULL check.

The incorrect annotations have been reported upstream as http://bugs.mysql.com/bug.php?id=74842. Marking this bug as a copy of that one, although it might be benign in Oracle MySQL currently.

We will respin the Utopic packages to include this fix.

Setting the target milestone for the fix to the next Percona Server release, that's when the other platforms will receive the code change.

[Tomislav Plavcic (tplavcic)]

New packages for Ubuntu Utopic have been pushed to main repository with the fix for this bug so everybody using that distribution should upgrade - revision number on the packages is 689 (initial was 688).

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-385