Bug #37936 ASSERT_COLUMN_MARKED_FOR_WRITE in Field_datetime::store , Field_varstring::store
Submitted: 7 Jul 2008 16:07 Modified: 29 Jan 2009 19:57
Reporter: Philip Stoev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S1 (Critical)
Version:5.1.28-bzr, 6.0, 6.0.7-bzr OS:Any
Assigned to: Georgi Kodinov CPU Architecture:Any
Tags: regression

[7 Jul 2008 16:07] Philip Stoev
Description:
When executing a query containing date expressions, mysqld crashed as follows:

#9  0x081f72dd in Field_datetime::store (this=0xa035828, from=0xa080f50 "2000-6-25", len=9, cs=0x877fc40) at field.cc:5831
#10 0x08171166 in Item::save_str_value_in_field (this=0xa080f60, field=0xe4d, result=0xa080f6c) at item.cc:371
#11 0x0817119c in Item_string::save_in_field (this=0xa080f60, field=0xa035828, no_conversions=true) at item.cc:4896
#12 0x0816c308 in Item::save_in_field_no_warnings (this=0xa080f60, field=0xa035828, no_conversions=<value optimized out>) at item.cc:972
#13 0x082ebda1 in get_mm_leaf (param=0xa891f338, conf_func=0xa080fe0, field=0xa035828, key_part=0xa08ac10, type=Item_func::LE_FUNC, value=0xa080f60)
    at opt_range.cc:5679
#14 0x082ec39d in get_mm_parts (param=0xa891f338, cond_func=0xa080fe0, field=0xa035828, type=Item_func::LE_FUNC, value=0xa080f60, cmp_type=INT_RESULT)
    at opt_range.cc:5488
#15 0x082f8b7c in get_func_mm_tree (param=0xa891f338, cond_func=0xa080fe0, field=0xa035828, value=0xa080f60, cmp_type=INT_RESULT, inv=false)
    at opt_range.cc:5167
#16 0x082f8d18 in get_full_func_mm_tree (param=0xa891f338, cond_func=0xa080fe0, field_item=0xa080eb8, value=0xa080f60, inv=<value optimized out>)
    at opt_range.cc:5266
#17 0x082f9513 in get_mm_tree (param=0xa891f338, cond=0xa080fe0) at opt_range.cc:5456
#18 0x082f8e2f in get_mm_tree (param=0xa891f338, cond=<value optimized out>) at opt_range.cc:5308
#19 0x082f9c58 in SQL_SELECT::test_quick_select (this=0xa081f70, thd=0xa025f40, keys_to_use={map = 16}, prev_tables=0, limit=4294967295,
    force_quick_range=false, ordered_output=false) at opt_range.cc:2311
#20 0x0828693f in make_join_statistics (join=0xa071db8, tables=0x0, conds=0xa081bb8, keyuse_array=0xa073094) at sql_select.cc:3758
#21 0x08287eb5 in JOIN::optimize (this=0x0) at sql_select.cc:1549
#22 0x0828e1a8 in mysql_select (thd=0xa025f40, rref_pointer_array=0xa027424, tables=0xa04b3e8, wild_num=0, fields=@0xa0273b4, conds=0xa0810d0, og_num=1,
    order=0x0, group=0xa0814b0, having=0x0, proc_param=0x0, select_options=2147764736, result=0xa081548, unit=0xa027090, select_lex=0xa027320)
    at sql_select.cc:2987
#23 0x082910dc in handle_select (thd=0xa025f40, lex=0xa027034, result=0xa081548, setup_tables_done_option=0) at sql_select.cc:302
#24 0x082201e2 in execute_sqlcom_select (thd=0xa025f40, all_tables=0xa04b3e8) at sql_parse.cc:4847
#25 0x08220f61 in mysql_execute_command (thd=0xa025f40) at sql_parse.cc:2015
#26 0x0822a02e in mysql_parse (thd=0xa025f40,
    inBuf=0xa04ae08 "SELECT  COUNT(DISTINCT OUTR . `varchar_nokey` ) AS X FROM B AS OUTR2 LEFT JOIN C AS OUTR ON ( OUTR2 . `varchar_nokey` = OUTR . `varchar_key` ) WHERE OUTR . `varchar_key` IN ( SELECT  INNR . `datetime_"..., length=451, found_semicolon=0xa8923314) at sql_parse.cc:5811
