[MDEV-25488] thd::transaction::modified_non_trans_tables isn't set before Rows_log_event caching - Jira

Details

Type: Bug
Status: In Review (View Workflow)
Priority: Major
Resolution: Unresolved
Affects Version/s: 11.3.0, 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL)
Fix Version/s: 10.6, 10.11
Component/s: Binary Protocol
Labels:
- affects-tests
- not-10.2
- not-10.3
- not-10.4
- not-10.5
- regression

Description

# mysqld options required for replay: --log-bin

SET GLOBAL max_binlog_stmt_cache_size=0;

CREATE TEMPORARY TABLE t (c INT) ENGINE=InnoDB;

SELECT @@GLOBAL.innodb_flush_method=variable_value FROM information_schema.global_variables;

DELETE FROM mysql.proc;

Leads to:

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Debug)
mysqld: /test/10.6_dbg/sql/log.cc:7424: int MYSQL_BIN_LOG::write_cache(THD, IO_CACHE): Assertion `!writer.checksum_len \|\| writer.remains == 0' failed.

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Debug)
Core was generated by `/test/MD150421-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x14c2a4c73700 (LWP 3661648))]
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x000014c2bab53859 in __GI_abort () at abort.c:79
#2 0x000014c2bab53729 in __assert_fail_base (fmt=0x14c2bace9588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55c5bde51990 "!writer.checksum_len \|\| writer.remains == 0", file=0x55c5bde4f364 "/test/10.6_dbg/sql/log.cc", line=7424, function=<optimized out>) at assert.c:92
#3 0x000014c2bab64f36 in __GI___assert_fail (assertion=assertion@entry=0x55c5bde51990 "!writer.checksum_len \|\| writer.remains == 0", file=file@entry=0x55c5bde4f364 "/test/10.6_dbg/sql/log.cc", line=line@entry=7424, function=function@entry=0x55c5bde518a8 "int MYSQL_BIN_LOG::write_cache(THD, IO_CACHE)") at assert.c:101
#4 0x000055c5bd4331ad in MYSQL_BIN_LOG::write_cache (this=this@entry=0x55c5be6135c0 <mysql_bin_log>, thd=<optimized out>, cache=cache@entry=0x14c26c2260f8) at /test/10.6_dbg/sql/log.cc:7424
#5 0x000055c5bd433d31 in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x55c5be6135c0 <mysql_bin_log>, entry=entry@entry=0x14c2a4c71a20, commit_id=commit_id@entry=0) at /test/10.6_dbg/sql/log.cc:562
#6 0x000055c5bd440d43 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x55c5be6135c0 <mysql_bin_log>, leader=leader@entry=0x14c2a4c71a20) at /test/10.6_dbg/sql/log.cc:8251
#7 0x000055c5bd4423a4 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x55c5be6135c0 <mysql_bin_log>, entry=entry@entry=0x14c2a4c71a20) at /test/10.6_dbg/sql/log.cc:8045
#8 0x000055c5bd442944 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x55c5be6135c0 <mysql_bin_log>, thd=thd@entry=0x14c26c000db8, cache_mngr=cache_mngr@entry=0x14c26c2260f8, end_ev=end_ev@entry=0x14c2a4c71bd0, all=all@entry=false, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=false) at /test/10.6_dbg/sql/log.cc:7642
#9 0x000055c5bd442c14 in binlog_flush_cache (thd=thd@entry=0x14c26c000db8, cache_mngr=cache_mngr@entry=0x14c26c2260f8, end_ev=end_ev@entry=0x14c2a4c71bd0, all=all@entry=false, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=false) at /test/10.6_dbg/sql/log.cc:1797
#10 0x000055c5bd443c6d in binlog_commit_flush_stmt_cache (thd=0x14c26c000db8, all=<optimized out>, cache_mngr=0x14c26c2260f8) at /test/10.6_dbg/sql/log.cc:1849
#11 0x000055c5bd4441ac in binlog_rollback (hton=<optimized out>, thd=0x14c26c000db8, all=<optimized out>) at /test/10.6_dbg/sql/log.cc:2253
#12 0x000055c5bd2d78a5 in ha_rollback_trans (thd=thd@entry=0x14c26c000db8, all=all@entry=false) at /test/10.6_dbg/sql/handler.cc:2054
#13 0x000055c5bd17e74a in trans_rollback_stmt (thd=thd@entry=0x14c26c000db8) at /test/10.6_dbg/sql/transaction.cc:535
#14 0x000055c5bd017042 in mysql_execute_command (thd=thd@entry=0x14c26c000db8) at /test/10.6_dbg/sql/sql_parse.cc:6039
#15 0x000055c5bcffca06 in mysql_parse (thd=thd@entry=0x14c26c000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14c2a4c72410) at /test/10.6_dbg/sql/sql_parse.cc:8017
#16 0x000055c5bd00b7df in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14c26c000db8, packet=packet@entry=0x14c26c00b489 "DELETE FROM mysql.proc", packet_length=packet_length@entry=22, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1331
#17 0x000055c5bd00ebd5 in do_command (thd=0x14c26c000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1406
#18 0x000055c5bd16877c in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55c5c12aea48, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#19 0x000055c5bd168d81 in handle_one_connection (arg=arg@entry=0x55c5c12aea48) at /test/10.6_dbg/sql/sql_connect.cc:1312
#20 0x000055c5bd616a03 in pfs_spawn_thread (arg=0x55c5c11df348) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#21 0x000014c2bb061609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#22 0x000014c2bac50293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt), 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (dbg), 10.4.19 (opt), 10.5.10 (dbg), 10.5.10 (opt), 10.6.0 (opt)

