log_t::append_prepare_wait(): Bogus assertion ‘… < buf_size’

janlindstrom notified me that some InnoDB tests fail on a CentOS 7 based Amazon EC2 instance. I have seen such failures also on the Microsoft Windows debug target on https://buildbot.mariadb.org.

I am able to reproduce the failure in an environment by making mysql-test/var a symbolic link to a directory on SATA storage and running the default test suites. Running some of the failed tests in isolation is not sufficient; this really needs some concurrency. I am afraid that this bug will be very hard to reproduce under rr replay, but I am also afraid that we’d need to attempt exactly this. For debugging this based on a core dump, I applied the following patch:

diff --git a/storage/innobase/mtr/mtr0mtr.cc b/storage/innobase/mtr/mtr0mtr.cc

index 450debc8fbd..e9374dfa653 100644

--- a/storage/innobase/mtr/mtr0mtr.cc

+++ b/storage/innobase/mtr/mtr0mtr.cc

@@ -877,7 +877,7 @@ ATTRIBUTE_COLD static void log_overwrite_warning(lsn_t lsn)

                   ? ". Shutdown is in progress" : "");

 }

-ATTRIBUTE_COLD void log_t::append_prepare_wait(bool late, bool ex) noexcept

+__attribute__((optimize(0))) ATTRIBUTE_COLD void log_t::append_prepare_wait(bool late, bool ex) noexcept

 {

   if (UNIV_LIKELY(!ex))

   {

@@ -915,6 +915,7 @@ ATTRIBUTE_COLD void log_t::append_prepare_wait(bool late, bool ex) noexcept

   else

   {

   got_ex:

+    std::atomic_thread_fence(std::memory_order_seq_cst);

     const uint64_t l= write_lsn_offset.load(std::memory_order_relaxed);

     const lsn_t lsn{base_lsn.load(std::memory_order_relaxed)};

     ut_d(lsn_t ll= lsn + (l & (WRITE_BACKOFF - 1)));

The second hunk is a hack to see if the problem would go away. It did not. The first hunk is specific to GCC; the Clang equivalent attribute would be optnone.

It’s worth noting that the data member log_sys.write_lsn is stored in a different cache line from the other data members that are involved: (log_sys.latch), log_sys.base_lsn, log_sys.write_lsn_offset. The log_sys.write_size is constant after server startup; it should not matter here. In my test environment, its value was 4096.

The failure probability might have become lower, but the failure still occurred in one test. I have carefully reviewed the generated machine code for this section, and it corresponds to my intention in the C++ code. The debug assertion expression would hold in the core dump. The log_sys.buf_size was at its default value 0x20000 (2 MiB), and the left-hand-side of the < expression when evaluated from the data in the core dump always was less than log_sys.write_bytes below that.

There is a chance that there is no impact of this race condition on non-debug builds, but I think that we must understand this to the deepest level to rule out any possible reincarnation of a bug like MDEV-34689.