#27 0x0822a921 in dispatch_command (command=COM_QUERY, thd=0xa025f40,
    packet=0xa027959 "SELECT  COUNT(DISTINCT OUTR . `varchar_nokey` ) AS X FROM B AS OUTR2 LEFT JOIN C AS OUTR ON ( OUTR2 . `varchar_nokey` = OUTR . `varchar_key` ) WHERE OUTR . `varchar_key` IN ( SELECT  INNR . `datetime_"..., packet_length=453) at sql_parse.cc:1051
#28 0x0822ba49 in do_command (thd=0xa025f40) at sql_parse.cc:724
#29 0x0821bef0 in handle_one_connection (arg=0xa025f40) at sql_connect.cc:1153
#30 0x0057d32f in start_thread () from /lib/libpthread.so.0
#31 0x0049a27e in clone () from /lib/libc.so.6

The assertion that is being hit is ASSERT_COLUMN_MARKED_FOR_WRITE, at the entry of Field_datetime::store. The assertion is:

(!table || (!table->write_set || bitmap_is_set(table->write_set, field_index))

(gdb) print table
$1 = (st_table *) 0xa035140
(gdb) print table->write_set
$2 = (MY_BITMAP *) 0xa0351e0
(gdb) print field_index
$3 = 7
(gdb) print * table->write_set
$4 = {bitmap = 0xa0313b0, n_bits = 11, last_word_mask = 4294965248, last_word_ptr = 0xa0359cc, mutex = 0x0}

The query in question is:

SELECT  COUNT(DISTINCT OUTR . `varchar_nokey` ) AS X FROM B AS OUTR2 LEFT JOIN C AS OUTR ON ( OUTR2 . `varchar_nokey` = OUTR . `varchar_key` ) WHERE OUTR . `varchar_key` IN ( SELECT  INNR . `datetime_key` AS Y FROM BB AS INNR2 LEFT JOIN AA AS INNR ON ( INNR2 . `int_nokey` = INNR . `pk` ) WHERE INNR . `varchar_key` < 'w'  HAVING X = '16:36:21' ) AND OUTR . `datetime_key` <= '2000-6-25' AND OUTR . `varchar_nokey` >= 'hkq' GROUP BY OUTR . `int_nokey`

How to repeat:
A simplifed test case will be uploaded shortly.
[14 Jul 2008 17:35] Philip Stoev
Grammar file for bug 37936

Attachment: bug37936.yy (application/octet-stream, text), 4.85 KiB.

[14 Jul 2008 17:40] Philip Stoev
To reproduce this bug, please clone the mysql-test-extra-6.0 tree and execute:

$ cd mysql-test-extra-6.0/mysql-test/gentest
$ ./runall.pl --basedir=/path/to/mysql-6.0 --grammar=/location/of/bug37936.yy --threads=1

This should crash shortly with the same assertion in Field_varstring::store.
[14 Jul 2008 17:44] Philip Stoev
Unsimplified non-concurrent test case for bug 37936

Attachment: bug37936.test (application/octet-stream, text), 19.31 KiB.

[19 Jul 2008 13:34] Valeriy Kravchuk
I was able to repeat a crash with the test case provided on recent 6.0.7-alpha-debug. 

openxs@suse:/home2/openxs/dbs/6.0> bin/mysql -uroot test < /home/openxs/bug37936.test
X
0
X
0000-00-00
X
0000-00-00
X
2004-10-27
X
1
16
X
1
8
12
19
ERROR 2013 (HY000) at line 158: Lost connection to MySQL server during query
openxs@suse:/home2/openxs/dbs/6.0> 080703 16:57:45 mysqld_safe Number of processes running now: 0
080703 16:57:45 mysqld_safe mysqld restarted

No meaningfull stack trace in the error log:

thd: 0x9b13e58
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 = 0x47ebf430 thread_stack 0x30000
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x9b6b318 = SELECT  MIN( OUTR . `pk` ) AS X FROM C AS OUTR WHERE OUTR . `pk` IN ( SELECT  INNR . `int_key` AS Y FROM B AS INNR WHERE INNR . `int_key` <> INNR . `int_key` AND OUTR . `date_nokey` < '2003-12-25'  ) OR NOT ( OUTR . `date_key` < '2009-10-8' OR NOT OUTR . `varchar_nokey` <= 'd' ) GROUP BY OUTR . `pk`  ORDER BY OUTR . `int_nokey` , OUTR . `pk` LIMIT 2
thd->thread_id=2
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
080703 16:57:45 mysqld_safe Number of processes running now: 0
080703 16:57:45 mysqld_safe mysqld restarted
080703 16:57:45  InnoDB: Started; log sequence number 0 46409
080703 16:57:46 [Note] Event Scheduler: Loaded 0 events
080703 16:57:46 [Note] /home2/openxs/dbs/6.0/libexec/mysqld: ready for connections.
Version: '6.0.7-alpha-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
[19 Jul 2008 13:39] Valeriy Kravchuk
Recent 5.1.28 debug binaries are also affected.
[19 Jul 2008 13:41] Valeriy Kravchuk
Recent 5.0 debug binaries are NOT affected, so this is a regression:

openxs@suse:/home2/openxs/dbs/5.0> bin/mysql -uroot test < /home/openxs/bug37936.test
X
0
X
0000-00-00
X
0000-00-00
X
2004-10-27
X
1
16
X
1
8
12
19
X
NULL
X
0
X
0000-00-00
X
NULL
X
NULL
X
5
X
NULL
X
0
0
4
X
0
X
1
4
8
9
12
17
19
[5 Nov 2008 14:55] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57900

2690 Georgi Kodinov	2008-11-05
      Bug #37936: ASSERT_COLUMN_MARKED_FOR_WRITE in Field_datetime::store , Field_varstring::store
      
      The code that temporary saved the bitmaps of the read set and the write set so that it 
      can set it to all columns for debug purposes was not expecting that the table->read_set and
      table->write_set can be the same. And was always saving both in sequence.
      As a result the original value was never restored.
      
      Fixed by saving & restoring the original value only once if the two sets are the same.
[6 Nov 2008 13:57] Ingo Strüwing
See comments by email.
[7 Nov 2008 10:11] Georgi Kodinov
I'm not able to get the stack trace described here. All I'm getting is the stack trace from Bug #37937.
Can you please try to get the same callstack with the latest 5.1 debug (I assume it's a debug version only) ?
[7 Nov 2008 10:47] Georgi Kodinov
Bug #37937 marked as a duplicate of this bug
[7 Nov 2008 10:48] Georgi Kodinov
Tried the original test case (using RQG) against a patched server :
=======================================================

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

Servers started, exiting
Autoreleasing /tmp/mysql-test-ports:200
# 12:47:15 Starting 
# 12:47:15  gentest.pl \ 
# 12:47:15  --gendata= \ 
# 12:47:15  --threads=1 \ 
# 12:47:15  --queries=1000 \ 
# 12:47:15  --duration=3600 \ 
# 12:47:15  --dsn1=dbi:mysql:host=127.0.0.1:port=19306:user=root:database=test \ 
# 12:47:15  --grammar=bug37936.yy
# 12:47:15 Starting 
# 12:47:15 # gendata-old.pl \ 
# 12:47:15 # --dsn=dbi:mysql:host=127.0.0.1:port=19306:user=root:database=test
# 12:47:15 Creating table A, size 0 rows, engine  .
# 12:47:15 Creating table B, size 2 rows, engine  .
# 12:47:15 Creating table C, size 20 rows, engine  .
# 12:47:15 Creating table D, size 100 rows, engine  .
# 12:47:15 Creating table E, size 1000 rows, engine  .
# 12:47:16 Creating table AA, size 0 rows, engine  .
# 12:47:16 Creating table BB, size 2 rows, engine  .
# 12:47:16 Creating table CC, size 20 rows, engine  .
# 12:47:16 Creating table DD, size 100 rows, engine  .
# 12:47:16 Creating table AAA, size 0 rows, engine  .
# 12:47:16 Creating table BBB, size 1 rows, engine  .
# 12:47:16 Creating table CCC, size 20 rows, engine  .
# 12:47:16 Reporters: ErrorLog, Backtrace
# 12:47:16 Validators: FalconErrors, ErrorMessageCorruption
# 12:47:16 Starting 1 processes, 1000 queries each, duration 3600 seconds.
# 12:47:18 Started periodic reporting process...
# 12:47:20 Child process completed successfully.
# 12:47:25 Killing periodic reporting process with pid 10690...
# 12:47:30 Test completed successfully.
[7 Nov 2008 11:07] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/58165

2690 Georgi Kodinov	2008-11-07
      Bug #37936: ASSERT_COLUMN_MARKED_FOR_WRITE in Field_datetime::store ,
      Field_varstring::store
      
      The code that temporary saved the bitmaps of the read set and the write set so that
      it can set it to all columns for debug purposes was not expecting that the
      table->read_set and table->write_set can be the same. And was always saving both in 
      sequence.
      As a result the original value was never restored.
      Fixed by saving & restoring the original value only once if the two sets are the
      same (in a special set of functions).
[8 Dec 2008 19:32] Michael Widenius
Another way to define the new functions that does the same thing but
may be a bit easier to understand is:

static inline void dbug_tmp_use_all_columns(TABLE *table,
                                            my_bitmap_map **save,
                                            MY_BITMAP *read_set,
                                            MY_BITMAP *write_set)
{
#ifndef DBUG_OFF
  save[0]= read_set->bitmap;
  save[1]= write_set->bitmap;
  (void) tmp_use_all_columns(table, read_set);
  (void) tmp_use_all_columns(table, write_set);
#endif
}

static inline void dbug_tmp_restore_column_maps(MY_BITMAP *read_set,
                                                MY_BITMAP *write_set,
                                                my_bitmap_map **old)
{
#ifndef DBUG_OFF
  tmp_restore_column_map(read_set, old[0]);
  tmp_restore_column_map(write_set, old[1]);
#endif

Feel free to use the above logic or just push the given code
[9 Dec 2008 17:46] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/61116

2690 Georgi Kodinov	2008-12-09
      Bug #37936: ASSERT_COLUMN_MARKED_FOR_WRITE in Field_datetime::store ,
      Field_varstring::store
            
      The code that temporary saved the bitmaps of the read set and the write set so that
      it can set it to all columns for debug purposes was not expecting that the
      table->read_set and table->write_set can be the same. And was always saving both in 
      sequence.
      As a result the original value was never restored.
      Fixed by saving & restoring the original value only once if the two sets are the
      same (in a special set of functions).
[15 Jan 2009 6:35] Bugs System
Pushed into 5.1.31 (revid:joro@sun.com-20090115053147-tx1oapthnzgvs1ro) (version source revid:azundris@mysql.com-20081230114838-cn52tu180wcrvh0h) (merge vers: 5.1.31) (pib:6)
[19 Jan 2009 11:25] Bugs System
Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090115073240-1wanl85vlvw2she1) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)
[19 Jan 2009 13:03] Bugs System
Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)
[19 Jan 2009 16:09] Bugs System
Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)
[20 Jan 2009 18:56] Bugs System
Pushed into 6.0.10-alpha (revid:joro@sun.com-20090119171328-2hemf2ndc1dxl0et) (version source revid:azundris@mysql.com-20081230114916-c290n83z25wkt6e4) (merge vers: 6.0.9-alpha) (pib:6)
[29 Jan 2009 19:57] Paul DuBois
Noted in 5.1.31, 6.0.10 changelogs.

An error in a debugging check caused crashes in debug servers.