Percona Server 5.7.11-4-log crashed w/ specified sql_mode + sql

Bug #1583866 reported by Responder
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
New
Undecided
Unassigned

Bug Description

Tested on Ubuntu 14.04.4 LTS

Steps to reproduce (sql file as attached)

# mysql test < mysqldump_crash_table.sql
# mysql test
=============================================================================================
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 8
Server version: 5.7.11-4-log Percona Server (GPL), Release '4', Revision '5c940e1'

Copyright (c) 2009-2016 Percona LLC and/or its affiliates
Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SHOW CREATE TABLE crash_table\G
*************************** 1. row ***************************
       Table: crash_table
Create Table: CREATE TABLE `crash_table` (
  `memberID` int(11) NOT NULL,
  `action` char(10) NOT NULL,
  `time` int(11) NOT NULL,
  PRIMARY KEY (`memberID`,`action`),
  KEY `action_time` (`action`,`time`),
  KEY `time` (`time`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> SELECT COUNT(1) FROM crash_table;
+----------+
| COUNT(1) |
+----------+
| 52462 |
+----------+
1 row in set (0.01 sec)

mysql> SHOW VARIABLES LIKE 'sql_mode';
+---------------+------------------------------------------------------------------------------------------------------------------------+
| Variable_name | Value |
+---------------+------------------------------------------------------------------------------------------------------------------------+
| sql_mode | STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION |
+---------------+------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.01 sec)

mysql> SELECT DISTINCT `memberID` FROM `crash_table` WHERE `memberID` != 0 ORDER BY `time` DESC LIMIT 5;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> Bye
=============================================================================================

According to the test it only happened when I turn off sql_mode=ONLY_FULL_GROUP_BY and row count is larger.
=============================================================================================
mysql> SET sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION';
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT COUNT(1) FROM crash_table;
+----------+
| COUNT(1) |
+----------+
| 52462 |
+----------+
1 row in set (0.02 sec)

mysql> SELECT DISTINCT `memberID` FROM `crash_table` WHERE `memberID` != 0 ORDER BY `time` DESC LIMIT 5;
ERROR 3065 (HY000): Expression #1 of ORDER BY clause is not in SELECT list, references column 'test.crash_table.time' which is not in SELECT list; this is incompatible with DISTINCT
=============================================================================================

Note : can't find a consistent row counts for the crash point.
=============================================================================================
mysql> SELECT COUNT(1) FROM crash_table;
+----------+
| COUNT(1) |
+----------+
| 52462 |
+----------+
1 row in set (0.02 sec)

mysql> DELETE FROM crash_table LIMIT 42462;
Query OK, 42462 rows affected (5.09 sec)

mysql> SELECT COUNT(1) FROM crash_table;
+----------+
| COUNT(1) |
+----------+
| 10000 |
+----------+
1 row in set (0.01 sec)

mysql> SELECT DISTINCT `memberID` FROM `crash_table` WHERE `memberID` != 0 ORDER BY `time` DESC LIMIT 5;
+----------+
| memberID |
+----------+
| 4377408 |
| 4377407 |
| 4377406 |
| 4377404 |
| 4377405 |
+----------+
5 rows in set (0.00 sec)
=============================================================================================

mysql error.log
=============================================================================================
2016-05-20T01:44:37.179831Z mysqld_safe Number of processes running now: 0
2016-05-20T01:44:37.181948Z mysqld_safe mysqld restarted
2016-05-20T01:44:37.201314Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 51205)
2016-05-20T01:44:37.201546Z 0 [Warning] Changed limits: max_connections: 214 (requested 10240)
2016-05-20T01:44:37.201568Z 0 [Warning] Changed limits: table_open_cache: 400 (requested 15360)
2016-05-20T01:44:37.380788Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-05-20T01:44:37.381487Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.11-4-log) starting as process 29267 ...
2016-05-20T01:44:37.391723Z 0 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
2016-05-20T01:44:37.391907Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-05-20T01:44:37.391948Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-05-20T01:44:37.391970Z 0 [Note] InnoDB: Uses event mutexes
2016-05-20T01:44:37.391990Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-05-20T01:44:37.392010Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-05-20T01:44:37.392030Z 0 [Note] InnoDB: Using Linux native AIO
2016-05-20T01:44:37.393047Z 0 [Note] InnoDB: Number of pools: 1
2016-05-20T01:44:37.393281Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-05-20T01:44:37.623224Z 0 [Note] InnoDB: Initializing buffer pool, total size = 2G, instances = 8, chunk size = 128M
2016-05-20T01:44:37.952289Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-05-20T01:44:37.984895Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-05-20T01:44:37.997350Z 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /var/lib/mysql/xb_doublewrite
2016-05-20T01:44:38.030557Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-05-20T01:44:38.051338Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 52855620
2016-05-20T01:44:38.051405Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 52855629
2016-05-20T01:44:38.071694Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 52855629
2016-05-20T01:44:38.071764Z 0 [Note] InnoDB: Database was not shutdown normally!
2016-05-20T01:44:38.071786Z 0 [Note] InnoDB: Starting crash recovery.
2016-05-20T01:44:38.492994Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /var/lib/mysql/xb_doublewrite, size 31457280 bytes
2016-05-20T01:44:38.583284Z 0 [Note] InnoDB: Last MySQL binlog file position 0 33562, file name ID20155-mysqlbin.000012
2016-05-20T01:44:38.592448Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2016-05-20T01:44:38.592504Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-05-20T01:44:38.592628Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-05-20T01:44:38.743757Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-05-20T01:44:38.745786Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-05-20T01:44:38.745839Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-05-20T01:44:38.746468Z 0 [Note] InnoDB: Waiting for purge to start
2016-05-20T01:44:38.796670Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.11-4 started; log sequence number 52855629
2016-05-20T01:44:38.797344Z 0 [Note] Plugin 'FEDERATED' is disabled.
2016-05-20T01:44:38.799858Z 0 [Note] Recovering after a crash using /var/log/mysql/ID20155-mysqlbin
2016-05-20T01:44:38.800221Z 0 [Note] Starting crash recovery...
2016-05-20T01:44:38.800805Z 0 [Note] Crash recovery finished.
2016-05-20T01:44:38.814002Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2016-05-20T01:44:38.818692Z 0 [Note] InnoDB: Buffer pool(s) load completed at 160520 9:44:38
2016-05-20T01:44:38.976002Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2016-05-20T01:44:38.976060Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2016-05-20T01:44:39.060320Z 0 [Warning] CA certificate ca.pem is self signed.
2016-05-20T01:44:39.060482Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2016-05-20T01:44:39.060734Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2016-05-20T01:44:39.060805Z 0 [Note] IPv6 is available.
2016-05-20T01:44:39.060845Z 0 [Note] - '::' resolves to '::';
2016-05-20T01:44:39.060870Z 0 [Note] Server socket created on IP: '::'.
2016-05-20T01:44:39.083157Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-05-20T01:44:39.083239Z 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-05-20T01:44:39.083305Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-05-20T01:44:39.083340Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-05-20T01:44:39.102082Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-05-20T01:44:39.164255Z 0 [Note] Event Scheduler: Loaded 0 events
2016-05-20T01:44:39.182033Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.11-4-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release '4', Revision '5c940e1'
01:53:54 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=1048576
max_used_connections=1
max_threads=215
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 = 285127 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f67b57f8000
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 = 7f6889a91e00 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xec0e3c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79b821]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f68881ff340]
/usr/sbin/mysqld[0xc8e8f5]
/usr/sbin/mysqld(_ZN4JOIN14test_skip_sortEv+0x15d)[0xc8f67d]
/usr/sbin/mysqld(_ZN4JOIN8optimizeEv+0x1b55)[0xc9c775]
/usr/sbin/mysqld(_ZN13st_select_lex8optimizeEP3THD+0x685)[0xce1795]
/usr/sbin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x155)[0xce1975]
/usr/sbin/mysqld[0x75ac89]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x46a8)[0xca5448]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x5a5)[0xca8425]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x92f)[0xca8dcf]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b7)[0xcaa767]
/usr/sbin/mysqld(handle_connection+0x2a8)[0xd6aed8]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x1226734]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7f68881f7182]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f688770447d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f67b5bd0030): SELECT DISTINCT `memberID` FROM `crash_table` WHERE `memberID` != 0 ORDER BY `time` DESC LIMIT 5
Connection ID (thread ID): 8
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.
=============================================================================================

my.cnf
=============================================================================================
[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
skip-external-locking
skip-name-resolve
sql_mode='STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'
innodb_file_format = BARRACUDA
log_bin_trust_function_creators=1
innodb_log_file_size = 512M
innodb_log_buffer_size = 8M
innodb_file_per_table
max_allowed_packet = 16M
thread_stack = 192K
join_buffer_size = 512K
thread_cache_size = 16
max_connections = 10240
innodb_buffer_pool_size = 1536M
table_open_cache = 15360
table_definition_cache = 640
query_cache_limit = 2M
query_cache_min_res_unit = 2K
read_buffer_size = 1M
general_log_file = /var/log/mysql/mysql.log
general_log = 1
log_error = /var/log/mysql/error.log
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 60
server-id = 20155
log-bin = /var/log/mysql/ID20155-mysqlbin.log
expire_logs_days = 14
max_binlog_files = 64
max_binlog_size = 1024M
=============================================================================================

Revision history for this message
Responder (responder-ad) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.