Bug #20486 server crashes under undeterminable (by me) circumstances
Submitted: 15 Jun 2006 19:39 Modified: 17 Jul 2006 17:04
Reporter: John Bachir Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S1 (Critical)
Version:5.0.21 OS:Linux (rhel 4)
Assigned to: CPU Architecture:Any

[15 Jun 2006 19:39] John Bachir
Description:
Version: '5.0.21-standard-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Edition - Standard (GPL)
060615 15:27:20InnoDB: Assertion failure in thread 7904176 in file row0sel.c line 2081
InnoDB: Failing assertion: dict_col_get_type(field->col)->mtype == dfield_get_type(dfield)->mtype
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/mysql/en/Forcing_recovery.html
InnoDB: about forcing recovery.
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.

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=2
max_connections=100
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 80383 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x8a9c8e8
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...
Cannot determine thread, fp=0x78492c, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x815c750
0xb76888
0x3
0x81f49d8
0x81f50e0
0x81f536f
0x81f90f5
0x81ae4a4
0x81b57de
0x81bb6ef
0x81bbdbb
0x8172489
0x8178afb
0x81792b7
0x817a098
0x817a7c0
0xb70371
0xadb9be
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/Using_stack_trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8ab1e48 = SELECT option_value FROM options WHERE blog = '435' AND option_name = 'siteurl' LIMIT 1
thd->thread_id=9
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Number of processes running now: 0
060615 15:27:20  mysqld restarted
060615 15:27:20 [Warning] No argument was provided to --log-bin, and --log-bin-index was not used; so replication may break when this MySQL serve
r acts as a master and has his hostname changed!! Please use '--log-bin=lyceum-bin' to avoid this problem.
060615 15:27:20  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...
060615 15:27:20  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 569363907.
InnoDB: Doing recovery: scanned up to log sequence number 0 569363907
InnoDB: Last MySQL binlog file position 0 481, file name ./lyceum-bin.010742
060615 15:27:20  InnoDB: Started; log sequence number 0 569363907
060615 15:27:20 [Note] Recovering after a crash using lyceum-bin
060615 15:27:20 [Note] Starting crash recovery...
060615 15:27:20 [Note] Crash recovery finished.
060615 15:27:20 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.0.21-standard-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Edition - Standard (GPL)
060615 15:28:10InnoDB: Assertion failure in thread 1350576 in file row0sel.c line 2081
InnoDB: Failing assertion: dict_col_get_type(field->col)->mtype == dfield_get_type(dfield)->mtype
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/mysql/en/Forcing_recovery.html
InnoDB: about forcing recovery.
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.

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=1
max_connections=100
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 80383 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x8a9c8e8
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...
Cannot determine thread, fp=0x14492c, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x815c750
0xb76888
0x3
0x81f49d8
0x81f50e0
0x81f536f
0x81f90f5
0x81ae4a4
0x81b57de
0x81bb6ef
0x81bbdbb
0x8172489
0x8178afb
0x81792b7
0x817a098
0x817a7c0
0xb70371
0xadb9be
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/Using_stack_trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8ab7e68 = SELECT option_value FROM options WHERE blog = '483' AND option_name = 'siteurl' LIMIT 1
thd->thread_id=2
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:
the result of that query in the error message is 0 rows... so that's one clue. of course, mysql encounters many such requests so there must be something else happening.

please feel free to contact me if you want me to do anything to give you more data.

jjb@ibiblio.org
[15 Jun 2006 20:24] Valeriy Kravchuk
Thank you for a problem report. Please, try to resolve that stack tarce as described in http://dev.mysql.com/doc/refman/5.0/en/using-stack-trace.html.

Please, send

EXPLAIN SELECT option_value FROM options WHERE blog = '435'
AND option_name = 'siteurl' LIMIT 1\G

results, SHOW CREATE TABLE and SHOW TABLE STATUS results for that options table.
[15 Jun 2006 21:19] John Bachir
mysql> EXPLAIN SELECT option_value FROM options WHERE blog = '435'
    -> AND option_name = 'siteurl' LIMIT 1;
