mysqld some times crashes at the end of Random Query Generator test #111
Comments
|
Could you paste whole stack trace? |
|
Trace #1 myrocks@rocksdb: 2015-11-25 11:25:48 2528 [Note] Plugin 'FEDERATED' is disabled. Level Files Size(MB) Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) Stall(cnt) KeyIn KeyDropL0 4/0 1.68 1.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 2.0 1 4 0.208 0 0 0 Trace #2, The top portion is from successful tests prior to the failed test 2015-11-25 11:53:27 2598 [Note] RocksDB: Begin filtering dropped index (0,456) Level Files Size(MB) Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) Stall(cnt) KeyIn KeyDropL0 4/0 2.80 1.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 3.2 8 45 0.185 0 0 0 |
|
@dleeyh It's error log, but what I wanted to look into was process stack trace (at assertion failure). Wasn't it printed in the error log? If not, could you enable core-file in my.cnf then get stack trace from core files? |
|
@dleeyh I couldn't reproduce. Could you paste my.cnf options? |
|
Here is my .cnf file: [mysqld] How do you enable mysqld logging? I tried few different methods according to online resources and still not getting log files. |
|
Thanks! About saving core files, add "core-file" in my.cnf. After crash, core file should be written at /var/tmp/cores. Then run "gdb /path/to/mysqld /path/to/core_file" then run "bt". -- https://dev.mysql.com/doc/refman/5.6/en/using-gdb-on-mysqld.html |
|
Also, if you have not updated MyRocks, would you please git pull then rebuild (and disable partition to prevent crash -- until Sergey commits his diff)? |
|
Got the latest MyRocks today. The first 4 tests were successful. The 5th test failed due to the same Assertion. |
|
myrocks@rocksdb:/home/qa/myr/bugs/111$ gdb /home/myrocks/builds/nightly/mysql-5.6/sql/mysqld core |
|
Are you able to reproduce the issue with information that I provided? Thanks |
|
No I couldn't reproduce. I'm not sure if it is caused by MyRocks or not. Could you also test with InnoDB then see if it reproduces? |
|
Ran the same test 7 times on InnoDB. All completed without crashing. |
|
I haven't been able to reproduce the problem with the gentest.pl file that comes with MySQL. I've downloaded the one from http://bazaar.launchpad.net/~elenst/randgen/mariadb-patches/revision/1050 but have trouble with the generator on my system. Which gentest.pl are you using for the test? Based the stack trace of the error, it looks like the Update statement is trying to execute set_ok_status() after it succeeded, but that's failing possibly because some prior status was already set. Looking through the myrocks code, I don't see where we maybe setting the status directly. Since it looks like there is 1 warning in the return, is it possible the status could have been set by whatever triggered the warning? |
|
I was able to reproduce, and generated a core file. |
|
commit f03213b I made a release build using the above source. I ran the following test 5 times for a total of 500 executions. All tests passed. In a shell script, repeat this command 100 times. NOTE: I used 1000 queries instead of 10000 in the original bug description. For the save test, when I increase the threads parameter value to 20 or 50, test failed somewhere within the 100 test executions. Here is the back trace of the core dump file. myrocks@rocksdb:/tmp$ gdb /home/myrocks/builds/mytest/mysql-5.6/sql/mysqld core |
|
This latest stack trace looks to be a different issue. The insert is failing because of an existing key, but unpacking the key triggers a segfault (possibly because the data is corrupted?). Is there a way for us to get access to these cores/source/build for debugging? |
|
I took a look at the core file. It looks like we might not be setting errkey properly when this duplicate key error occurs for the partitioned table. (gdb) f 2 |
|
When I ran master/slave mismatch test (#107), MyRocks slave crashed because of the wrong errkey. This matches Herman's last issue. |
|
The bug is not setting the errkey in the update path. errkey is set when info is called, but the error is printed out before info is called. It should be easy to fix by setting errkey and dupp_errkey when the problem occurs. dupp_errkey is still needed for info to be more precise about which index caused the duplicate key error. I'll post a fix shortly. |
|
(I believe, the assert failure that I am seeing is not related to the errkey problem) Added code to save the stack trace when Diagnostics' area m_status changes to DA_ERROR. Then, repeated the assert failure, it occurred here: and the record shows it happened here: |
|
A deterministic testcase for the assert: |
nodes: Single server, no replication
partition support: disabled
I executed the RQG sample test 5 times. For 2 of them, mysqld crashed at the end of the tests.
RQG test command:
perl gentest.pl --dsn=dbi:mysql:host=localhost:port=3306:user=root:database=test:mysql_socket=/tmp/mysql.sock --gendata=conf/examples/example.zz --grammar=conf/examples/example.yy --threads=10 --queries=10000
Terminal output:
.
.
.
#2015-11-25T11:28:04 [2538] Killing remaining worker process with pid 2553...
#2015-11-25T11:28:04 [2555] Mixer: Server crash or critical failure (STATUS_SERVER_CRASHED) reported at dsn dbi:mysql:host=localhost:port=3306:user=root:database=test:mysql_socket=/tmp/mysql.sock
#2015-11-25T11:28:04 [2538] Killing remaining worker process with pid 2546...
#2015-11-25T11:28:04 [2538] Killing remaining worker process with pid 2555...
#2015-11-25T11:28:04 [2538] Killing remaining worker process with pid 2547...
#2015-11-25T11:28:05 [2538] Killing periodic reporting process with pid 2545...
#2015-11-25T11:28:05 [2545] GenTest: child is being stopped with status STATUS_OK
#2015-11-25T11:28:05 [2538] For pid 2545 reporter status STATUS_OK
#2015-11-25T11:28:05 [2538] Kill GenTest::ErrorFilter(2544)
#2015-11-25T11:28:05 [2538] Server crash reported, initiating post-crash analysis...
#2015-11-25T11:28:05 [2538] datadir is /home/myrocks/builds/mytest/install.db/
#2015-11-25T11:28:05 [2538] binary is
#2015-11-25T11:28:05 [2538] bindir is
#2015-11-25T11:28:05 [2538] WARNING: Core file not found!
: No such file or directory.
"/home/myrocks/mariadb-patches" is not a core dump: Is a directory
backtrace.gdb:19: Error in sourced command file:
No stack.
#2015-11-25T11:28:05 [2538]
: No such file or directory.
"/home/myrocks/mariadb-patches" is not a core dump: Is a directory
#2015-11-25T11:28:05 [2538]
#2015-11-25T11:28:05 [2538] Test completed with failure status STATUS_SERVER_CRASHED (101)
myrocks@rocksdb:~/mariadb-patches$
mysqld output for failed test #1:
rocksdb.number.keys.read COUNT : 794851
rocksdb.number.keys.updated COUNT : 0
rocksdb.bytes.written COUNT : 5927602
rocksdb.bytes.read COUNT : 39486267
rocksdb.num
mysqld: /home/myrocks/builds/mytest/mysql-5.6/sql/sql_error.cc:432: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `! is_set()' failed.
mysqld output for failed test #2:
2015-11-25 12:00:07 2598 [Note] RocksDB: Begin filtering dropped index (0,651)
2015-11-25 12:00:07 2598 [Note] RocksDB: Begin filtering dropped index (0,652)
2015-11-25 12:00:07 2598 [Note] RocksDB: Begin filtering dropped index (0,653)
2015-11-25 12:00:07 2598 [Note] RocksDB: Begin filtering dropped index (0,654)
2015-11-25 12:00:07 2598 [Note] RocksDB: Begin filtering dropped index (0,655)
mysqld: /home/myrocks/builds/mytest/mysql-5.6/sql/sql_error.cc:432: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `! is_set()' failed.
The text was updated successfully, but these errors were encountered: