Linux Ubuntu 20.04 LTS

It is a very serious error if the circular log file overwrites itself. Such an overwrite means that crash recovery is not guaranteed to succeed. Recovery could end in a state where some InnoDB data pages correspond to a newer point of time than other pages. That in turn could cause various consistency issues, such as crashes when some pointers between data pages are wrong.

It is better to avoid killing the server and try to rescue the situation by initiating furious flushing and a log checkpoint. With luck, the server will not be killed before the log checkpoint is advanced and the log gets into a healthy state again.

wlad changed slow shutdown in MariaDB Server 10.5 so that it will use the maximum number of purge tasks. This might cause the log file overflow.

cedric, if you are using the default innodb_page_size=16k, the 32388×100/25×innodb_page_size should correspond to around innodb_buffer_pool_size=12G. Have you tried making the innodb_log_file_size about the same size as the buffer pool, or even bigger? Recovery should not run out of memory in MariaDB Server 10.5 or later. In recovery, if the redo log records occupy ⅓ of the buffer pool, a new recovery batch will be started. A large redo log can signficantly reduce the frequency of checkpoints and data page writes.

Yes, my innodb_page_size is set to 16384, and I think you meant to type 2G instead of 12G. My innodb_buffer_pool_size is 2G, which is 32388×100/25×16K.

I will try increasing the log file size to match or exceed the buffer pool size. I'll report back when I get a chance to perform that experiment.

Surely though, InnoDB is designed such that it would never allow a transaction to be committed and for a buffer page to become marked as dirty if there is no space in the redo log to ensure the DB is in a crash-proof state? Wouldn't InnoDB freeze up until the redo logs have been flushed a little before allowing the redo log to overflow and lose data?

It's also confusing that in the error log I've pasted, the age of the last checkpoint is reported as increasing every 15 seconds until the shutdown succeeds. I wonder if there is some kind of bug in the shutdown code.

Note that this is a slave DB, and prior to the shutdown that produced the errors, the 'stop slave' command was issued. I wonder if some binary logs from the master were still being processed by the slave prior to the shutdown command being issued, causing some kind of issue during shutdown.

FYI I just tried the ''SET GLOBAL innodb_fast_shutdown = 0; shutdown;" again on that same database, and it completed without errors. It's only been 4 days since I last did the shutdown, which was done because I was upgrading from 10.6.3 to 10.6.5.

Therefore either this is an intermittent problem, or it is a problem that affects 10.6.3 but not 10.6.5. I'll report back here if I'm able to reproduce the problem in the future.

What is the best way to check whether the slave did not lose any data during the earlier shutdown that reported errors? I'd like to try comparing the slave data with the master somehow to see if the slave is a proper replica of the master.

cedric, if the server was not killed, no data could have been lost. To put it bluntly, writing anything to ib_logfile0 is entirely wasted effort as long as the server keeps running normally. Only if the server process is killed for any reason, the next startup of InnoDB will need that file for ensuring that all data files will correspond to the last durably written log sequence number (the last log record that was successfully parsed from the circular log file).

By design, log overwrite errors can be very sporadic. Earlier, in MDEV-14462 I wrote the following:

There is a kind of inherent race condition between threads that do the following:

log_free_check();

mtr.start();

…

mtr.commit();

We can have N threads that successfully execute log_free_check(), noting that there is enough free space in the redo log. Then, each thread could generate redo log, and at mtr_t::commit() attempt to write that log to the global buffer. If each concurrent thread generates the worst-case amount of log (say, each one is splitting a very high B-tree from the leaf to the root, rewriting about 64 pages), each thread could be attempting to write 64*16KiB=1MiB of redo log. So, should we ensure that N*1MiB will be available in the redo log before the checkpoint will be overwritten? In some setups, this is reasonable, but it could be a serious overkill for smaller server instances.

monty suggested an idea that goes roughly like this:

• If innodb_log_file_size is large enough, retain the current logic. That is, assume that between log_free_check() and mtr_t::commit() it is impossible for the log to overrun.
• For smaller log files, in each log_free_check(), reserve space (or increment an atomic counter), and release it after the log was written in mtr_t::commit().

How large is ‘large enough’? There may be at most 8×innodb_page_size active transactions (524,288 when using innodb_page_size=64k). There may also be 32 purge threads, and up to 255 fil_crypt_thread. In the worst case, each thread may be splitting a B-tree to its maximum height of 31 or 32 nodes, that is, modify roughly 64 pages and write up to roughly 32×innodb_page_size bytes of log.

Rounding up, the ‘large enough’ log file should be something like 9×innodb_page_size×32×innodb_page_size = 288×innodb_page_size×innodb_page_size. That would range from 4.5 GiB to 1,152 GiB. At the default innodb_page_size=16k, this ‘large enough’ estimate would be 72 GiB.

Even though this estimate might feel like an overestimate, it may in fact be an underestimate. We assumed that each of the concurrent threads would run only once. But, it is possible that on such a heavily loaded system, some threads are starved of CPU resources for an extended period of time while other threads are scheduled to run multiple mtr_t::commit() each. One of those starved threads could already have acquired a latch on the oldest modified page, and the log_free_check() from other threads would not be able to advance the checkpoint. Eventually, all subsequent threads would end up waiting in log_free_check() and the starved threads would be allowed to proceed to release the page latches, which would allow the checkpoint to be completed. During such a glitch it is possible that the log was momentarily overrun.