ERROR 2013 (HY000): Lost connection to MySQL server during query

-----------

SHOW CREATE TABLE options;
.......
CREATE TABLE `options` (
  `option_id` int(10) unsigned NOT NULL auto_increment,
  `blog_id` int(10) unsigned NOT NULL default '0',
  `option_name` varchar(64) NOT NULL default '',
  `option_can_override` enum('Y','N') NOT NULL default 'Y',
  `option_type` int(11) NOT NULL default '1',
  `option_value` longtext NOT NULL,
  `option_width` int(11) NOT NULL default '20',
  `option_height` int(11) NOT NULL default '8',
  `option_description` tinytext NOT NULL,
  `option_admin_level` int(11) NOT NULL default '1',
  `autoload` enum('yes','no') NOT NULL default 'yes',
  `option_domain` enum('system','blog') NOT NULL default 'blog',
  `blog` mediumint(8) unsigned NOT NULL default '0',
  PRIMARY KEY  (`option_id`,`blog_id`,`option_name`),
  UNIQUE KEY `blogdomainindex` (`blog`,`autoload`,`option_name`),
  UNIQUE KEY `systemdomainindex` (`option_domain`,`option_name`,`blog`),
  KEY `option_name` (`option_name`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

--------------

SHOW TABLE STATUS;
.....
| Name           | Engine | Version | Row_format | Rows   | Avg_row_length | Data_length | Max_data_length | Index_length | Data_free | Auto_increment | Create_time         | Update_time | Check_time | Collation         | Checksum | Create_options | Comment              
+----------------+--------+---------+------------+--------+----------------+-------------+-----------------+--------------+-----------+----------------+---------------------+-------------+------------+-------------------+----------+----------------+----------------------
| options        | InnoDB |      10 | Redundant  | 152983 |            476 |    72957952 |               0 |     14106624 |         0 |          52754 | 2006-06-14 19:13:25 | NULL        | NULL       | latin1_swedish_ci |     NULL | NULL           | InnoDB free: 22528 kB
[15 Jun 2006 21:34] John Bachir
$ resolve_stack_dump -s /usr/lib/mysql/mysqld.sym -n /tmp/mysqld.stack
0x815c750 handle_segfault + 610
0xb76888 (?)
0x3 (?)
0x81f49d8 _Z16check_quick_keysP13st_qsel_paramjP7SEL_ARGPcjS3_j + 776
0x81f50e0 _Z18check_quick_selectP13st_qsel_paramjP7SEL_ARG + 188
0x81f536f _Z20get_key_scans_paramsP13st_qsel_paramP8SEL_TREEbd + 421
0x81f90f5 _ZN10SQL_SELECT17test_quick_selectEP3THD6BitmapILj64EEyyb + 4207
0x81ae4a4 _Z20make_join_statisticsP4JOINP13st_table_listP4ItemP16st_dynamic_array + 5666
0x81b57de _ZN4JOIN8optimizeEv + 1070
0x81bb6ef _Z12mysql_selectP3THDPPP4ItemP13st_table_listjR4ListIS1_ES2_jP8st_orderSB_S2_SB_mP13select_resultP18st_select_lex_unitP13st_sel + 131
0x81bbdbb _Z13handle_selectP3THDP6st_lexP13select_resultm + 277
0x8172489 _Z21mysql_execute_commandP3THD + 4547
0x8178afb _Z11mysql_parseP3THDPcj + 305
0x81792b7 _Z16dispatch_command19enum_server_commandP3THDPcj + 1717
0x817a098 _Z10do_commandP3THD + 148
0x817a7c0 handle_one_connection + 1600
0xb70371 (?)
0xadb9be (?)
[16 Jun 2006 0:06] Heikki Tuuri
row0sel.c in 5.0.xx:

/********************************************************************
Converts a key value stored in MySQL format to an Innobase dtuple. The last
field of the key value may be just a prefix of a fixed length field: hence
the parameter key_len. But currently we do not allow search keys where the
last field is only a prefix of the full key field len and print a warning if
such appears. A counterpart of this function is
ha_innobase::store_key_val_for_row() in ha_innodb.cc. */

void
row_sel_convert_mysql_key_to_innobase(
/*==================================*/
        dtuple_t*       tuple,          /* in: tuple where to build;
                                        NOTE: we assume that the type info
                                        in the tuple is already according
                                        to index! */
        byte*           buf,            /* in: buffer to use in field
                                        conversions */
        ulint           buf_len,        /* in: buffer length */
        dict_index_t*   index,          /* in: index of the key value */
        byte*           key_ptr,        /* in: MySQL key value */
        ulint           key_len,        /* in: MySQL key value length */
        trx_t*          trx)            /* in: transaction */
{
        byte*           original_buf    = buf;
        byte*           original_key_ptr = key_ptr;
        dict_field_t*   field;
        dfield_t*       dfield;
        ulint           data_offset;
        ulint           data_len;
        ulint           data_field_len;
        ibool           is_null;
        byte*           key_end;
        ulint           n_fields = 0;
        ulint           type;

        /* For documentation of the key value storage format in MySQL, see
        ha_innobase::store_key_val_for_row() in ha_innodb.cc. */

        key_end = key_ptr + key_len;

        /* Permit us to access any field in the tuple (ULINT_MAX): */

        dtuple_set_n_fields(tuple, ULINT_MAX);

        dfield = dtuple_get_nth_field(tuple, 0);
        field = dict_index_get_nth_field(index, 0);

        if (dfield_get_type(dfield)->mtype == DATA_SYS) {
                /* A special case: we are looking for a position in the
                generated clustered index which InnoDB automatically added
                to a table with no primary key: the first and the only
                ordering column is ROW_ID which InnoDB stored to the key_ptr
                buffer. */

                ut_a(key_len == DATA_ROW_ID_LEN);

                dfield_set_data(dfield, key_ptr, DATA_ROW_ID_LEN);

                dtuple_set_n_fields(tuple, 1);

                return;
        }

        while (key_ptr < key_end) {

                ut_a(dict_col_get_type(field->col)->mtype
                     == dfield_get_type(dfield)->mtype);

                data_offset = 0;
                is_null = FALSE;

It is the assertion above that fails.
[16 Jun 2006 0:10] Heikki Tuuri
John,

is the table big?

Can you send a dump of it to us?

I am not able to repeat the crash on 5.0.19 with an empty table.

Regards,

Heikki
[16 Jun 2006 0:20] Heikki Tuuri
John,

ok, I see the table is about 75 MB. Valerie can give you an ftp address where you can upload the table dump.

The optimizer is probably testing the keys on blog and option_name, and the key length may be wrong.

What is the history of this table? Under which MySQL version did you create it?

Regards,

Heikki
[16 Jun 2006 1:49] John Bachir
The table was created under mysql 4.0.x, I'll try to find out the specific version if that will be helpful, let me know.

The system/table was upgraded to 5.0.21 and everything was working fine for weeks. Recently we updated the application, for which this command was run:

DELETE FROM options WHERE option_name = 'siteurl' AND option_domain = 'blog';

I THINK that's when the problems started. After that command was run, an update script was run which executed many different sql commands. If you don't think the above command is the culprit, let me know where to start hunting and I can look into it.
[16 Jun 2006 1:51] John Bachir
And let me know about that ftp site, I'll gladly upload a dump. Also maybe tell me exactly which command to use for the dump, just to make sure we are on the same page.
[16 Jun 2006 12:36] Valeriy Kravchuk
Upload your dump to ftp://ftp.mysql.com/pub/mysql/upload. Use 20486 in a file name, please. Reopen this report when you'll do it.
[18 Jun 2006 17:00] John Bachir
I have uploaded the file. It is called:

20486_18062006_jjb_lyceum_ibiblio_COMPLETE.sql.gz

the md5sum is:

37b2d376d28c0f199252cd7bb1e4521e

I think the first time I uploaded it, the transfer was interrupted. Please discard the file that does not have "complete" in the name.
[18 Jun 2006 19:01] John Bachir
New info: we've done some investigating, and it seems that /var was at 100% at the time of the application upgrade, and before and after it.

So the issue could be stemming from MySQL, InnoDB, Apache or PHP not being able to write tmp files or logs at some point. Although it seems to me this shouldn't result in a corrupt table.
[18 Jun 2006 19:14] John Bachir
More info: I just ran optimize on that table, and that seems to have fixed it. (haven't done extensive testing yet, but the data wasn't available before, and now it is).
[19 Jun 2006 5:59] Valeriy Kravchuk
> Although it seems to me this shouldn't result in a corrupt table.

If indexes were rebuilt with not enough temporary space they can be corrupted. Your OPTIMIZE rebuilt table again, with enough temporary space (http://dev.mysql.com/doc/refman/5.0/en/optimize-table.html):

"For InnoDB tables, OPTIMIZE TABLE is mapped to ALTER TABLE, which rebuilds the table to update index statistics and free unused space in the clustered index."

Please, reopen this bug report if you'll see similar crash later.
[19 Jun 2006 7:04] Heikki Tuuri
John, Valerie,

the problem may have been that some data type in the table had a different format in 4.0.x than in 5.0. That is why a rebuild of the table fixed the problem. 

A suspect is this:

option_domain` enum('system','blog') NOT NULL default 'blog',

I do not recall any incompatible change in enums 4.0 -> 5.0, but there might be one.

Regards,

Heikki
[19 Jun 2006 7:57] John Bachir
Heikki, Valeriy-

I suspect that the problem was from a full /var and not from the software upgrade, because the application was running fine for several weeks after the move to mysql 5. However, I suppose it might have taken just the right command to irritate the particular version incompatibility, which wasn't executed until I was upgrading the application.

If you do discover what the particular problem might have been, I would be very interested to hear about it. I do find it peculiar that this data incompatibility resulted in the daemon terminating.

Thank you for the attention you have given this bug, it makes me even more glad that I use open source software, and MySQL, and InnoDB.

-John
[19 Jun 2006 14:50] Valeriy Kravchuk
Please, send the SHOW CREATE TABLE results for the table you OPTIMIZEd.
[19 Jun 2006 14:57] John Bachir
CREATE TABLE `options` (
  `option_id` int(10) unsigned NOT NULL auto_increment,
  `blog_id` int(10) unsigned NOT NULL default '0',
  `option_name` varchar(64) NOT NULL default '',
  `option_can_override` enum('Y','N') NOT NULL default 'Y',
  `option_type` int(11) NOT NULL default '1',
  `option_value` longtext NOT NULL,
  `option_width` int(11) NOT NULL default '20',
  `option_height` int(11) NOT NULL default '8',
  `option_description` tinytext NOT NULL,
  `option_admin_level` int(11) NOT NULL default '1',
  `autoload` enum('yes','no') NOT NULL default 'yes',
  `option_domain` enum('system','blog') NOT NULL default 'blog',
  `blog` mediumint(8) unsigned NOT NULL default '0',
  PRIMARY KEY  (`option_id`,`blog_id`,`option_name`),
  UNIQUE KEY `blogdomainindex` (`blog`,`autoload`,`option_name`),
  UNIQUE KEY `systemdomainindex` (`option_domain`,`option_name`,`blog`),
  KEY `option_name` (`option_name`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
[17 Jul 2006 16:53] Valeriy Kravchuk
As your (InnoDB) table has enum, varchar and text columns, the only correct way to upgrade from 4.x.y to 5.x.y is with dump and restore, as described in the manual (or with rebuild of table in 5.0.x, immediately after upgrade).
[17 Jul 2006 17:04] John Bachir
Okay, sorry for all the fuss then. Could you show me where in the documentation is this is covered?

Thanks for all the attention to this.

John
[18 Jul 2006 12:16] Valeriy Kravchuk
http://dev.mysql.com/doc/refman/5.0/en/upgrading-from-4-1.html:

"Note: It is good practice to back up your data before installing any new version of software. Although MySQL works very hard to ensure a high level of quality, you should protect your data by making a backup. MySQL generally recommends that you dump and reload your tables from any previous version to upgrade to 5.0."