Bug #79679 Failure of innodb.innodb_ctype_ldml and main.ctype_ldml
Submitted: 16 Dec 2015 18:33 Modified: 18 Dec 2015 3:22
Reporter: Justin Tolmer Email Updates:
Status: Open Impact on me:
None 
Category:Tests Severity:S7 (Test Cases)
Version:5.6.27 OS:CentOS (6)
Assigned to: CPU Architecture:Any

[16 Dec 2015 18:33] Justin Tolmer
Description:
In our environment where we link against jemalloc, these 2 tests fail 100% of the time:

innodb.innodb_ctype_ldml                 w10 [ fail ]
        Test ended at 2015-12-15 15:51:57

CURRENT_TEST: innodb.innodb_ctype_ldml
mysqltest: At line 157: query 'select group_concat(c1 order by hex(c1) SEPARATOR '') from t1 group by c1' failed: 2013: Lost connection to MySQL server during query

Looking at mysqld.1.err:

mysqld: ../mysql/sql/sql_string.cc:437: bool String::append(const String&): Assertion `!s.uses_buffer_owned_by(this)' failed.
23:51:57 UTC - mysqld got signal 6 ;

I do not reproduce the failure witout linking to jemalloc.

Debugging shows that the assert is firing in String::append when:

(gdb) info frame
Stack level 0, frame at 0x7ffff7f90040:
 rip = 0x903d51 in String::append (/home/jtolmer/mysql/56/sql/sql_string.cc:436); saved rip = 0x79f93e
 called by frame at 0x7ffff7f90120
 source language c++.
 Arglist at 0x7ffff7f90030, args: this=0x7fffe2862558, s=...
 Locals at 0x7ffff7f90030, Previous frame's sp is 0x7ffff7f90040
 Saved registers:
  rbx at 0x7ffff7f90028, rbp at 0x7ffff7f90030, rip at 0x7ffff7f90038
(gdb) p	*this
$1 = {Ptr = 0x7fffe282d030 "", str_length = 8, Alloced_length = 16, alloced = true, str_charset = 0x7ffff497cf10}
(gdb) p	s
$2 = (const String &) @0x7fffe28151f0: {Ptr = 0x7fffe282d030 "", str_length = 0, Alloced_length = 0, alloced = false, str_charset = 0x7ffff497cf10}

How to repeat:
Build with -DCMAKE_BUILD_TYPE=Debug and link with jemalloc. Then run the tests.

Suggested fix:
diff --git a/client/sql_string.h b/client/sql_string.h
index 866f6bc..61d4586 100644
--- a/client/sql_string.h
+++ b/client/sql_string.h
@@ -366,7 +366,9 @@ public:
 
   inline bool uses_buffer_owned_by(const String *s) const
   {
-    return (s->alloced && Ptr >= s->Ptr && Ptr < s->Ptr + s->str_length);
+    return (alloced && s->alloced &&
+            Ptr >= s->Ptr &&
+            Ptr < s->Ptr + s->str_length);
   }
 };
[17 Dec 2015 9:17] MySQL Verification Team
Hi Justin,

Thank you for the report.
I'm not able to reproduce this issue on OL6 with 5.6.27/5.6.28(jemalloc-4.0.3, cmake version 2.8.12.2). How you link jemalloc with mtr, and which version of jemalloc you are using? Please let us know.

--
 
[ushastry@cluster-repo mysql-5.6.27]# mkdir bld_debug
[ushastry@cluster-repo mysql-5.6.27]# cd bld_debug
[ushastry@cluster-repo mysql-5.6.27]# cmake .. -DCMAKE_BUILD_TYPE=Debug
.
[ushastry@cluster-repo mysql-5.6.27]# make -j12
.
.
[ushastry@cluster-repo mysql-5.6.27]# cd mysql-test/
[ushastry@cluster-repo mysql-test]$ ./mtr --mysqld-env="LD_PRELOAD=/usr/local/lib/libjemalloc.so" innodb.innodb_ctype_ldml main.ctype_ldml
Logging: /data/ushastry/bugs/mysql-5.6.27/mysql-test/mysql-test-run.pl  --mysqld-env=LD_PRELOAD=/usr/local/lib/libjemalloc.so innodb.innodb_ctype_ldml main.ctype_ldml
2015-12-19 21:47:36 0 [Note] /data/ushastry/bugs/mysql-5.6.27/bld_debug/sql/mysqld (mysqld 5.6.27-debug) starting as process 3887 ...
2015-12-19 21:47:36 3887 [Note] Plugin 'FEDERATED' is disabled.
2015-12-19 21:47:36 3887 [Note] Binlog end
2015-12-19 21:47:36 3887 [Note] Shutting down plugin 'CSV'
2015-12-19 21:47:36 3887 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.27
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/data/ushastry/bugs/mysql-5.6.27/bld_debug/mysql-test/var'...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
innodb.innodb_ctype_ldml                 [ pass ]   3026
main.ctype_ldml                          [ pass ]    204
--------------------------------------------------------------------------
The servers were restarted 1 times
Spent 3.230 of 13 seconds executing testcases

Completed: All 2 tests were successful.

Thanks,
Umesh
[17 Dec 2015 18:27] Justin Tolmer
We're using jemalloc 4.0.0. But it's an internal version that may not exactly match what you have access to.

We are not using LD_PRELOAD. We're using -I and -L to link to jemalloc at compile time rather than runtime.

I suspected that you would have difficulty reproducing in your environment. That is why I included the gdb output so that you can see the values in the fields of the objects. The current code is comparing the value of Ptr when alloced is false, which results in an incorrect value being returned.
[18 Dec 2015 3:22] Justin Tolmer
My previous suggested fix is bad. It creates other problems and test failures. I've spent more time debugging. Here's what's happening in our environment. Note that we're building with both -DHAVE_purify and -DEXTRA_DEBUG.

* Failure happens on this line of the test https://github.com/mysql/mysql-server/blob/mysql-5.6.27/mysql-test/t/ctype_ldml.test#L165
* In Item_func_group_concat::fix_fields, separator->needs_conversion returns true for a 0 length string, resulting in a call to thd->stmt_arena->alloc(0) at https://github.com/mysql/mysql-server/blob/mysql-5.6.27/sql/item_sum.cc#L3467
* alloc_root adds 16 bytes to the length: https://github.com/mysql/mysql-server/blob/mysql-5.6.27/mysys/my_alloc.c#L172 and so passes 16 as the size to malloc
* alloc_root then returns my_mallloc + 16, which points to an unallocated memory location
* later in the 4th call to dump_leaf_key, String::append is called at https://github.com/mysql/mysql-server/blob/mysql-5.6.27/sql/item_sum.cc#L3119
* That append call results in a call to realloc, which receives back the memory block immediate after the one that was created in Item_func_group_concat::fix_fields
* Next call to dump_leaf_key then hits an assertion failure on append at https://github.com/mysql/mysql-server/blob/mysql-5.6.27/sql/item_sum.cc#L3089