On optimized:

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Optimized)
10.6.0-opt>DELETE FROM mysql.proc;
ERROR 1705 (HY000): Multi-row statements required more than 'max_binlog_stmt_cache_size' bytes of storage.

Attachments

Issue Links

includes

MDEV-35378 sequence statement does not trigger warning when mixed transaction rolls back

In Review

relates to

MDEV-33107 Assertion `!writer.checksum_len || writer.remains == 0' failed in Event_log::write_cache on OOS in --tmpdir

Closed

MDEV-35207 ignored error at binlogging by CREATE-TABLE-SELECT leads to assert

Stalled

MDEV-23529 Assertion `!writer.checksum_len || writer.remains == 0' failed in MYSQL_BIN_LOG::write_cache

Confirmed

Activity

Ascending order - Click to sort in descending order

Sergei Golubchik added a comment - 2021-04-22 13:30

This test case doesn't make any sense. What this SELECT has to do with anything? What does the CREATE TEMPORARY TABLE do — starts a transaction?

Sergei Golubchik added a comment - 2021-04-22 13:30 This test case doesn't make any sense. What this SELECT has to do with anything? What does the CREATE TEMPORARY TABLE do — starts a transaction?

Andrei Elkin added a comment - 2021-04-22 15:48

Roel, thanks for finding it. Reproduced at once. I am not sure why 'Binary protocol' was there. Corrected.

Andrei Elkin added a comment - 2021-04-22 15:48 Roel , thanks for finding it. Reproduced at once. I am not sure why 'Binary protocol' was there. Corrected.

Andrei Elkin added a comment - 2021-04-22 16:29 - edited

serg, the 1st SET GLOBAL max_binlog_stmt_cache_size=0 has the meaning of narrowing down the actual value from ULONGLONG_MAX to 4096, which must play some role in future bin-logging of DELETE. The latter gets involved into binlogging through an error

ERROR 1705 (HY000): Multi-row statements

And the error seems to be induced by two more queries in between.
Quite a joking case!

Andrei Elkin added a comment - 2021-04-22 16:29 - edited serg , the 1st SET GLOBAL max_binlog_stmt_cache_size=0 has the meaning of narrowing down the actual value from ULONGLONG_MAX to 4096, which must play some role in future bin-logging of DELETE. The latter gets involved into binlogging through an error ERROR 1705 (HY000): Multi-row statements And the error seems to be induced by two more queries in between. Quite a joking case!

Andrei Elkin added a comment - 2021-04-23 17:55

As a workaround, don't set max_binlog_stmt_cache_size to too small value.

Andrei Elkin added a comment - 2021-04-23 17:55 As a workaround, don't set max_binlog_stmt_cache_size to too small value.

Matthias Leich added a comment - 2023-09-07 14:35

origin/11.3, 11.3 8ad1e26b1bafa4ed9928306efc10c047f2274108 2023-09-04T09:36:44+04:00  debug build claims to be a 11.3.0

A significant share of RQG tests fails with

