mysql server crash accessing Virtual Column Index to Indirectly Index a JSON Column

[rajani]

Hi , We are testing Json to implement in our new project and as part of test we tried to create table with Json column and other columns(virtual) to pre populate data based on json column. Inserts go fine. But when i create index on one of the column. And try a select using where <index_column> mysql crashes. And we have seen this happening on both 5.7.10 and 5.7.11. Please help in resolving this issue.

-- Here is the table syntax:
mysql> show create table load_test_par\G
*************************** 1. row ***************************
       Table: load_test_par
Create Table: CREATE TABLE `load_test_par` (
  `data` json DEFAULT NULL,
  `create_date` datetime GENERATED ALWAYS AS (replace(replace(replace(json_extract(`data`,'$.dateTime'),'"',''),'T',' '),'Z','')) VIRTUAL,
  `eventType` varchar(16) GENERATED ALWAYS AS (json_extract(`data`,'$.eventType')) VIRTUAL,
  `appName` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.appName')) VIRTUAL,
  `appBuildVersion` varchar(32) GENERATED ALWAYS AS (json_extract(`data`,'$.appBuildVersion')) VIRTUAL,
  `acquisitionDivision` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.acquisitionDivision')) VIRTUAL,
  `adNetwork` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.adNetwork')) VIRTUAL,
  `dataCenter` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.dataCenter')) VIRTUAL,
  `locale` varchar(8) GENERATED ALWAYS AS (json_extract(`data`,'$.locale')) VIRTUAL,
  `product` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.product')) VIRTUAL,
  `channel` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.channel')) VIRTUAL,
  `moduleName` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.app.moduleName')) VIRTUAL,
  `providerSource` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.app.providerSource')) VIRTUAL,
  `productDivision` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.productDivision')) VIRTUAL,
  `queryOrigination` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.app.queryOrigination')) VIRTUAL,
  `resultType` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.app.resultType')) VIRTUAL,
  `suspectCategory` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.suspectCategory')) VIRTUAL,
  `deviceType` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.deviceType')) VIRTUAL,
  `responseCode` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.responseCode')) VIRTUAL,
  `actionType` varchar(64) GENERATED ALWAYS AS (json_extract(`data`,'$.app.actionType')) VIRTUAL,
  KEY `dba_idx` (`create_date`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
/*!50500 PARTITION BY RANGE ( to_seconds(create_date))
(PARTITION p1_10 VALUES LESS THAN (63628909500) ENGINE = InnoDB,
 PARTITION p1_11 VALUES LESS THAN (63628909560) ENGINE = InnoDB,
 PARTITION p1_12 VALUES LESS THAN (63628909620) ENGINE = InnoDB,
 PARTITION p1_13 VALUES LESS THAN (63628909680) ENGINE = InnoDB,
 PARTITION p1_14 VALUES LESS THAN (63628909740) ENGINE = InnoDB,
 PARTITION p1_15 VALUES LESS THAN (63628909800) ENGINE = InnoDB,
 PARTITION p1_16 VALUES LESS THAN (63628909860) ENGINE = InnoDB,
 PARTITION p1_17 VALUES LESS THAN (63628909920) ENGINE = InnoDB,
 PARTITION p1_18 VALUES LESS THAN (63628909980) ENGINE = InnoDB,
 PARTITION p1_19 VALUES LESS THAN (63628910040) ENGINE = InnoDB,
 PARTITION p1_20 VALUES LESS THAN (63628910100) ENGINE = InnoDB,
 PARTITION p1_21 VALUES LESS THAN (63628910160) ENGINE = InnoDB,
 PARTITION p1_22 VALUES LESS THAN (63628910220) ENGINE = InnoDB,
 PARTITION p1_23 VALUES LESS THAN (63628910280) ENGINE = InnoDB,
 PARTITION p1_24 VALUES LESS THAN (63628910340) ENGINE = InnoDB,
 PARTITION p1_25 VALUES LESS THAN (63628910400) ENGINE = InnoDB,
 PARTITION p1_26 VALUES LESS THAN (63628910460) ENGINE = InnoDB,
 PARTITION p1_27 VALUES LESS THAN (63628910520) ENGINE = InnoDB,
 PARTITION p1_28 VALUES LESS THAN (63628910580) ENGINE = InnoDB,
 PARTITION p1_29 VALUES LESS THAN (63628910640) ENGINE = InnoDB,
 PARTITION p1_30 VALUES LESS THAN (63628910700) ENGINE = InnoDB,
 PARTITION p1_31 VALUES LESS THAN (63628910760) ENGINE = InnoDB,
 PARTITION p1_32 VALUES LESS THAN (63628910820) ENGINE = InnoDB,
 PARTITION p1_33 VALUES LESS THAN (63628910880) ENGINE = InnoDB,
 PARTITION p1_34 VALUES LESS THAN (63628910940) ENGINE = InnoDB,
 PARTITION p1_35 VALUES LESS THAN (63628911000) ENGINE = InnoDB,
 PARTITION p1_36 VALUES LESS THAN (63628911060) ENGINE = InnoDB,
 PARTITION p1_37 VALUES LESS THAN (63628911120) ENGINE = InnoDB,
 PARTITION p1_END VALUES LESS THAN MAXVALUE ENGINE = InnoDB) */
1 row in set (0.00 sec)

mysql> show indexes from load_test_par\G
*************************** 1. row ***************************
        Table: load_test_par
   Non_unique: 1
     Key_name: dba_idx
 Seq_in_index: 1
  Column_name: create_date
    Collation: A
  Cardinality: 1045
     Sub_part: NULL
       Packed: NULL
         Null: YES
   Index_type: BTREE
      Comment:
Index_comment:
1 row in set (0.00 sec)

mysql>
System crashes with below select :
mysql> select locale,suspectCategory,count(*) from load_test_par where eventType='Action' and create_date between '2016-04-26 17:12:45' and '2016-04-26 17:13:45' group by 1,2;

--- Table size is 60GB .

Error message during crash :
016-05-03 21:48:39 0x7fefac191700 InnoDB: Assertion failure in thread 140667361236736 in file row0mysql.cc line 202
InnoDB: Failing assertion: len < 256
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
04:48:39 UTC - mysqld got signal 6 ;
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=131072
max_used_connections=1
max_threads=513
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 = 211982 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fef3c000ae0
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 = 7fefac190d40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xea838c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7930d1]
/lib64/libpthread.so.0[0x3fd940f500]
/lib64/libc.so.6(gsignal+0x35)[0x3fd8c328a5]
/lib64/libc.so.6(abort+0x175)[0x3fd8c34085]
/usr/sbin/mysqld[0x761fde]
/usr/sbin/mysqld(_Z28row_mysql_store_true_var_lenPhmm+0x5a)[0xfbd82a]
/usr/sbin/mysqld(_Z40row_sel_field_store_in_mysql_format_funcPhPK17mysql_row_templ_tPKhm+0x1d0)[0xfdc960]
/usr/sbin/mysqld[0xfdca86]
/usr/sbin/mysqld(_Z15row_search_mvccPh15page_cur_mode_tP14row_prebuilt_tmm+0x1963)[0xfdf6c3]
/usr/sbin/mysqld(_ZN11ha_innobase13general_fetchEPhjj+0x100)[0xed75c0]
/usr/sbin/mysqld(_ZN11ha_innopart23read_range_next_in_partEjPh+0x32)[0xeeec42]
/usr/sbin/mysqld(_ZN16Partition_helper21handle_unordered_nextEPhb+0x88)[0xc06138]
/usr/sbin/mysqld(_ZN7handler21multi_range_read_nextEPPc+0xd2)[0x7ed6f2]
/usr/sbin/mysqld(_ZN18QUICK_RANGE_SELECT8get_nextEv+0x4b)[0xdb351b]
/usr/sbin/mysqld[0xc0ac1a]
/usr/sbin/mysqld(_Z10sub_selectP4JOINP7QEP_TABb+0x137)[0xc6ef77]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x237)[0xc67cf7]
/usr/sbin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x17d)[0xcd697d]
/usr/sbin/mysqld[0x754b4f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x4715)[0xc9a8a5]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x5b5)[0xc9d7d5]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x92f)[0xc9e17f]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b7)[0xc9fab7]
/usr/sbin/mysqld(handle_connection+0x280)[0xd5f590]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x1213f74]
/lib64/libpthread.so.0[0x3fd9407851]
/lib64/libc.so.6(clone+0x6d)[0x3fd8ce890d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fef3c005770): is an invalid pointer
Connection ID (thread ID): 2
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.
160503 21:48:39 mysqld_safe Number of processes running now: 0
160503 21:48:39 mysqld_safe mysqld restarted
2016-05-04T04:48:39.951487Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-05-04T04:48:39.951621Z 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2016-05-04T04:48:39.951756Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.10-3-log) starting as process 9255 ...
2016-05-04T04:48:39.963055Z 0 [Note] InnoDB: PUNCH HOLE support available
2016-05-04T04:48:39.963171Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-05-04T04:48:39.963216Z 0 [Note] InnoDB: Uses event mutexes
2016-05-04T04:48:39.963252Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2016-05-04T04:48:39.963286Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-05-04T04:48:39.963319Z 0 [Note] InnoDB: Using Linux native AIO
2016-05-04T04:48:39.965475Z 0 [Note] InnoDB: Number of pools: 1
2016-05-04T04:48:39.965888Z 0 [Note] InnoDB: Using CPU crc32 instructions
2016-05-04T04:48:40.014291Z 0 [Note] InnoDB: Initializing buffer pool, total size = 48G, instances = 8, chunk size = 128M
2016-05-04T04:48:45.831035Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-05-04T04:48:46.305099Z 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-04T04:48:46.364535Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-05-04T04:48:46.706743Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 18637880609807
2016-05-04T04:48:46.706891Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 18637880609816
2016-05-04T04:48:47.021905Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 18637880609816
2016-05-04T04:48:47.021976Z 0 [Note] InnoDB: Database was not shutdown normally!
2016-05-04T04:48:47.021992Z 0 [Note] InnoDB: Starting crash recovery.
2016-05-04T04:48:49.240064Z 0 [Note] InnoDB: Last MySQL binlog file position 8 3977125534, file name mysql-bin-dpbtm001iad.049673
2016-05-04T04:48:49.792501Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2016-05-04T04:48:49.792590Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-05-04T04:48:49.792657Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-05-04T04:48:49.811716Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-05-04T04:48:49.813284Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-05-04T04:48:49.813321Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-05-04T04:48:49.895364Z 0 [Note] InnoDB: Waiting for purge to start
2016-05-04T04:48:49.957179Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.10-3 started; log sequence number 18637880609816
2016-05-04T04:48:49.958069Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/db/ib_buffer_pool
2016-05-04T04:48:49.958870Z 0 [Note] InnoDB: not started
2016-05-04T04:48:49.959122Z 0 [Note] Plugin 'FEDERATED' is disabled.
2016-05-04T04:48:49.996053Z 0 [Note] Recovering after a crash using /ask/mysql/binlogs/mysql-bin-dpbtm001iad
2016-05-04T04:48:49.996100Z 0 [Note] Starting crash recovery...
2016-05-04T04:48:49.996220Z 0 [Note] Crash recovery finished.
2016-05-04T04:48:50.024768Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2016-05-04T04:48:50.024878Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2016-05-04T04:48:50.033191Z 0 [Warning] CA certificate ca.pem is self signed.
2016-05-04T04:48:50.033372Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2016-05-04T04:48:50.033891Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2016-05-04T04:48:50.034009Z 0 [Note] IPv6 is available.
2016-05-04T04:48:50.034056Z 0 [Note] - '::' resolves to '::';
2016-05-04T04:48:50.034081Z 0 [Note] Server socket created on IP: '::'.
2016-05-04T04:48:50.129844Z 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.129924Z 0 [Warning] 'user' entry '<email address hidden>' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.129964Z 0 [Warning] 'user' entry 'askdba@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.130147Z 0 [Warning] 'user' entry 'dba@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.130185Z 0 [Warning] 'user' entry 'xbackup@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.130209Z 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.130333Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.130375Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.130395Z 0 [Warning] 'proxies_priv' entry '@ <email address hidden>' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.213835Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-05-04T04:48:50.222979Z 0 [Note] Event Scheduler: Loaded 6 events
2016-05-04T04:48:50.223300Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.10-3-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release 3, Revision 63dafaf
2016-05-04T04:48:50.301676Z 0 [Note] InnoDB: Buffer pool(s) load completed at 160503 21:48:50

[rajani (rajani-sathuluri)]

we have seen this on Server version: 5.7.10-3-log Percona Server (GPL) and Server version: 5.7.10-3-log Percona Server (GPL) and Server version: 5.7.11-4-log Percona Server (GPL).

[Shahriyar Rzayev (rzayev-sehriyar)]

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