| Bug #76040 | Assertion `!flags.finalized' failed in sql/binlog.cc:1172 | ||
|---|---|---|---|
| Submitted: | 25 Feb 2015 7:31 | Modified: | 27 Feb 2015 8:00 |
| Reporter: | Ramesh Sivaraman | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: DML | Severity: | S3 (Non-critical) |
| Version: | 5.6.23, 5.6.25 | OS: | Linux (CentOS 7) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | debug | ||
[25 Feb 2015 7:31]
Ramesh Sivaraman
Testcase bundle
Attachment: 1424748697_bug_bundle.tar.gz (application/gzip, text), 93.84 KiB.
[27 Feb 2015 8:00]
MySQL Verification Team
Hello Ramesh Sivaraman, Thank you for the report. Observed that 5.6.25 debug build affected. Thanks, Umesh
[27 Feb 2015 8:05]
MySQL Verification Team
// 5.6.25 debug build only (tried opt build but it didn't assert in 5+ attempts)
scripts/mysql_install_db --basedir=/export/umesh/mysql-5.6.25 --datadir=/export/umesh/mysql-5.6.25/75057
bin/mysqld-debug --basedir=/export/umesh/mysql-5.6.25 --datadir=/export/umesh/mysql-5.6.25/75057 --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --log-bin=binlog --binlog_format=MIXED --event-scheduler=ON --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/export/umesh/mysql-5.6.25/75057/log.err 2>&1 &
// Build used
commit: f7e34a3e1f12598c43608983c1c0145d418acae6
date: 2015-02-25 13:17:49 +0530
build-date: 2015-02-25 08:53:33 +0100
short: f7e34a3
branch: mysql-5.6
MySQL source 5.6.25
### only customized 1424748697_mybase and 1424748697_run_pquery ( started etc with above way instead of provided), also comented jemalloc in the test case
[umshastr@hod03]/export/umesh/mysql-5.6.25: ./1424748697_run_pquery
Executing testcase ./1424748697.sql against mysqld with socket /dev/shm/1424748697/socket.sock using pquery...
Infile is ./1424748697.sql
Database is test
Starting with 30 threads
Query limit per thread is 4000
User is root
Socket is /tmp/mysql_ushastry.sock
MySQL Connection Info: Localhost via UNIX socket
MySQL Client Info: 5.6.25
MySQL Server Info: 5.6.25-enterprise-commercial-advanced-debug-log
* SUMMARY: 1724/4000 queries failed (56.90% were successful)
* SUMMARY: 2202/4000 queries failed (44.95% were successful)
* SUMMARY: 1741/4000 queries failed (56.48% were successful)
* SUMMARY: 1750/4000 queries failed (56.25% were successful)
* SUMMARY: 1824/4000 queries failed (54.40% were successful)
* SUMMARY: 1841/4000 queries failed (53.98% were successful)
* SUMMARY: 1847/4000 queries failed (53.83% were successful)
* SUMMARY: 1849/4000 queries failed (53.77% were successful)
* SUMMARY: 1840/4000 queries failed (54.00% were successful)
* SUMMARY: 1833/4000 queries failed (54.17% were successful)
* SUMMARY: 1823/4000 queries failed (54.42% were successful)
* SUMMARY: 1864/4000 queries failed (53.40% were successful)
* SUMMARY: 1816/4000 queries failed (54.60% were successful)
* SUMMARY: 1783/4000 queries failed (55.42% were successful)
* SUMMARY: 1842/4000 queries failed (53.95% were successful)
* Last 250 consecutive queries all failed. Likely crash/assert, user privileges drop, or similar. Ending run.
* Last 250 consecutive queries all failed. Likely crash/assert, user privileges drop, or similar. Ending run.
* Last 250 consecutive queries all failed. Likely crash/assert, user privileges drop, or similar. Ending run.
./1424748697_run_pquery: line 5: 10460 Segmentation fault (core dumped) ./1424748697_pquery --infile=./1424748697.sql --database=test --threads=30 --queries=4000 --user=root --socket=/tmp/mysql_ushastry.sock
[1]+ Aborted (core dumped) bin/mysqld-debug --basedir=/export/umesh/mysql-5.6.25 --datadir=/export/umesh/mysql-5.6.25/75057 --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT --log-bin=binlog --binlog_format=MIXED --event-scheduler=ON --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/export/umesh/mysql-5.6.25/75057/log.err 2>&1
// extract from error log
2015-02-27 08:54:47 10432 [ERROR] Failed to write the DROP statement for temporary tables to binary log
mysqld-debug: /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/binlog.cc:1159: int binlog_cache_data::finalize(THD*, Log_event*): Assertion `!flags.finalized' failed.
07:54:47 UTC - mysqld got signal 6 ;
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `bin/mysqld-debug --basedir=/export/umesh/mysql-5.6.25 --datadir=/export/umesh/m'.
Program terminated with signal 6, Aborted.
#0 0x00007f8566490771 in pthread_kill () from /lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install glibc-2.17-55.0.4.el7_0.1.x86_64 libaio-0.3.109-12.el7.x86_64 libgcc-4.8.2-16.2.el7_0.x86_64 libstdc++-4.8.2-16.2.el7_0.x86_64 nss-softokn-freebl-3.16.2-1.el7_0.x86_64
(gdb) bt
#0 0x00007f8566490771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ae0e13 in my_write_core (sig=6) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/mysys/stacktrace.c:422
#2 0x0000000000745d72 in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/signal_handler.cc:230
#3 <signal handler called>
#4 0x00007f85650965c9 in raise () from /lib64/libc.so.6
#5 0x00007f8565097cd8 in abort () from /lib64/libc.so.6
#6 0x00007f856508f536 in __assert_fail_base () from /lib64/libc.so.6
#7 0x00007f856508f5e2 in __assert_fail () from /lib64/libc.so.6
#8 0x0000000000a74b6c in binlog_cache_data::finalize (this=0x7f84ec0084e0, thd=0x29d3730, end_event=0x0)
at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/binlog.cc:1159
#9 0x0000000000a74cb6 in binlog_stmt_cache_data::finalize (this=0x7f84ec0084e0, thd=0x29d3730) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/binlog.cc:599
#10 0x0000000000a75216 in MYSQL_BIN_LOG::commit (this=0x1936580 <mysql_bin_log>, thd=0x29d3730, all=true)
at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/binlog.cc:6410
#11 0x00000000007b2080 in THD::cleanup (this=0x29d3730) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/sql_class.cc:1531
#12 0x00000000007b21be in THD::release_resources (this=0x29d3730) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/sql_class.cc:1575
#13 0x000000000063ab49 in one_thread_per_connection_end (thd=0x29d3730, block_pthread=true) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/mysqld.cc:2752
#14 0x00000000007bb0d4 in do_handle_one_connection (thd_arg=0x29d3730) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/sql_connect.cc:989
#15 0x00000000007bb137 in handle_one_connection (arg=0x29d3730) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/sql/sql_connect.cc:898
#16 0x0000000000dadaf4 in pfs_spawn_thread (arg=0x29db7d0) at /export/home/pb2/build/sb_0-14531309-1424851851.85/mysqlcom-pro-5.6.25/storage/perfschema/pfs.cc:1860
#17 0x00007f856648bdf3 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f856515747d in clone () from /lib64/libc.so.6
[20 Apr 2018 23:33]
Roel Van de Paar
Also see in 8.0.11 GA debug, please update Version string
Description: GDB info #0 0x00007f3ec3756771 in pthread_kill () from /lib64/libpthread.so.0 #1 0x0000000000a980a6 in my_write_core (sig=6) at /sda/mysql-server-5.6/mysys/stacktrace.c:422 #2 0x00000000007277f0 in handle_fatal_signal (sig=6) at /sda/mysql-server-5.6/sql/signal_handler.cc:230 #3 <signal handler called> #4 0x00007f3ec25625c9 in raise () from /lib64/libc.so.6 #5 0x00007f3ec2563cd8 in abort () from /lib64/libc.so.6 #6 0x00007f3ec255b536 in __assert_fail_base () from /lib64/libc.so.6 #7 0x00007f3ec255b5e2 in __assert_fail () from /lib64/libc.so.6 #8 0x0000000000a1ee5c in binlog_cache_data::finalize (this=0x7f3ea0c47300, thd=0x7f3eb2a93000, end_event=0x0) at /sda/mysql-server-5.6/sql/binlog.cc:1172 #9 0x0000000000a1de1a in binlog_stmt_cache_data::finalize (this=0x7f3ea0c47300, thd=0x7f3eb2a93000) at /sda/mysql-server-5.6/sql/binlog.cc:612 #10 0x0000000000a2c020 in MYSQL_BIN_LOG::commit (this=0x1811b80 <mysql_bin_log>, thd=0x7f3eb2a93000, all=true) at /sda/mysql-server-5.6/sql/binlog.cc:6423 #11 0x000000000078a888 in THD::cleanup (this=0x7f3eb2a93000) at /sda/mysql-server-5.6/sql/sql_class.cc:1523 #12 0x000000000078a9f1 in THD::release_resources (this=0x7f3eb2a93000) at /sda/mysql-server-5.6/sql/sql_class.cc:1567 #13 0x000000000061ea09 in one_thread_per_connection_end (thd=0x7f3eb2a93000, block_pthread=true) at /sda/mysql-server-5.6/sql/mysqld.cc:2746 #14 0x0000000000797bae in do_handle_one_connection (thd_arg=0x7f3eb2a93000) at /sda/mysql-server-5.6/sql/sql_connect.cc:989 #15 0x0000000000797626 in handle_one_connection (arg=0x7f3eb2a93000) at /sda/mysql-server-5.6/sql/sql_connect.cc:898 #16 0x0000000000b5d7f0 in pfs_spawn_thread (arg=0x7f3ebcf3de80) at /sda/mysql-server-5.6/storage/perfschema/pfs.cc:1860 #17 0x00007f3ec3751df3 in start_thread () from /lib64/libpthread.so.0 #18 0x00007f3ec26231ad in clone () from /lib64/libc.so.6 (gdb) +set logging off How to repeat: DROP DATABASE transforms;CREATE DATABASE transforms;DROP DATABASE test;CREATE DATABASE test;USE test; select insert('hello', 1, 18446744073709551615, 'hi'); create temporary TABLE t1(a int(11), b varchar(8)); SET @@global.sql_safe_updates = 1-@@global.sql_safe_updates; SET @@global.max_binlog_cache_size = -1; XA START 'xatest'; DROP TEMPORARY TABLE IF EXISTS t_history; To reproducing the bug we need to use multi thread pquery binary, the attached tarball gives the testcase as an exact match of our system, including some handy utilities $ vi {epoch}_mybase # Update base path in this file (the only change required!) $ ./{epoch}_init # Initializes the data dir $ ./{epoch}_start # Starts mysqld $ ./{epoch}_cl # To check mysqld is up $ ./{epoch}_run_pquery # Run the testcase with pquery binary(produces output) $ vi /dev/shm/{epoch}/error.log.out # Verify the error log $ ./{epoch}_gdb # Brings you to a gdb prompt attached to correct mysqld & generated core $ ./{epoch}_parse_core # Create {epoch}_STD.gdb and {epoch}_FULL.gdb; standard and full var gdb stack traces etc.