mariadbd: /data/Server/11.3/sql/log.cc:8052: int Event_log::write_cache(THD*, IO_CACHE*): Assertion `!writer.checksum_len || writer.remains == 0' failed.

Query (0x6767640133a0): COMMIT

Status: KILL_TIMEOUT

# 2023-09-07T04:51:32 [3411390] | Thread 3 (Thread 3415550.3422250 (mariadbd)):

# 2023-09-07T04:51:32 [3411390] | #0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=33824607811136) at ./nptl/pthread_kill.c:44

# 2023-09-07T04:51:32 [3411390] | #1  __pthread_kill_internal (signo=6, threadid=33824607811136) at ./nptl/pthread_kill.c:78

# 2023-09-07T04:51:32 [3411390] | #2  __GI___pthread_kill (threadid=33824607811136, signo=signo@entry=6) at ./nptl/pthread_kill.c:89

# 2023-09-07T04:51:32 [3411390] | #3  0x00004c9a6874e476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26

# 2023-09-07T04:51:32 [3411390] | #4  0x00004c9a687347f3 in __GI_abort () at ./stdlib/abort.c:79

# 2023-09-07T04:51:32 [3411390] | #5  0x00004c9a6873471b in __assert_fail_base (fmt=0x4c9a688e9150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55bb03b799d0 "!writer.checksum_len || writer.remains == 0", file=0x55bb03b76ae8 "/data/Server/11.3/sql/log.cc", line=8052, function=<optimized out>) at ./assert/assert.c:92

# 2023-09-07T04:51:32 [3411390] | #6  0x00004c9a68745e96 in __GI___assert_fail (assertion=0x55bb03b799d0 "!writer.checksum_len || writer.remains == 0", file=0x55bb03b76ae8 "/data/Server/11.3/sql/log.cc", line=8052, function=0x55bb03b798e8 "int Event_log::write_cache(THD*, IO_CACHE*)") at ./assert/assert.c:101

# 2023-09-07T04:51:32 [3411390] | #7  0x000055bb0322fc75 in Event_log::write_cache (this=this@entry=0x55bb044a2a68 <mysql_bin_log+8>, thd=<optimized out>, cache=cache@entry=0x67676401a368) at /data/Server/11.3/sql/log.cc:8052

# 2023-09-07T04:51:32 [3411390] | #8  0x000055bb0323035a in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, entry=entry@entry=0x1ec367bb8b60, commit_id=commit_id@entry=0) at /data/Server/11.3/sql/log.cc:9182

# 2023-09-07T04:51:32 [3411390] | #9  0x000055bb0323ba55 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, leader=leader@entry=0x1ec367bb8b60) at /data/Server/11.3/sql/log.cc:8902

# 2023-09-07T04:51:32 [3411390] | #10 0x000055bb0323c98b in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, entry=entry@entry=0x1ec367bb8b60) at /data/Server/11.3/sql/log.cc:8694

# 2023-09-07T04:51:32 [3411390] | #11 0x000055bb0323cdeb in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, thd=thd@entry=0x676764000d58, cache_mngr=cache_mngr@entry=0x67676401a1c8, end_ev=end_ev@entry=0x1ec367bb8e80, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=false, using_trx_cache=true, is_ro_1pc=true) at /data/Server/11.3/sql/log.cc:8291

# 2023-09-07T04:51:32 [3411390] | #12 0x000055bb0323d070 in binlog_flush_cache (thd=thd@entry=0x676764000d58, cache_mngr=cache_mngr@entry=0x67676401a1c8, end_ev=end_ev@entry=0x1ec367bb8e80, all=all@entry=true, using_stmt=using_stmt@entry=false, using_trx=using_trx@entry=true, is_ro_1pc=true) at /data/Server/11.3/sql/log.cc:1907

# 2023-09-07T04:51:32 [3411390] | #13 0x000055bb0323eabf in binlog_commit_flush_trx_cache (thd=thd@entry=0x676764000d58, all=all@entry=true, cache_mngr=cache_mngr@entry=0x67676401a1c8, ro_1pc=ro_1pc@entry=true) at /data/Server/11.3/sql/log.cc:2006

# 2023-09-07T04:51:32 [3411390] | #14 0x000055bb0323ee82 in binlog_commit (thd=thd@entry=0x676764000d58, all=all@entry=true, ro_1pc=<optimized out>) at /data/Server/11.3/sql/log.cc:2416

# 2023-09-07T04:51:32 [3411390] | #15 0x000055bb03098b94 in commit_one_phase_2 (thd=thd@entry=0x676764000d58, all=all@entry=true, trans=trans@entry=0x676764004800, is_real_trans=is_real_trans@entry=true) at /data/Server/11.3/sql/handler.cc:2130

# 2023-09-07T04:51:32 [3411390] | #16 0x000055bb03098f8f in ha_commit_one_phase (thd=thd@entry=0x676764000d58, all=all@entry=true) at /data/Server/11.3/sql/handler.cc:2092

# 2023-09-07T04:51:32 [3411390] | #17 0x000055bb0309a572 in ha_commit_trans (thd=thd@entry=0x676764000d58, all=all@entry=true) at /data/Server/11.3/sql/handler.cc:1886

# 2023-09-07T04:51:32 [3411390] | #18 0x000055bb02ee8ee8 in trans_commit (thd=thd@entry=0x676764000d58) at /data/Server/11.3/sql/transaction.cc:266

# 2023-09-07T04:51:32 [3411390] | #19 0x000055bb02d3fa9a in mysql_execute_command (thd=thd@entry=0x676764000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/11.3/sql/sql_parse.cc:5361

# 2023-09-07T04:51:32 [3411390] | #20 0x000055bb02d41d81 in mysql_parse (thd=thd@entry=0x676764000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1ec367bba270) at /data/Server/11.3/sql/sql_parse.cc:7760

# 2023-09-07T04:51:32 [3411390] | #21 0x000055bb02d4419d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x676764000d58, packet=packet@entry=0x67676400b009 " COMMIT  /* E_R Thread9 QNO 244 CON_ID 19 */ ", packet_length=packet_length@entry=45, blocking=blocking@entry=true) at /data/Server/11.3/sql/sql_parse.cc:1893

# 2023-09-07T04:51:32 [3411390] | #22 0x000055bb02d4665c in do_command (thd=0x676764000d58, blocking=blocking@entry=true) at /data/Server/11.3/sql/sql_parse.cc:1406

# 2023-09-07T04:51:32 [3411390] | #23 0x000055bb02ed25e7 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55bb0531b498, put_in_cache=put_in_cache@entry=true) at /data/Server/11.3/sql/sql_connect.cc:1445

# 2023-09-07T04:51:32 [3411390] | #24 0x000055bb02ed2855 in handle_one_connection (arg=0x55bb0531b498) at /data/Server/11.3/sql/sql_connect.cc:1347

# 2023-09-07T04:51:32 [3411390] | #25 0x00004c9a687a0b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442

# 2023-09-07T04:51:32 [3411390] | #26 0x00004c9a68831bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100

No replay of the problem on a RelWithDebInfo build.

Matthias Leich added a comment - 2023-09-07 14:35 origin/11.3, 11.3 8ad1e26b1bafa4ed9928306efc10c047f2274108 2023-09-04T09:36:44+04:00 debug build claims to be a 11.3.0 A significant share of RQG tests fails with mariadbd: /data/Server/11.3/sql/log.cc:8052: int Event_log::write_cache(THD*, IO_CACHE*): Assertion `!writer.checksum_len || writer.remains == 0' failed. Query (0x6767640133a0): COMMIT Status: KILL_TIMEOUT # 2023-09-07T04:51:32 [3411390] | Thread 3 (Thread 3415550.3422250 (mariadbd)): # 2023-09-07T04:51:32 [3411390] | #0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=33824607811136) at ./nptl/pthread_kill.c:44 # 2023-09-07T04:51:32 [3411390] | #1 __pthread_kill_internal (signo=6, threadid=33824607811136) at ./nptl/pthread_kill.c:78 # 2023-09-07T04:51:32 [3411390] | #2 __GI___pthread_kill (threadid=33824607811136, signo=signo@entry=6) at ./nptl/pthread_kill.c:89 # 2023-09-07T04:51:32 [3411390] | #3 0x00004c9a6874e476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26 # 2023-09-07T04:51:32 [3411390] | #4 0x00004c9a687347f3 in __GI_abort () at ./stdlib/abort.c:79 # 2023-09-07T04:51:32 [3411390] | #5 0x00004c9a6873471b in __assert_fail_base (fmt=0x4c9a688e9150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55bb03b799d0 "!writer.checksum_len || writer.remains == 0", file=0x55bb03b76ae8 "/data/Server/11.3/sql/log.cc", line=8052, function=<optimized out>) at ./assert/assert.c:92 # 2023-09-07T04:51:32 [3411390] | #6 0x00004c9a68745e96 in __GI___assert_fail (assertion=0x55bb03b799d0 "!writer.checksum_len || writer.remains == 0", file=0x55bb03b76ae8 "/data/Server/11.3/sql/log.cc", line=8052, function=0x55bb03b798e8 "int Event_log::write_cache(THD*, IO_CACHE*)") at ./assert/assert.c:101 # 2023-09-07T04:51:32 [3411390] | #7 0x000055bb0322fc75 in Event_log::write_cache (this=this@entry=0x55bb044a2a68 <mysql_bin_log+8>, thd=<optimized out>, cache=cache@entry=0x67676401a368) at /data/Server/11.3/sql/log.cc:8052 # 2023-09-07T04:51:32 [3411390] | #8 0x000055bb0323035a in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, entry=entry@entry=0x1ec367bb8b60, commit_id=commit_id@entry=0) at /data/Server/11.3/sql/log.cc:9182 # 2023-09-07T04:51:32 [3411390] | #9 0x000055bb0323ba55 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, leader=leader@entry=0x1ec367bb8b60) at /data/Server/11.3/sql/log.cc:8902 # 2023-09-07T04:51:32 [3411390] | #10 0x000055bb0323c98b in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, entry=entry@entry=0x1ec367bb8b60) at /data/Server/11.3/sql/log.cc:8694 # 2023-09-07T04:51:32 [3411390] | #11 0x000055bb0323cdeb in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x55bb044a2a60 <mysql_bin_log>, thd=thd@entry=0x676764000d58, cache_mngr=cache_mngr@entry=0x67676401a1c8, end_ev=end_ev@entry=0x1ec367bb8e80, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=false, using_trx_cache=true, is_ro_1pc=true) at /data/Server/11.3/sql/log.cc:8291 # 2023-09-07T04:51:32 [3411390] | #12 0x000055bb0323d070 in binlog_flush_cache (thd=thd@entry=0x676764000d58, cache_mngr=cache_mngr@entry=0x67676401a1c8, end_ev=end_ev@entry=0x1ec367bb8e80, all=all@entry=true, using_stmt=using_stmt@entry=false, using_trx=using_trx@entry=true, is_ro_1pc=true) at /data/Server/11.3/sql/log.cc:1907 # 2023-09-07T04:51:32 [3411390] | #13 0x000055bb0323eabf in binlog_commit_flush_trx_cache (thd=thd@entry=0x676764000d58, all=all@entry=true, cache_mngr=cache_mngr@entry=0x67676401a1c8, ro_1pc=ro_1pc@entry=true) at /data/Server/11.3/sql/log.cc:2006 # 2023-09-07T04:51:32 [3411390] | #14 0x000055bb0323ee82 in binlog_commit (thd=thd@entry=0x676764000d58, all=all@entry=true, ro_1pc=<optimized out>) at /data/Server/11.3/sql/log.cc:2416 # 2023-09-07T04:51:32 [3411390] | #15 0x000055bb03098b94 in commit_one_phase_2 (thd=thd@entry=0x676764000d58, all=all@entry=true, trans=trans@entry=0x676764004800, is_real_trans=is_real_trans@entry=true) at /data/Server/11.3/sql/handler.cc:2130 # 2023-09-07T04:51:32 [3411390] | #16 0x000055bb03098f8f in ha_commit_one_phase (thd=thd@entry=0x676764000d58, all=all@entry=true) at /data/Server/11.3/sql/handler.cc:2092 # 2023-09-07T04:51:32 [3411390] | #17 0x000055bb0309a572 in ha_commit_trans (thd=thd@entry=0x676764000d58, all=all@entry=true) at /data/Server/11.3/sql/handler.cc:1886 # 2023-09-07T04:51:32 [3411390] | #18 0x000055bb02ee8ee8 in trans_commit (thd=thd@entry=0x676764000d58) at /data/Server/11.3/sql/transaction.cc:266 # 2023-09-07T04:51:32 [3411390] | #19 0x000055bb02d3fa9a in mysql_execute_command (thd=thd@entry=0x676764000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/11.3/sql/sql_parse.cc:5361 # 2023-09-07T04:51:32 [3411390] | #20 0x000055bb02d41d81 in mysql_parse (thd=thd@entry=0x676764000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1ec367bba270) at /data/Server/11.3/sql/sql_parse.cc:7760 # 2023-09-07T04:51:32 [3411390] | #21 0x000055bb02d4419d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x676764000d58, packet=packet@entry=0x67676400b009 " COMMIT /* E_R Thread9 QNO 244 CON_ID 19 */ ", packet_length=packet_length@entry=45, blocking=blocking@entry=true) at /data/Server/11.3/sql/sql_parse.cc:1893 # 2023-09-07T04:51:32 [3411390] | #22 0x000055bb02d4665c in do_command (thd=0x676764000d58, blocking=blocking@entry=true) at /data/Server/11.3/sql/sql_parse.cc:1406 # 2023-09-07T04:51:32 [3411390] | #23 0x000055bb02ed25e7 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55bb0531b498, put_in_cache=put_in_cache@entry=true) at /data/Server/11.3/sql/sql_connect.cc:1445 # 2023-09-07T04:51:32 [3411390] | #24 0x000055bb02ed2855 in handle_one_connection (arg=0x55bb0531b498) at /data/Server/11.3/sql/sql_connect.cc:1347 # 2023-09-07T04:51:32 [3411390] | #25 0x00004c9a687a0b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442 # 2023-09-07T04:51:32 [3411390] | #26 0x00004c9a68831bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100 No replay of the problem on a RelWithDebInfo build.