So, there does not exist any ‘large enough’ innodb_log_file_size that can guarantee to avoid the race condition between log_free_check() and mtr.commit(). We could only reduce the probability to very close to 0, which is already the case for well configured installations. Besides, 72 GiB is already a quite large redo log. Even with innodb_buffer_pool_size=128G it could be perfectly reasonable to use a much smaller innodb_log_file_size, especially when page splits are rare.

Practically, if we wanted to completely avoid the log overrun condition, we practically would have to implement some additional locking. Based on some experience with MDEV-25062, I expect that an innocent-looking std::atomic::fetch_add() call for updating a global variable will seriously degrade throughput. Even when using numactl to ensure that the server runs on a single NUMA node, the AMD64 LOCK XADD instruction for trx_sys.rseg_history_len++ consumed several per cent of all CPU cycles during my simple benchmark. If we added anything like that to log_free_check(), the impact should be much bigger, because every write transaction consists of multiple mini-transactions.

What if we implemented the extra locking only for the cases where a mini-transaction is expected to split or merge pages? That would still leave a small probability of log overrun due to threads being scheduled ‘unfairly’ on a heavily loaded system.

?? if the server was not killed, no data could have been lost??

marko I think therefore you're saying that if it says "shutdown complete", I should ignore the error. I'm guessing the reason that this still needs to be listed as an ERROR in the logs is because if the shutdown did not complete successfully, then the ERROR would be there to let me know that my DB has lost data and thus I need to restore from backup?

A user got these messages during a shutdown with innodb_fast_shutdown=0 when testing a misconfigured system (tiny innodb_log_file_size and innodb_buffer_pool_size=22G). I am quoting the relevant server log messages:

2022-10-24 23:20:16 0 [Note] InnoDB: FTS optimize thread exiting.

2022-10-24 23:20:16 0 [Note] InnoDB: to purge 5 transactions

2022-10-24 23:20:17 0 [Note] InnoDB: Starting shutdown...

2022-10-24 23:20:17 0 [Note] InnoDB: Dumping buffer pool(s) to /data/maria_data/ib_buffer_pool

2022-10-24 23:20:17 0 [Note] InnoDB: Restricted to 354860 pages due to innodb_buf_pool_dump_pct=25

2022-10-24 23:20:17 0 [Note] InnoDB: Buffer pool(s) dump completed at 221024 23:20:17

2022-10-24 23:57:37 0 [ERROR] InnoDB: The age of the last checkpoint is 966373838, which exceeds the log capacity 966365799.

2022-10-24 23:57:53 0 [ERROR] InnoDB: The age of the last checkpoint is 974973721, which exceeds the log capacity 966365799.

2022-10-24 23:58:09 0 [ERROR] InnoDB: The age of the last checkpoint is 983054253, which exceeds the log capacity 966365799.

2022-10-24 23:58:25 0 [ERROR] InnoDB: The age of the last checkpoint is 991661268, which exceeds the log capacity 966365799.

...

2022-10-25  2:02:57 0 [ERROR] InnoDB: The age of the last checkpoint is 4351924949, which exceeds the log capacity 966365799.

221025 02:03:48 mysqld_safe Starting mariadbd daemon with databases from /data/maria_data

...

2022-10-25  2:03:49 0 [ERROR] InnoDB: Missing FILE_CHECKPOINT at 12010302916974 between the checkpoint 12009722108511 and the end 12010302916608.

According to this output, there were 5 only transactions to be purged in slow shutdown, but the slow shutdown kept running for over 2 hours until it was forcibly killed. It failed to recover from the corrupted (overwritten) log.

During a slow shutdown, writes will be caused either by merging buffered changes to secondary index leaf pages, or the purge of history of completed transactions. The change buffer was disabled by default in MDEV-27734, mainly because bug reports led me to believe that it can corrupt data and we have not been able to reproduce that. If the change buffer was disabled, then I wonder how large those 5 transactions were.

I could say more if I were able to reproduce this scenario with an executable test case (SQL workload).

If one is unlucky and InnoDB hangs (for example, due to MDEV-29835) during a time when the misconfigured redo log is in in the corrupted state, then everything can be lost. Therefore it is of paramount importance to ensure that the innodb_log_file_size has been configured to be large enough. It would be nice if correlated parameters (such as innodb_buffer_pool_size and innodb_log_file_size) could be configured automatically based on a smaller number of parameters (MDEV-19895).

An unreasonably small redo log will cause hugely degraded write performance, because it will trigger more frequent log checkpoints, which involves writing changed pages from the buffer pool pages to the data files. Starting with 10.5 and MDEV-21351, InnoDB crash recovery should work reliably even if the redo log is much larger than the buffer pool. I recommend reading a recent blog post by mdcallag.

I filed MDEV-29905 for missing log_free_check() calls in change buffer operations. I think that it fully explains the reported corruption. According to the messages, the circular log had been overwritten astonishing 4½ times since the previous checkpoint. Even a single overwrite can be disastrous.

Unfortunately, this issue evolved from the original bug report into a discussion of log overwriting in InnoDB.

The originally reported behavior is clearly not a bug. Log overwriting in InnoDB is a serious error and it is and should be reported as an [ERROR] not as a [Warning].

As for the actual log overwriting, it, of course, shouldn't be happening. MDEV-29905 fixes a bug that was causing it. At least, it was one of the reasons. If there are more and you'll see this error after MDEV-29905 is fixed, please, open a new issue for it.