Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
12.0
-
None
-
MSAN + clang-20
Description
|
main-3a43b7c60b84314135b324840b03b3e36265f072 (12.0) |
innodb.log_file_size_online 'slow' w3 [ fail ]
|
Test ended at 2025-02-25 03:24:44
|
|
|
CURRENT_TEST: innodb.log_file_size_online
|
mysqltest: At line 7: query 'SET GLOBAL innodb_log_file_size=4194304' failed: <Unknown> (2013): Lost connection to server during query
|
|
|
The result from queries just before the failure was:
|
SET GLOBAL innodb_log_file_size=4194304;
|
|
|
|
|
Server [mysqld.1 - pid: 23817, winpid: 23817, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
$ /build/sql/mariadbd --defaults-group-suffix=.1 --defaults-file=/build/mysql-test/var/3/my.cnf --log-output=file --innodb-flush-sync=OFF --innodb-encrypt-log=OFF --innodb-log-file-size=5M --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --loose-sequence --core-file --loose-debug-sync-timeout=300
|
2025-02-25 3:24:35 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32198)
|
2025-02-25 3:24:35 0 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000)
|
2025-02-25 3:24:36 0 [Note] Starting MariaDB 12.0.0-MariaDB-log source revision server_uid 7bXZE78Br8zVsGQGE/YJALR2TwE= as process 23818
|
2025-02-25 3:24:36 0 [Note] Plugin 'partition' is disabled.
|
2025-02-25 3:24:36 0 [Note] InnoDB: Compressed tables use zlib 1.3.1
|
2025-02-25 3:24:36 0 [Note] InnoDB: Number of transaction pools: 1
|
2025-02-25 3:24:36 0 [Note] InnoDB: Using AVX512 instructions
|
2025-02-25 3:24:36 0 [Note] InnoDB: Initializing buffer pool, total size = 8.000MiB, chunk size = 1.000MiB
|
2025-02-25 3:24:36 0 [Note] InnoDB: Completed initialization of buffer pool
|
2025-02-25 3:24:36 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
|
2025-02-25 3:24:36 0 [Note] InnoDB: End of log at LSN=49148
|
2025-02-25 3:24:36 0 [Note] InnoDB: Resizing redo log from 10.000MiB to 5.000MiB; LSN=49148
|
2025-02-25 3:24:36 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
|
2025-02-25 3:24:36 0 [Note] InnoDB: Opened 3 undo tablespaces
|
2025-02-25 3:24:36 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
|
2025-02-25 3:24:36 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
|
2025-02-25 3:24:36 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
|
2025-02-25 3:24:36 0 [Note] InnoDB: log sequence number 49148; transaction id 16
|
2025-02-25 3:24:36 0 [Note] InnoDB: Loading buffer pool(s) from /build/mysql-test/var/3/mysqld.1/data/ib_buffer_pool
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_CMP' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'user_variables' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'unix_socket' is disabled.
|
2025-02-25 3:24:36 0 [Note] Plugin 'wsrep_provider' is disabled.
|
2025-02-25 3:24:36 0 [Note] InnoDB: Buffer pool(s) load completed at 250225 3:24:36
|
2025-02-25 3:24:36 0 [Warning] /build/sql/mariadbd: unknown variable 'loose-feedback-debug-startup-interval=20'
|
2025-02-25 3:24:36 0 [Warning] /build/sql/mariadbd: unknown variable 'loose-feedback-debug-first-interval=60'
|
2025-02-25 3:24:36 0 [Warning] /build/sql/mariadbd: unknown variable 'loose-feedback-debug-interval=60'
|
2025-02-25 3:24:36 0 [Warning] /build/sql/mariadbd: unknown option '--loose-pam-debug'
|
2025-02-25 3:24:36 0 [Warning] /build/sql/mariadbd: unknown option '--loose-aria'
|
2025-02-25 3:24:36 0 [Warning] /build/sql/mariadbd: unknown variable 'loose-debug-sync-timeout=300'
|
2025-02-25 3:24:36 0 [Note] Server socket created on IP: '127.0.0.1'.
|
2025-02-25 3:24:36 0 [Note] mariadbd: Event Scheduler: Loaded 0 events
|
2025-02-25 3:24:36 0 [Note] /build/sql/mariadbd: ready for connections.
|
Version: '12.0.0-MariaDB-log' socket: '/build/mysql-test/var/tmp/3/mysqld.1.sock' port: 19180 Source distribution
|
Uninitialized bytes in pwrite64 at offset 496 inside [0x7f152b600200, 512)
|
==23818==WARNING: MemorySanitizer: use-of-uninitialized-value
|
#0 0x55ff2fba931d in SyncFileIO::execute_low(IORequest const&, long) /source/storage/innobase/os/os0file.cc:671:10
|
#1 0x55ff2fba931d in SyncFileIO::execute(IORequest const&) /source/storage/innobase/os/os0file.cc:694:18
|
#2 0x55ff2fbb4332 in os_file_io(IORequest const&, int, void*, unsigned long, unsigned long, dberr_t*) /source/storage/innobase/os/os0file.cc:2537:34
|
#3 0x55ff2fbabf21 in os_file_pwrite(IORequest const&, int, unsigned char const*, unsigned long, unsigned long, dberr_t*) /source/storage/innobase/os/os0file.cc:2612:20
|
#4 0x55ff2fbabf21 in os_file_write_func(IORequest const&, char const*, int, void const*, unsigned long, unsigned long) /source/storage/innobase/os/os0file.cc:2641:20
|
#5 0x55ff2fb2a422 in log_t::resize_write_buf(unsigned char const*, unsigned long) /source/storage/innobase/log/log0log.cc:982:3
|
#6 0x55ff2e291a2a in unsigned long log_t::write_buf<(log_t::resizing_and_latch)2>() /source/storage/innobase/log/log0log.cc:1095:7
|
#7 0x55ff2e291a2a in log_writer_resizing() /source/storage/innobase/log/log0log.cc:1207:18
|
#8 0x55ff2fb27d7b in log_write_up_to(unsigned long, bool, completion_callback const*) /source/storage/innobase/log/log0log.cc:1183:43
|
#9 0x55ff2feaacac in log_checkpoint_low(unsigned long, unsigned long) /source/storage/innobase/buf/buf0flu.cc:1969:3
|
#10 0x55ff2fea5ae8 in buf_flush_page_cleaner() /source/storage/innobase/buf/buf0flu.cc:2496:11
|
#11 0x55ff2feb301e in decltype(std::declval<void (*)() noexcept>()()) std::__1::__invoke[abi:ne200100]<void (*)() noexcept>(void (*&&)() noexcept) /usr/lib/llvm-20/bin/../include/c++/v1/__type_traits/invoke.h:179:25
|
#12 0x55ff2feb301e in void std::__1::__thread_execute[abi:ne200100]<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)() noexcept>(std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)() noexcept>&, std::__1::__tuple_indices<...>) /usr/lib/llvm-20/bin/../include/c++/v1/__thread/thread.h:199:3
|
#13 0x55ff2feb301e in void* std::__1::__thread_proxy[abi:ne200100]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)() noexcept>>(void*) /usr/lib/llvm-20/bin/../include/c++/v1/__thread/thread.h:208:3
|
#14 0x7f153f49d1c3 (/lib/x86_64-linux-gnu/libc.so.6+0x891c3) (BuildId: c047672cae7964324658491e7dee26748ae5d2f8)
|
#15 0x7f153f51d85b (/lib/x86_64-linux-gnu/libc.so.6+0x10985b) (BuildId: c047672cae7964324658491e7dee26748ae5d2f8)
|
|
|
Memory was marked as uninitialized
|
#0 0x55ff2e3dd63d in __msan_allocated_memory (/build/sql/mariadbd+0x83663d) (BuildId: 295d003ebc92aa33073be236574106f7ec768a8b)
|
#1 0x55ff2fb290f6 in log_t::resize_start(unsigned long) /source/storage/innobase/log/log0log.cc:651:11
|
#2 0x55ff2fa652f9 in innodb_log_file_size_update(THD*, st_mysql_sys_var*, void*, void const*) /source/storage/innobase/handler/ha_innodb.cc:18627:21
|
#3 0x55ff2e83263f in sys_var_pluginvar::global_update(THD*, set_var*) /source/sql/sql_plugin.cc:3691:3
|
#4 0x55ff2e52f055 in sys_var::update(THD*, set_var*) /source/sql/set_var.cc:211:12
|
#5 0x55ff2e53334d in set_var::update(THD*) /source/sql/set_var.cc:871
|
#6 0x55ff2e532623 in sql_set_variables(THD*, List<set_var_base>*, bool) /source/sql/set_var.cc:752:20
|
#7 0x55ff2e7c4cdc in mysql_execute_command(THD*, bool) /source/sql/sql_parse.cc:4884:9
|
#8 0x55ff2e7b1cce in mysql_parse(THD*, char*, unsigned int, Parser_state*) /source/sql/sql_parse.cc:7915:18
|
#9 0x55ff2e7ab078 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /source/sql/sql_parse.cc:1902:7
|
#10 0x55ff2e7b2dba in do_command(THD*, bool) /source/sql/sql_parse.cc:1415:17
|
#11 0x55ff2ec03dec in do_handle_one_connection(CONNECT*, bool) /source/sql/sql_connect.cc:1415:11
|
#12 0x55ff2ec03891 in handle_one_connection /source/sql/sql_connect.cc:1327:5
|
#13 0x55ff2f8127a4 in pfs_spawn_thread /source/storage/perfschema/pfs.cc:2198:3
|
#14 0x7f153f49d1c3 (/lib/x86_64-linux-gnu/libc.so.6+0x891c3) (BuildId: c047672cae7964324658491e7dee26748ae5d2f8)
|
|
|
SUMMARY: MemorySanitizer: use-of-uninitialized-value /source/storage/innobase/os/os0file.cc:671:10 in SyncFileIO::execute_low(IORequest const&, long)
|
Exiting
|
250225 3:24:37 [ERROR] /build/sql/mariadbd got signal 6 ;
|
Attachments
Issue Links
- relates to
-
MDBF-793 Retire MSAN clang-15 builder, upgrade to clang-19
-
- In Progress
-
Activity
Thanks to a shared rr replay debugging session today, we figured out that the problem is incorrect MemorySanitizer (or Valgrind) instrumentation:
diff --git a/storage/innobase/log/log0log.cc b/storage/innobase/log/log0log.cc
|
index d35f66a78ec..970c2ca1a1d 100644
|
--- a/storage/innobase/log/log0log.cc
|
+++ b/storage/innobase/log/log0log.cc
|
@@ -1043,13 +1043,13 @@ lsn_t log_t::write_buf() noexcept
|
This block will be overwritten later, once records beyond
|
the current LSN are generated. */
|
MEM_MAKE_DEFINED(buf + length, (write_size_1 + 1) - new_buf_free);
|
+ MEM_MAKE_DEFINED((re_write_buf ? re_write_buf : buf) + length,
|
+ (write_size_1 + 1) - new_buf_free);
|
buf[length]= 0; /* allow recovery to catch EOF faster */
|
length&= ~write_size_1;
|
memcpy_aligned<16>(flush_buf, buf + length, (new_buf_free + 15) & ~15);
|
if (UNIV_LIKELY_NULL(re_write_buf))
|
{
|
- MEM_MAKE_DEFINED(re_write_buf + length, (write_size_1 + 1) -
|
- new_buf_free);
|
memcpy_aligned<16>(resize_flush_buf, re_write_buf + length,
|
(new_buf_free + 15) & ~15);
|
re_write_buf[length + new_buf_free]= 0; |
The problem is that both MEM_MAKE_DEFINED need to know the original length. In the case that we debugged, length was originally 512+16 but then modified to 512, leaving the last 16 bytes marked as uninitialized.
Yes, the code is intentionally writing up to log_sys.write_size - 2 bytes of garbage to the last block of ib_logfile0 and ib_logfile101. Only the first byte of the "garbage area" will be initialized to 0 in order to ensure that recv_sys_t::parse() will correctly detect the end of the log. We avoid zero-filling all of the garbage area (random copies of previously written log snippets) for performance reasons.
In summary, this was only a bug in the MemorySanitizer and Valgrind instrumentation, affecting only this test.
For some reason, the MEM_MAKE_DEFINED(re_write_buf …) in log_t::write_buf<resizing=RESIZING>() does not have the desired effect. Which part of the write request does it cover? The complaint is:
Uninitialized bytes in pwrite64 at offset 496 inside [0x7f152b600200, 512)The last 16 bytes of the 512-byte block are claimed to be uninitialized. Could those bytes have been copied from another buffer in log_t::write_buf<RESIZING>()? If yes, where were those bytes originally marked as uninitialized?
Are you able to reproduce this with ./mtr --rr? That would ease debugging. If this is not amenable to testing with rr, I would suggest to add some debug output, including invocations of __msan_print_shadow(ptr, size).