Ramesh Sivaraman added a comment - 2023-12-08 05:07

Found different assertion on 10.4 debug build when executing the following test case, but 10.[56] debug build crashes similar to this ticket when executing the given test case

# mysqld options required for replay: --log-bin --binlog_format=ROW

CREATE TABLE t (a INT) ENGINE=MyISAM;

SET GLOBAL max_binlog_stmt_cache_size=1;

INSERT t VALUES (1),(1),(1),(1),(1),(1),(1),(1);

INSERT INTO t SELECT 1 FROM t A,t B,t C, t D;

ANALYZE UPDATE t SET a=10;

Leads to:

10.4.33 5f89045221717533994da01fc270d4851ccdc06c (Debug)

mariadbd: /test/10.4_dbg/sql/log.cc:8385: int MYSQL_BIN_LOG::write_transaction_or_stmt(MYSQL_BIN_LOG::group_commit_entry*, uint64): Assertion `!(entry->using_stmt_cache && !mngr->stmt_cache.empty() && mngr->get_binlog_cache_log((0))->error)' failed.

10.4.33 5f89045221717533994da01fc270d4851ccdc06c (Debug)
Core was generated by `/test/MD011223-mariadb-10.4.33-linux-x86_64-dbg/bin/mariadbd --no-defaults --co'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x14b4993e5700 (LWP 1219661))]
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x000014b4bf6fb859 in __GI_abort () at abort.c:79
#2 0x000014b4bf6fb729 in __assert_fail_base (fmt=0x14b4bf891588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x558c160840f0 "!(entry->using_stmt_cache && !mngr->stmt_cache.empty() && mngr->get_binlog_cache_log((0))->error)", file=0x558c160821b0 "/test/10.4_dbg/sql/log.cc", line=8385, function=<optimized out>) at assert.c:92
#3 0x000014b4bf70cfd6 in __GI___assert_fail (assertion=assertion@entry=0x558c160840f0 "!(entry->using_stmt_cache && !mngr->stmt_cache.empty() && mngr->get_binlog_cache_log((0))->error)", file=file@entry=0x558c160821b0 "/test/10.4_dbg/sql/log.cc", line=line@entry=8385, function=function@entry=0x558c16083fc8 "int MYSQL_BIN_LOG::write_transaction_or_stmt(MYSQL_BIN_LOG::group_commit_entry*, uint64)") at assert.c:101
#4 0x0000558c156606ec in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x558c167f05a0 <mysql_bin_log>, entry=entry@entry=0x14b4993e26a0, commit_id=commit_id@entry=0) at /test/10.4_dbg/sql/log.cc:534
#5 0x0000558c1566d5e0 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x558c167f05a0 <mysql_bin_log>, leader=leader@entry=0x14b4993e26a0) at /test/10.4_dbg/sql/log.cc:8127
#6 0x0000558c1566e330 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x558c167f05a0 <mysql_bin_log>, entry=entry@entry=0x14b4993e26a0) at /test/10.4_dbg/sql/log.cc:7921
#7 0x0000558c1566e883 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x558c167f05a0 <mysql_bin_log>, thd=thd@entry=0x14b45c000d28, cache_mngr=cache_mngr@entry=0x14b45c067c58, end_ev=end_ev@entry=0x14b4993e27f0, all=all@entry=false, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=false) at /test/10.4_dbg/sql/log.cc:7516
#8 0x0000558c1566e9de in binlog_flush_cache (thd=thd@entry=0x14b45c000d28, cache_mngr=cache_mngr@entry=0x14b45c067c58, end_ev=end_ev@entry=0x14b4993e27f0, all=all@entry=false, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=false) at /test/10.4_dbg/sql/log.cc:1762
#9 0x0000558c1566f04f in binlog_commit_flush_stmt_cache (thd=thd@entry=0x14b45c000d28, all=all@entry=false, cache_mngr=cache_mngr@entry=0x14b45c067c58) at /test/10.4_dbg/sql/log.cc:1814
#10 0x0000558c1566f23c in binlog_rollback (hton=<optimized out>, thd=0x14b45c000d28, all=<optimized out>) at /test/10.4_dbg/sql/log.cc:2092
#11 0x0000558c1550dc78 in ha_rollback_trans (thd=thd@entry=0x14b45c000d28, all=all@entry=false) at /test/10.4_dbg/sql/handler.cc:1955
#12 0x0000558c153be1f6 in trans_rollback_stmt (thd=thd@entry=0x14b45c000d28) at /test/10.4_dbg/sql/transaction.cc:496
#13 0x0000558c152780d8 in mysql_execute_command (thd=thd@entry=0x14b45c000d28) at /test/10.4_dbg/sql/sql_parse.cc:6317
#14 0x0000558c15279d6c in mysql_parse (thd=thd@entry=0x14b45c000d28, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b4993e4360, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:8062
#15 0x0000558c1527cd7e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b45c000d28, packet=packet@entry=0x14b45c019729 "", packet_length=packet_length@entry=25, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_class.h:1242
#16 0x0000558c1527f9fd in do_command (thd=0x14b45c000d28) at /test/10.4_dbg/sql/sql_parse.cc:1378
#17 0x0000558c153ab252 in do_handle_one_connection (connect=connect@entry=0x558c1882ab68) at /test/10.4_dbg/sql/sql_connect.cc:1419
#18 0x0000558c153ab371 in handle_one_connection (arg=0x558c1882ab68) at /test/10.4_dbg/sql/sql_connect.cc:1323
#19 0x000014b4bfc0c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#20 0x000014b4bf7f8133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.33 (dbg)

Ramesh Sivaraman added a comment - 2023-12-08 05:07 Found different assertion on 10.4 debug build when executing the following test case, but 10. [56] debug build crashes similar to this ticket when executing the given test case # mysqld options required for replay: --log-bin --binlog_format=ROW CREATE TABLE t (a INT ) ENGINE=MyISAM; SET GLOBAL max_binlog_stmt_cache_size=1; INSERT t VALUES (1),(1),(1),(1),(1),(1),(1),(1); INSERT INTO t SELECT 1 FROM t A,t B,t C, t D; ANALYZE UPDATE t SET a=10; Leads to: 10.4.33 5f89045221717533994da01fc270d4851ccdc06c (Debug) mariadbd: /test/10.4_dbg/sql/log.cc:8385: int MYSQL_BIN_LOG::write_transaction_or_stmt(MYSQL_BIN_LOG::group_commit_entry*, uint64): Assertion `!(entry->using_stmt_cache && !mngr->stmt_cache.empty() && mngr->get_binlog_cache_log((0))->error)' failed. 10.4.33 5f89045221717533994da01fc270d4851ccdc06c (Debug) Core was generated by `/test/MD011223-mariadb-10.4.33-linux-x86_64-dbg/bin/mariadbd --no-defaults --co'. Program terminated with signal SIGABRT, Aborted. #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 [Current thread is 1 (Thread 0x14b4993e5700 (LWP 1219661))] (gdb) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x000014b4bf6fb859 in __GI_abort () at abort.c:79 #2 0x000014b4bf6fb729 in __assert_fail_base (fmt=0x14b4bf891588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x558c160840f0 "!(entry->using_stmt_cache && !mngr->stmt_cache.empty() && mngr->get_binlog_cache_log((0))->error)", file=0x558c160821b0 "/test/10.4_dbg/sql/log.cc", line=8385, function=<optimized out>) at assert.c:92 #3 0x000014b4bf70cfd6 in __GI___assert_fail (assertion=assertion@entry=0x558c160840f0 "!(entry->using_stmt_cache && !mngr->stmt_cache.empty() && mngr->get_binlog_cache_log((0))->error)", file=file@entry=0x558c160821b0 "/test/10.4_dbg/sql/log.cc", line=line@entry=8385, function=function@entry=0x558c16083fc8 "int MYSQL_BIN_LOG::write_transaction_or_stmt(MYSQL_BIN_LOG::group_commit_entry*, uint64)") at assert.c:101 #4 0x0000558c156606ec in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x558c167f05a0 <mysql_bin_log>, entry=entry@entry=0x14b4993e26a0, commit_id=commit_id@entry=0) at /test/10.4_dbg/sql/log.cc:534 #5 0x0000558c1566d5e0 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x558c167f05a0 <mysql_bin_log>, leader=leader@entry=0x14b4993e26a0) at /test/10.4_dbg/sql/log.cc:8127 #6 0x0000558c1566e330 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x558c167f05a0 <mysql_bin_log>, entry=entry@entry=0x14b4993e26a0) at /test/10.4_dbg/sql/log.cc:7921 #7 0x0000558c1566e883 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x558c167f05a0 <mysql_bin_log>, thd=thd@entry=0x14b45c000d28, cache_mngr=cache_mngr@entry=0x14b45c067c58, end_ev=end_ev@entry=0x14b4993e27f0, all=all@entry=false, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=false) at /test/10.4_dbg/sql/log.cc:7516 #8 0x0000558c1566e9de in binlog_flush_cache (thd=thd@entry=0x14b45c000d28, cache_mngr=cache_mngr@entry=0x14b45c067c58, end_ev=end_ev@entry=0x14b4993e27f0, all=all@entry=false, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=false) at /test/10.4_dbg/sql/log.cc:1762 #9 0x0000558c1566f04f in binlog_commit_flush_stmt_cache (thd=thd@entry=0x14b45c000d28, all=all@entry=false, cache_mngr=cache_mngr@entry=0x14b45c067c58) at /test/10.4_dbg/sql/log.cc:1814 #10 0x0000558c1566f23c in binlog_rollback (hton=<optimized out>, thd=0x14b45c000d28, all=<optimized out>) at /test/10.4_dbg/sql/log.cc:2092 #11 0x0000558c1550dc78 in ha_rollback_trans (thd=thd@entry=0x14b45c000d28, all=all@entry=false) at /test/10.4_dbg/sql/handler.cc:1955 #12 0x0000558c153be1f6 in trans_rollback_stmt (thd=thd@entry=0x14b45c000d28) at /test/10.4_dbg/sql/transaction.cc:496 #13 0x0000558c152780d8 in mysql_execute_command (thd=thd@entry=0x14b45c000d28) at /test/10.4_dbg/sql/sql_parse.cc:6317 #14 0x0000558c15279d6c in mysql_parse (thd=thd@entry=0x14b45c000d28, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b4993e4360, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:8062 #15 0x0000558c1527cd7e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b45c000d28, packet=packet@entry=0x14b45c019729 "", packet_length=packet_length@entry=25, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_class.h:1242 #16 0x0000558c1527f9fd in do_command (thd=0x14b45c000d28) at /test/10.4_dbg/sql/sql_parse.cc:1378 #17 0x0000558c153ab252 in do_handle_one_connection (connect=connect@entry=0x558c1882ab68) at /test/10.4_dbg/sql/sql_connect.cc:1419 #18 0x0000558c153ab371 in handle_one_connection (arg=0x558c1882ab68) at /test/10.4_dbg/sql/sql_connect.cc:1323 #19 0x000014b4bfc0c609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #20 0x000014b4bf7f8133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Bug confirmed present in: MariaDB: 10.4.33 (dbg)

Roel Van de Paar added a comment - 2023-12-22 01:21 - edited

The stack first seen by mleich, above seems to be a different issue (aborts in Event_log::write_cache). I ran into this stack as well in 11.3, as a result of OOS in --tmpdir. Created ~~MDEV-33107~~ Assertion `!writer.checksum_len || writer.remains == 0' failed in Event_log::write_cache and added the trace from mleich there also.

Roel Van de Paar added a comment - 2023-12-22 01:21 - edited The stack first seen by mleich , above seems to be a different issue (aborts in Event_log::write_cache ). I ran into this stack as well in 11.3, as a result of OOS in --tmpdir . Created MDEV-33107 Assertion `!writer.checksum_len || writer.remains == 0' failed in Event_log::write_cache and added the trace from mleich there also.

People

Assignee:: Brandon Nesterenko

Reporter:: Roel Van de Paar

Votes:: 0 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2021-04-22 10:04

Updated:: 2024-11-26 16:11

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server