Digging into MariaDB's Source 12: Two Logs — the Redo Log, the Binlog and Crash Recovery, and Wrapping Up

What this post covers

This is the twelfth and final part of "Digging into MariaDB's Source". In part 11 we watched InnoDB carry a transaction around as a trx_t, build old versions of rows from undo (MVCC) and keep writers apart with locks. All of that was a story inside memory. This post zooms into the COMMIT at the end of ⑥ Execution on the part 2 map, and into leaving things on disk, at the very bottom of the ⑧ Engine box. It is the machinery that makes committed work survive a sudden crash and uncommitted work disappear.

The blue boxes are what this post reads.

There are three questions to answer.

• When COMMIT returns "OK", what is on disk? Where in the source do the values 0, 1 and 2 of innodb_flush_log_at_trx_commit part ways?
• When the server dies from kill -9, what does it do when it comes back? Who removes the uncommitted rows?
• InnoDB already has a redo log, so why is there a binlog as well, and how are the two kept from disagreeing?

Every line number in this post refers to that commit. Part 1 explains how to get the source at the same commit and build the Docker image used for the examples.

sql/log.cc alone is over 15,000 lines, and InnoDB's log and recovery code (log0log.cc, log0recv.cc) adds close to 9,000 more. This post keeps only the main thread that someone seeing the code for the first time can follow. What was left out is named, with its location, under "What this post leaves out" at the end.

Words to know first

Redo log. Every time InnoDB changes a page, it also writes down "these bytes at this offset of this page were changed like this" in a separate file (ib_logfile0). The changed page stays in memory (the buffer pool, part 10) to be written later; only the log goes to disk first. This approach is commonly called WAL (write-ahead logging: write the log first). If the server dies, it reads this log again and fixes the pages up. Because it "does the change again", it is called redo.

LSN (log sequence number). A 64-bit number that names a position in the redo log. Think of it as a clock that counts how many bytes of log have been written. It grows by the length of every record appended, and every page carries in its header (FIL_PAGE_LSN) "the LSN of the log that last changed me". The Log sequence number in SHOW ENGINE INNODB STATUS is this number.

mtr (mini-transaction). A small unit that changes a few pages atomically. Even inserting one row changes a B-tree page and an undo page together; those changes are grouped into one mtr_t and logged "all or nothing". We met it with page latches in part 10. One SQL transaction is made of many mtrs.

Checkpoint. A mark that says "every page changed by the log before this LSN has been written to the data files". Recovery only has to read the log from the checkpoint on, and the log space before the checkpoint may be reused.

Undo. Records of the values rows had before they were changed. In part 11 we saw them used for MVCC and rollback. Undo lives in pages too, so changing an undo page is itself recorded in the redo log. That fact matters a lot in this post.

Binlog (binary log) and events. The log written by the server layer (sql/). Independently of the engine, it records "which SQL was run, which rows changed and how" as events (Log_event). It is used for replication (a replica receives it and re-executes it) and point-in-time recovery. It is on only when you pass --log-bin.

XA, two-phase commit, XID. A way to commit a transaction that has two or more participants together. First everyone is told "get ready to commit (prepare)", and once all are ready, "commit". The number that names the transaction meanwhile is the XID. Inside MariaDB, InnoDB and the binlog are the two participants.

handlerton and transaction_participant. The function table that represents one engine is the handlerton (part 2); its parent struct, which holds only the transaction functions such as commit, rollback and prepare, is transaction_participant. The binlog is not an engine, but it joins transactions as a transaction_participant (section 5).

1. Why a separate log — pages later, log first

Changing a row makes InnoDB change a 16KB page in the buffer pool (part 10). If every commit wrote all the changed pages to the data files, changing a few rows would mean writing several scattered pages all over the disk. Instead InnoDB appends just the changed bytes to the end of one file. Appending is fast, and the amount appended is far smaller than the pages. The pages stay in memory marked "dirty" and are written out later, separately.

Everything about this log lives in one global object, log_sys (log0log.h lines 760–761). Here are only the fields this post keeps coming back to.

  /** The current log sequence number, relative to base_lsn, and flags;
  may be modified while latch_have_any() */
  alignas(CPU_LEVEL1_DCACHE_LINESIZE)
  Atomic_relaxed<uint64_t> write_lsn_offset;
  /** the LSN of the last write_buf() or persist(); protected by latch */
  std::atomic<lsn_t> base_lsn;
  /** the first guaranteed-durable log sequence number */
  std::atomic<lsn_t> flushed_to_disk_lsn;
  // ...
  /** log record buffer, written to by mtr_t::commit() */
  alignas(CPU_LEVEL1_DCACHE_LINESIZE) byte *buf;
  // ...
  /** Last written LSN; protected by latch */
  lsn_t write_lsn;
  // ...
  /** latest completed checkpoint (protected by latch.wr_lock()) */
  Atomic_relaxed<lsn_t> last_checkpoint_lsn;

storage/innobase/include/log0log.h lines 172–288

Four LSNs appear. In order of size:

last_checkpoint_lsn ≤ flushed_to_disk_lsn ≤ write_lsn ≤ get_lsn(). You could say this whole post is about when each of these four numbers moves forward. The status variable names are at ha_innodb.cc lines 1050–1053.

The top half is the connection thread's work; the bottom half is done separately by the page cleaner thread.

mtr_t::commit() — appending to the log buffer

Log records go to the log buffer all at once when an mtr ends.

void mtr_t::commit()
{
  // ...
  if (m_modifications && (m_log_mode == MTR_LOG_NO_REDO || !m_log.empty()))
  {
    if (UNIV_UNLIKELY(!is_logged()))
    {
      release_unlogged();
      goto func_exit;
    }

    ut_ad(!srv_read_only_mode);
    ut_ad(!recv_sys.rpo);
    std::pair<lsn_t,lsn_t> lsns{do_write()};
    process_freed_pages();
#ifdef HAVE_PMEM
    commit_logger(this, lsns);
#else
    commit_log<false>(this, lsns);
#endif
  }

storage/innobase/mtr/mtr0mtr.cc lines 534–560

do_write() copies the records the mtr has collected (m_log) into the log buffer (the first value of the pair it returns is the mtr's start LSN; the second is the result of log_close(), which we meet in section 3), and commit_log() takes care of the pages. The function that reserves the room to copy into is log_t::append_prepare().

template<log_t::write mode>
inline
std::pair<lsn_t,byte*> log_t::append_prepare(size_t size, bool ex) noexcept
{
  // ...
  uint64_t l;
  static_assert(WRITE_TO_BUF == WRITE_BACKOFF << 1, "");
  while (UNIV_UNLIKELY((l= write_lsn_offset.fetch_add(size + WRITE_TO_BUF) &
                        (WRITE_TO_BUF - 1)) >=
                       (mode ? capacity() : buf_size) - size))
  {
    // ...
    bool late(write_lsn_offset.fetch_or(WRITE_BACKOFF) & WRITE_BACKOFF);
    /* Subtract our LSN overshoot. */
    write_lsn_offset.fetch_sub(size);
    append_prepare_wait(late, ex);
  }

  const lsn_t lsn{l + base_lsn.load(std::memory_order_relaxed)};
  return {lsn,
          buf + size_t(mode ? FIRST_LSN + (lsn - first_lsn) % capacity() : l)};
}

storage/innobase/mtr/mtr0mtr.cc lines 1060–1088

Two things stand out.

1. An LSN is a byte count. fetch_add(size + …) grows write_lsn_offset by the record length, and the old value l plus base_lsn is this mtr's start LSN. Even when many threads arrive at once, each gets its own spot with a single atomic add, so they do not wait on each other long while reserving buffer space.
2. When the buffer is full, they wait. If the room needed exceeds buf_size (= innodb_log_buffer_size, 16MB by default — see the output of example 1), the thread goes to append_prepare_wait(). One thread writes the buffer out to the file with log_write_up_to(lsn, false) and the others wait meanwhile (lines 984–1053). The status variable Innodb_log_waits counts these waits (ha_innodb.cc line 1047).

After copying, commit_log() writes the mtr's end LSN into the header of every page it changed and puts the page on the buffer pool's flush list (the list of dirty pages waiting their turn to be written) (mtr0mtr.cc lines 446–450). The FIL_PAGE_LSN in the page header is the very 8 bytes we read with od from an .ibd file in part 10. During recovery this value tells InnoDB "this page already contains the log up to this LSN".

Easy to get wrong: an mtr commit is not a transaction commit

The names are the same, which is confusing, but mtr_t::commit() writes nothing to disk. It only copies records into the in-memory log buffer and marks pages dirty. Even a single INSERT statement commits several mtrs, and that log is still only in memory. Asking for the log to be written to the file is the job of the SQL transaction's COMMIT (section 2). Conversely, the changes of an uncommitted transaction are already in the log buffer, mtr by mtr, so when another transaction's commit writes the buffer to the file, they go to disk along with it. The crash example in section 4 stands on this fact.

2. Where COMMIT reaches the disk — log_write_up_to and innodb_flush_log_at_trx_commit

When a transaction commits, InnoDB asks for the log up to that transaction's commit record to be in the file. With the binlog off, the path is this: the server layer's ha_commit_trans() calls InnoDB's innobase_commit() (part 11), which commits the transaction in memory and at the end calls trx_commit_complete_for_mysql() (ha_innodb.cc line 4816).

void trx_commit_complete_for_mysql(trx_t *trx)
{
  const lsn_t lsn= trx->commit_lsn;
  if (!lsn)
    return;
  switch (srv_flush_log_at_trx_commit) {
  case 0:
    goto func_exit;
  case 1:
    if (trx->active_commit_ordered && trx->active_prepare)
      return;
  }
  trx_flush_log_if_needed(lsn, trx);
 func_exit:
  trx->commit_lsn= 0;
}

storage/innobase/trx/trx0trx.cc lines 1776–1791

srv_flush_log_at_trx_commit is innodb_flush_log_at_trx_commit from my.cnf. With 0 it returns without doing anything. The line that returns for 1 when active_commit_ordered && active_prepare is a binlog-on story, so we come back to it in section 6. Everything else goes to trx_flush_log_if_needed().

static void trx_flush_log_if_needed(lsn_t lsn, trx_t *trx)
{
  // ...
  if (log_sys.get_flushed_lsn(std::memory_order_relaxed) >= lsn)
    return;

  ut_ad(!trx->read_only);

  const bool flush= srv_flush_log_at_trx_commit & 1;
  if (!log_sys.is_mmap())
  {
    completion_callback cb;

    if ((cb.m_param= thd_increment_pending_ops(trx->mysql_thd)))
    {
      cb.m_callback= thd_decrement_pending_ops;
      log_write_up_to(lsn, flush, &cb);
      return;
    }
  }
  trx->op_info= "flushing log";
  log_write_up_to(lsn, flush);
  trx->op_info= "";
}

storage/innobase/trx/trx0trx.cc lines 1284–1309

The single line flush = srv_flush_log_at_trx_commit & 1 separates 1 and 3 (odd) from 2 (even). Odd means durable=true, "all the way to fsync"; 2 means durable=false, "only write to the file". If the log is already fsynced up to that LSN (get_flushed_lsn() >= lsn), nothing happens. The path with cb (a callback) is how the thread pool (part 4) avoids having a connection thread sit on an fsync. While a commit waits, trx_operation_state in information_schema.INNODB_TRX shows flushing log because of the two lines that change op_info (trx0i_s.cc line 446).

log_write_up_to — one thread writes, the rest ride along

void log_write_up_to(lsn_t lsn, bool durable,
                     const completion_callback *callback) noexcept
{
  // ...
repeat:
  if (durable)
  {
    if (flush_lock.acquire(lsn, callback) != group_commit_lock::ACQUIRED)
      return;
    /* Promise to other concurrent flush_lock.acquire() that we
    will be durable at least up to the current LSN. The LSN may still
    advance when we acquire log_sys.latch below. */
    if (lsn > log_sys.get_flushed_lsn())
      flush_lock.set_pending(lsn);
  }

  lsn_t pending_write_lsn= 0, pending_flush_lsn= 0, flush_ahead= 0;

  if (write_lock.acquire(lsn, durable ? nullptr : callback) ==
      group_commit_lock::ACQUIRED)
  {
    ut_ad(!recv_no_log_write || srv_operation != SRV_OPERATION_NORMAL);
    log_sys.latch.wr_lock();
    // ...
    pending_write_lsn= write_lock.release(log_sys.writer());
  }

  if (durable)
    pending_flush_lsn= log_flush(write_lock.value());
  // ...
}

storage/innobase/log/log0log.cc lines 1837–1899

write_lock and flush_lock are not ordinary mutexes but a special lock called group_commit_lock (log0sync.h). acquire(lsn) means "if someone has already written up to that LSN, return EXPIRED (nothing to do); otherwise take the lock and return ACQUIRED". If another thread holds the lock and is writing, the caller waits for that to finish and decides again; when a callback was passed, it may instead leave the callback queued and return CALLBACK_QUEUED without waiting. So even when ten threads commit at once, only the one holding the lock actually does write() and fsync(); it writes all the log accumulated so far in one go, and the others see that their LSN has already been covered and simply return. This is InnoDB's own group commit. The binlog has a separate group commit built on the same idea (section 6).

log_sys.writer() leads to log_t::write_buf(), which pwrites the buffer to ib_logfile0, and log_flush() calls log_t::flush() (lines 1802–1813) to fsync. Only after the fsync does flushed_to_disk_lsn move forward. If log_write_through is true, though (the file is opened with O_DSYNC, so write() itself goes all the way to the disk), the fsync is skipped. At the reference commit this is true when innodb_flush_method=O_DSYNC (ha_innodb.cc lines 4174–4176).

Who writes for 0 and 2 — the master callback that runs every second

With 0, commit writes nothing; with 2, it does not fsync. A background job that runs every second covers for them.

static void srv_sync_log_buffer_in_background()
{
	time_t	current_time = time(NULL);

	srv_main_thread_op_info = "flushing log";
	if (difftime(current_time, srv_last_log_flush_time)
	    >= srv_flush_log_at_timeout) {
		log_buffer_flush_to_disk();
		srv_last_log_flush_time = current_time;
		srv_log_writes_and_flush++;
	}
}

storage/innobase/srv/srv0srv.cc lines 1236–1247

The timer job srv_master_callback(), which runs every 1000ms (srv0start.cc lines 2002–2003), calls this function (line 1334), and once innodb_flush_log_at_timeout (1 second by default) has passed it writes and fsyncs with log_buffer_flush_to_disk() — that is, log_write_up_to(current LSN, durable=true). The variable's help text (ha_innodb.cc lines 19687–19699) sums up what the four values mean. As a table (the default is 1):

The reason 2 "loses nothing if only mariadbd dies" is that data whose write() has finished stays in the operating system's page cache even if the process dies, and is eventually written to disk. If the operating system or the power goes too, that cache is gone. That is why, if you start the server with 2, InnoDB deliberately keeps the operating system cache on for the log file (log_sys.log_buffered= true, ha_innodb.cc lines 4204–4207). Changing it at run time with SET GLOBAL does not redo that adjustment (the variable has no function to call when its value changes — the NULL, NULL on line 19699).

Example 1: how many log writes per setting

We switched innodb_flush_log_at_trx_commit from 1 → 2 → 0 and counted how much the status variables grew while sending 200 one-row autocommit INSERTs. This and every other example in the post was run on MariaDB 13.2.0 (13.2.0-MariaDB-debug), a Debug build of the reference commit (c894d97781) as is, in a Docker container (Ubuntu 24.04). The example folder is ex/u12-flush-log.

# An example written for this post (not MariaDB source)
# ... (starting the server, creating the table and printing five settings omitted)
for v in 1 2 0; do
  mariadb -e "SET GLOBAL innodb_flush_log_at_trx_commit=$v"
  # ... (read three status variables before and after, print the difference)
  # send 200 INSERTs over one connection so that each statement is its own (autocommit) transaction
  for i in $(seq 1 200); do echo "INSERT INTO lab.t VALUES ($((base+i)), 'row');"; done | mariadb
done
# ... (printing the LSNs twice, a clean shutdown and opening ib_logfile0 with od omitted)

innodb_flush_method	O_DIRECT
innodb_log_buffer_size	16777216
innodb_log_file_size	100663296
innodb_flush_log_at_trx_commit	1
innodb_flush_log_at_timeout	1
--- 200 autocommit INSERTs per setting
setting    log_writes  data_fsyncs   os_log_written
=1                201          201            66797
=2                200            0            51573
=0                  1            3            88511
--- right after the =0 run, and 2 seconds later
VARIABLE_NAME	VARIABLE_VALUE
INNODB_LSN_CURRENT	276616
INNODB_LSN_FLUSHED	261471
VARIABLE_NAME	VARIABLE_VALUE
INNODB_LSN_CURRENT	276616
INNODB_LSN_FLUSHED	276616

Innodb_log_writes is log_sys.write_to_log, the number of times write_buf() wrote to the file (ha_innodb.cc line 1049).

1. =1: about 200 writes and about 200 fsyncs for 200 commits. Each commit's log_write_up_to(lsn, true) did a write and an fsync (one connection sent them one after another, so there were no peers to group with).
2. =2: still 200 writes, but 0 fsyncs. flush & 1 was 0, so it only wrote.
3. =0: just 1 write during 200 commits. The commits wrote no log, and that one write was the once-a-second job (depending on the run you get 0 or 1). Right after the run, Innodb_lsn_flushed lagged about 15,000 bytes behind Innodb_lsn_current; two seconds later they were equal. Had a kill -9 come in between, the commits inside those 15,000 bytes would have been lost. How far it lags depends on when the once-a-second job last ran, so it differs from run to run (a re-run showed about 73,000 bytes), and if background work adds more log in the meantime, flushed can still be one step behind current two seconds later.

One odd/even bit (flush & 1) decides the fsync, and the once-a-second task picks up the rest. The numbers are Example 1's actual output; data_fsyncs also includes fsyncs of data files (see the confusing spot below).

LSNs and byte counts differ from run to run.

Easy to get wrong: what the numbers mean

• Innodb_data_fsyncs does not count only the redo log. It is os_n_fsyncs, which grows by one on every call to os_file_flush_func() or os_file_sync_posix() (os0file.cc line 835, ha_innodb.cc line 1034), so fsyncs of data files are counted too. That is why =0 shows 3 fsyncs for 1 log write (a re-run showed 0 writes and 2 fsyncs — the numbers in this row vary a little from run to run).
• Despite its name, Innodb_os_log_written is not "bytes written to the file" but lsn_current - recv_sys.lsn, i.e. how much the LSN has grown since startup (srv0srv.cc lines 961–962). That is why it grows even with =0, which wrote to the file only once. The three rows differ in size because background work also logs during the same time, so do not use this column to compare the settings.

3. ib_logfile0 and the checkpoint — reusing a circular file

There is a single redo log file, ib_logfile0, and its size is fixed by innodb_log_file_size (96MB by default in this build, the 100663296 in example 1). When the end is reached, writing wraps back to the front. These are the lines in write_buf() that decide the position in the file.

    lsn_t offset{write_lsn - first_lsn};
    if (resizing == RESIZING || !archive)
      offset%= capacity();
    offset+= START_OFFSET;

storage/innobase/log/log0log.cc lines 1696–1699

capacity() is file_size - START_OFFSET (log0log.h line 696). The first 12KB of the file (START_OFFSET = 12288) are set aside and the rest is used as a ring. Those first 12KB hold the file header and two checkpoint blocks (CHECKPOINT_1 = 4096, CHECKPOINT_2 = 8192) (log0log.h lines 153–158).

The header field positions come from log_t::header_write(), the checkpoint block fields from log_t::write_checkpoint().

The header is written by log_t::header_write() (log0log.cc lines 448–468). A checkpoint block is written like this.

  static_assert(CHECKPOINT_1 << 1 == CHECKPOINT_2, "");
  offset= CHECKPOINT_1 << (next_checkpoint_no & 1);
  c= is_mmap() ? buf + offset : checkpoint_buf;
  circular_recovery_from_sequence_bit_0= !get_sequence_bit(checkpoint);
  memset_aligned<CPU_LEVEL1_DCACHE_LINESIZE>(c, 0,
                                             CPU_LEVEL1_DCACHE_LINESIZE);
  mach_write_to_8(my_assume_aligned<8>(c), checkpoint);
  mach_write_to_8(my_assume_aligned<8>(c + 8), end_lsn);
  mach_write_to_4(my_assume_aligned<4>(c + 60), my_crc32c(0, c, 60));

storage/innobase/buf/buf0flu.cc lines 2030–2038

Depending on the last bit of the checkpoint number, it writes to 4096 and 8192 in turn. If the power goes out in the middle of writing a checkpoint and one block is torn, the other block still holds the previous checkpoint (the CRC tells which one is torn).

Example 1 (continued): opening the file directly

At the end of example 1 we shut the server down cleanly and opened three places in ib_logfile0 with od.

f=/var/lib/mariadb-lab/ib_logfile0
od -A d -t x1z -N 48 $f
od -A d -t x1 -j 4096 -N 16 $f
od -A d -t x1 -j 8192 -N 16 $f

0000000 50 68 79 73 00 00 00 00 00 00 00 00 00 00 30 00  >Phys..........0.<
0000016 4d 61 72 69 61 44 42 20 31 33 2e 32 2e 30 00 00  >MariaDB 13.2.0..<
0000032 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  >................<
0000048
0004096 00 00 00 00 00 04 38 ea 00 00 00 00 00 04 38 ea
0004112
0008192 00 00 00 00 00 04 38 88 00 00 00 00 00 04 38 88
0008208

1. The 50 68 79 73 ("Phys") at byte 0 is log_t::FORMAT_10_8 = 0x50687973 (log0log.h line 147). The 00 … 30 00 = 12288 at byte 8 is this file's first LSN, the same as FIRST_LSN when the file was created. From byte 16 the name of the server that created it is stored as a string.
2. The checkpoint LSN at 4096 is 0x438ea = 276,714 and at 8192 0x43888 = 276,616. The two blocks hold different checkpoints, and the larger one (4096) is the last one, left at shutdown. A clean shutdown writes all dirty pages and pulls the checkpoint all the way forward, so restarting from this state finds no log to recover.

The LSN values differ from run to run.

Who moves the checkpoint, and when

To move the checkpoint, every page changed by the log before it must already be in the data files. So the checkpoint LSN becomes "the LSN of the oldest dirty page left in the buffer pool".

/** Make a checkpoint. Note that this function does not flush dirty
blocks from the buffer pool: it only checks what is lsn of the oldest
modification in the pool, and writes information about the lsn in
log file. Use log_make_checkpoint() to flush also the pool.
@return the lsn to invoke log_sys.archive_create(lsn, false) on
@retval 0 if log_sys.archive_create() should not be called */
static lsn_t log_checkpoint() noexcept
{
  // ...
  log_sys.latch.wr_lock();
  const lsn_t end_lsn= log_sys.get_lsn();
  mysql_mutex_lock(&buf_pool.flush_list_mutex);
  const lsn_t oldest_lsn= buf_pool.get_oldest_modification(end_lsn);
  // FIXME: limit oldest_lsn below binlog split write LSN
  mysql_mutex_unlock(&buf_pool.flush_list_mutex);
  return log_checkpoint_low(oldest_lsn, end_lsn);
}

storage/innobase/buf/buf0flu.cc lines 2311–2342

As the comment says, log_checkpoint() writes no pages. The page cleaner thread (buf_flush_page_cleaner(), part 10) writes pages, and between batches it calls log_checkpoint() to move the checkpoint up to the LSN of the oldest dirty page (buf0flu.cc line 2904). Writing out every page and pulling the checkpoint all the way forward is log_make_checkpoint() (→ buf_flush_sync_batch(0, true), lines 3134–3137).

A circular file has one danger. If the checkpoint stays put too long, new log would overwrite old log that is still needed. log_close(), called every time an mtr appends log, watches for this. When "current LSN − last checkpoint" (the checkpoint age, Innodb_checkpoint_age) crosses a set line, it asks the page cleaner to write pages faster (buf_flush_ahead()); past a further line it sets a furious flag that makes writing threads wait (mtr0mtr.cc lines 1094–1130). That is why an innodb_log_file_size that is too small can make things suddenly slow when writes pile up.

Easy to get wrong: log_sys is full of unfamiliar names

Open log0log.h and you find names like archive, resize_log, is_mmap() and HAVE_PMEM everywhere. They belong to features added in recent versions — innodb_log_archive (a mode that keeps creating new log files instead of overwriting circularly, log_t::set_archive()), resizing the log at run time (resize_start()), and writing the log through persistent memory (PMEM) and memory mapping. This build did not enable WITH_INNODB_PMEM (CMakeLists.txt lines 431–434) and archiving is off, so this post follows only the ordinary path that pwrites through write_buf().

4. Crash recovery — forward with redo, back with undo

When you restart after kill -9 or a power loss, InnoDB does this.

The four boxes below the red one happen while InnoDB starts (srv_start()); the rest happens after the server has brought up all engines.

1. Find the checkpoint. srv_start() calls recv_sys.find_checkpoint(), which picks the latest valid one of the two checkpoint blocks (srv0start.cc line 1425).
2. Read the log. recv_recovery_from_checkpoint_start() (line 1570, defined at log0recv.cc line 5869) uses recv_scan_log() to read records from the checkpoint LSN and group them per page. If there are records after the checkpoint, it prints Starting crash recovery from checkpoint LSN=… to the error log (lines 5241–5243). The end of the records is recognized by the CRC and the sequence bit (a bit that tells whether the file has wrapped around) attached to each mtr — a half-written mtr fails its CRC, reading stops there, and that mtr is treated as if it never happened (log_parse_start(), lines 2923–3005).
3. Re-apply redo. recv_sys.apply(true) (line 1623, defined at log0recv.cc line 4788) writes the collected records over the pages. If a record's start LSN is smaller than the page's FIL_PAGE_LSN, it is treated as already applied and skipped (recv_recover_page() lines 4086–4096). When this step ends, every page looks as it did right before the crash — including uncommitted changes.
4. Resurrect transactions. trx_lists_init_at_db_start() (line 1645) reads the undo log headers and rebuilds unfinished transactions as trx_t. It can do so because step 3 brought the undo pages back as well. The error log line … transaction(s) which must be rolled back or cleaned up in total … row operations to undo comes from here (trx0trx.cc lines 807–811).
5. Roll back. Unfinished transactions are rolled back with undo (the same work as trx_t::rollback() in part 11). But not right away. Only transactions that were changing the data dictionary (and statistics tables) are rolled back during startup (trx_rollback_recovered(false), line 1924); the rest starts after the server has finished the XA recovery of section 6.

static void innobase_tc_log_recovery_done() noexcept
{
  if (high_level_read_only || recv_sys.rpo)
    return;

  /* Make durable any innobase_recover_rollback_by_xid(). */
  log_buffer_flush_to_disk(true);

  if (srv_force_recovery < SRV_FORCE_NO_TRX_UNDO)
  {
    /* Rollback incomplete non-DDL transactions */
    trx_rollback_is_active= true;
    srv_thread_pool->submit_task(&rollback_all_recovered_task);
  }
}

storage/innobase/handler/ha_innodb.cc lines 17849–17863

This function hangs in the signal_tc_log_recovery_done slot of the handlerton (line 4323). The server opens the coordinator (tc_log->open(); with the binlog on, this is where the binlog is read and recovered), calls ha_recover(), then calls this slot (mysqld.cc lines 5993–6004), and InnoDB hands the rollback to a thread pool task. That task, trx_rollback_all_recovered() (trx0roll.cc lines 491–505), prints Starting in background the rollback of recovered transactions, rolls everything back with trx_rollback_recovered(true), then prints Rollback of non-prepared transactions completed. True to the words "in background", the server does not wait for this rollback to finish before accepting connections. A resurrected transaction also resurrects the locks on the tables it was changing (trx_resurrect_table_locks(), trx0trx.cc line 584) and holds them until its rollback ends.

Example 2: kill -9 with committed and uncommitted work in flight

The example folder is ex/u12-crash-recovery. We made one committed transfer and one big transaction (1,001 rows changed) left open and uncommitted in another session, made one more small commit, and then killed the server.

# An example written for this post (not MariaDB source)
# ... (creating the table and committing step 1, one transfer, omitted)
echo "--- 2. not committed: big transaction left open in another session"
# this session changes rows after BEGIN and waits in SLEEP without committing
mariadb -e "BEGIN;
  UPDATE lab.acct SET balance=0 WHERE id=3;
  INSERT INTO lab.acct SELECT seq, 'tmp', 1 FROM lab.seq_100_to_1099;
  SELECT SLEEP(60);" > /tmp/open-trx.out 2>&1 &
sleep 3
mariadb -e "SELECT trx_id, trx_state, trx_rows_modified FROM information_schema.INNODB_TRX"

echo "--- 3. one more small commit (its log write also carries the open trx's redo)"
mariadb -e "INSERT INTO lab.acct VALUES (4,'dave',100)"
# ...
kill -9 $(cat /tmp/mariadbd.pid)
# ... (restarting, grepping the error log, and looking at the surviving rows and the data directory omitted)

--- 1. committed: alice -> bob 30
--- 2. not committed: big transaction left open in another session
trx_id	trx_state	trx_rows_modified
25	RUNNING	1001
--- 3. one more small commit (its log write also carries the open trx's redo)
VARIABLE_NAME	VARIABLE_VALUE
INNODB_LSN_CURRENT	150791
INNODB_LSN_FLUSHED	150791
INNODB_LSN_LAST_CHECKPOINT	52245
--- 4. kill -9
--- 5. restart
[Note] InnoDB: Starting crash recovery from checkpoint LSN=52245
[Note] InnoDB: To recover: 32 pages
[Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1001 row operations to undo
[Note] InnoDB: Trx id counter is 28
[Note] Recovering after a crash using tc.log
[Note] Crash table recovery finished.
[Note] InnoDB: Starting in background the rollback of recovered transactions
[Note] InnoDB: Rolled back recovered transaction 25
[Note] InnoDB: Rollback of non-prepared transactions completed
--- 6. what survived
+----+-------+---------+
 id | owner | balance |
+----+-------+---------+
  1 | alice |      70 |
  2 | bob   |     130 |
  3 | carol |     100 |
  4 | dave  |     100 |
+----+-------+---------+
+----------+
 tmp_rows |
+----------+
        0 |
+----------+
ib_logfile0
ibdata1
tc.log
undo001
undo002
undo003

From the error log we dropped the timestamps and thread numbers and kept only the lines about recovery; the last six lines are an ls of the data directory. LSNs and trx ids may differ depending on the environment (a re-run during review gave the same values); the number of pages to recover (To recover: … pages) did differ on a re-run, at 30 pages.

1. Right before the kill, Innodb_lsn_flushed equals Innodb_lsn_current. The small commit in step 3 wrote the whole buffer with log_write_up_to(), so the log of uncommitted transaction 25 went to disk too. The checkpoint, on the other hand, stayed at 52245, so the roughly 98KB of log after it became the recovery work.
2. On restart, InnoDB read from the checkpoint LSN and fixed 32 pages (To recover: 32 pages), then found in undo "1 transaction to roll back, 1001 row operations to undo". In other words, redo brought back transaction 25's changes too.
3. Recovering after a crash using tc.log — the server's XA recovery ran even though the binlog was not on (see "Easy to get wrong" below).
4. Only then did Starting in background the rollback appear and transaction 25 get rolled back. The result: the committed transfer (alice 70, bob 130) and dave survived; carol's uncommitted 0 and the 1,000 tmp rows are gone.

Easy to get wrong: there is no binlog, yet there is a tc.log

The data directory contains a file called tc.log (the last ls of example 2), and recovery prints Recovering after a crash using tc.log. The function that picks the server's transaction coordinator (TC) explains it.

static inline TC_LOG *get_tc_log_implementation()
{
  if (total_ha_2pc <= 2) // online_alter_tp and MHNSW_Trx::tp
    return &tc_log_dummy;
  if (opt_bin_log)
    return &mysql_bin_log;
  return &tc_log_mmap;
}

sql/log.h lines 1553–1560

total_ha_2pc is the number of participants that can do two-phase commit. The two internal participants named in the comment (online ALTER's online_alter_tp and the vector index's MHNSW_Trx::tp) are counted in it, so it is compared with 2. Once an engine like InnoDB pushes it past 2 and the binlog is off, tc_log_mmap (TC_LOG_MMAP, an implementation that records XIDs in a memory-mapped tc.log file) is chosen. The file is only used when one transaction changes two or more engines that do two-phase commit. An ordinary transaction that changes only InnoDB takes the rw_ha_count <= 1 path of section 6 and commits in one phase, never touching tc.log. So the Crash table recovery finished. in example 2 finished with nothing to do.

5. The binlog — the server layer's log

There is a redo log, so why a binlog as well? The two record different things, and different parts of the server write them.

The yellow cylinders are files on disk.

• Redo is a physical log, and InnoDB's alone. It says things like "page 3 of space 5, at offset 120, these bytes". It only means something for the same files on the same server, and it holds no changes made to Aria or MyISAM. Once the checkpoint passes, it is overwritten.
• The binlog is a logical log, and the server layer's. It says "this SQL was run" or "this row of this table changed from this value to that value". It does not depend on the engine, and another server can receive it and run it again. It stays until you tell it to go (expire_logs_days, PURGE BINARY LOGS).

The class that writes the binlog is MYSQL_BIN_LOG.

class MYSQL_BIN_LOG: public TC_LOG, public Event_log

sql/log.h line 629

Besides Event_log (the part that writes events to a file), it inherits TC_LOG. That means with the binlog on, the binlog itself becomes the transaction coordinator, and this is the key to section 6. The face it shows as a transaction participant is binlog_tp.

transaction_participant binlog_tp;

int binlog_init(void *p)
{
  bzero(&binlog_tp, sizeof(binlog_tp));
  // ... (the savepoint slots)
  binlog_tp.commit= [](THD *thd, bool all) { return 0; };
  binlog_tp.rollback= binlog_rollback;
  if (WSREP_ON || opt_bin_log)
  {
    binlog_tp.prepare= binlog_prepare;
    binlog_tp.start_consistent_snapshot= binlog_start_consistent_snapshot;
  }
  binlog_tp.flags= HTON_NO_ROLLBACK;
  // ...
  return setup_transaction_participant(plugin);
}

sql/log.cc lines 2031–2054

The binlog registers not as a handlerton but as its parent, a transaction_participant. It has no tables, so there is no handler to create, and it fills in only the slots it needs to take part in transactions. The thing to notice is that commit is a lambda that does nothing. The real writing to the binlog happens not in the participant's commit but in the coordinator's log_and_order() (section 6). prepare (binlog_prepare(), lines 2662–2674) also carries a comment saying it does nothing and exists only because the code that decides whether to do two-phase commit looks at whether a prepare slot is present.

Events — one line of the binlog

A binlog file is a sequence of events. The event type numbers are in enum Log_event_type (log_event.h from line 669), and each type has a class derived from Log_event (line 1322). Only the ones that appear in example 3:

Example 3: looking at the events left in the binlog

The example folder is ex/u12-binlog-events. We started with --log-bin and committed two transactions: the first in the default format (MIXED), the second after switching the session to binlog_format=ROW.

# An example written for this post (not MariaDB source)
lab-start --log-bin=mysql-bin --server-id=1
# ...
mariadb -e "BEGIN; INSERT INTO lab.acct VALUES (1,'alice',100),(2,'bob',100); COMMIT;"
mariadb -e "SET SESSION binlog_format=ROW;
            BEGIN; UPDATE lab.acct SET balance=balance-30 WHERE id=1;
                   UPDATE lab.acct SET balance=balance+30 WHERE id=2; COMMIT;"

log_bin	1
binlog_format	MIXED
sync_binlog	0
gtid_domain_id	0
--- 1. SHOW BINARY LOGS / SHOW BINLOG EVENTS
+------------------+------+-------------------+-----------+-------------+-----------------------------------------------------------------------------
 Log_name         | Pos  | Event_type        | Server_id | End_log_pos | Info
+------------------+------+-------------------+-----------+-------------+-----------------------------------------------------------------------------
 mysql-bin.000001 |    4 | Format_desc       |         1 |         257 | Server ver: 13.2.0-MariaDB-debug-log, Binlog ver: 4
 mysql-bin.000001 |  257 | Gtid_list         |         1 |         286 | []
 mysql-bin.000001 |  286 | Binlog_checkpoint |         1 |         329 | mysql-bin.000001
 mysql-bin.000001 |  329 | Gtid              |         1 |         371 | GTID 0-1-1
 mysql-bin.000001 |  371 | Query             |         1 |         456 | CREATE DATABASE lab
 mysql-bin.000001 |  456 | Gtid              |         1 |         498 | GTID 0-1-2
 mysql-bin.000001 |  498 | Query             |         1 |         658 | CREATE TABLE lab.acct (id INT PRIMARY KEY, owner VARCHAR(20), balance INT) E
 mysql-bin.000001 |  658 | Gtid              |         1 |         700 | BEGIN GTID 0-1-3
 mysql-bin.000001 |  700 | Query             |         1 |           0 | INSERT INTO lab.acct VALUES (1,'alice',100),(2,'bob',100)
 mysql-bin.000001 |  820 | Xid               |         1 |         851 | COMMIT /* xid=8 */
 mysql-bin.000001 |  851 | Gtid              |         1 |         893 | BEGIN GTID 0-1-4
 mysql-bin.000001 |  893 | Annotate_rows     |         1 |           0 | UPDATE lab.acct SET balance=balance-30 WHERE id=1
 mysql-bin.000001 |  965 | Table_map         |         1 |           0 | table_id: 18 (lab.acct)
 mysql-bin.000001 | 1015 | Update_rows_v1    |         1 |           0 | table_id: 18 flags: STMT_END_F
 mysql-bin.000001 | 1079 | Annotate_rows     |         1 |           0 | UPDATE lab.acct SET balance=balance+30 WHERE id=2
 mysql-bin.000001 | 1151 | Table_map         |         1 |           0 | table_id: 18 (lab.acct)
 mysql-bin.000001 | 1201 | Update_rows_v1    |         1 |           0 | table_id: 18 flags: STMT_END_F
 mysql-bin.000001 | 1261 | Xid               |         1 |        1292 | COMMIT /* xid=13 */
+------------------+------+-------------------+-----------+-------------+-----------------------------------------------------------------------------

The output is wide, so we dropped the SHOW BINARY LOGS table and the mariadb-binlog output that follows, and cut the line ends of the table. Decoding the same file with mariadb-binlog --base64-output=decode-rows -v prints, under the first Update_rows event, ### UPDATE → ### WHERE … @3=100 → ### SET … @3=70: the before and after values of the row, by column number (@1, @2, @3).

1. A transaction starts with Gtid (BEGIN GTID 0-1-3) and ends with Xid (COMMIT /* xid=8 */). DDL is a Gtid + Query pair with no Xid.
2. Under MIXED, INSERT … VALUES is a safe statement, so it was kept as SQL (Query); the two UPDATEs after switching to ROW left Table_map + Update_rows with the before and after values of the changed rows. Annotate_rows is the original statement that produced those row events.
3. The three events at the start of the file (Format_desc, Gtid_list, Binlog_checkpoint) are written when the file is opened, regardless of transactions. Binlog_checkpoint is the marker that the XA recovery of section 6 uses.

The xid numbers and table_id may differ from run to run.

Easy to get wrong: events whose End_log_pos is 0

In the output, the events inside a transaction (Query, Annotate_rows, Table_map, Update_rows) have an End_log_pos of 0. The file is not broken.

  if (is_artificial_event() ||
      cache_type == Log_event::EVENT_STMT_CACHE ||
      cache_type == Log_event::EVENT_TRANSACTIONAL_CACHE)
  {
    /*
      Artificial events are automatically generated and do not exist
      in master's binary log, so log_pos should be set to 0.

      Events written through transaction or statement cache have log_pos set
      to 0 so that they can be copied directly to the binlog without having
      to compute the real end_log_pos.
    */
    log_pos= 0;
  }

sql/log_event_server.cc lines 888–901

While a transaction runs, its events pile up first not in the file but in a binlog cache that each connection has (the transaction cache of binlog_cache_mngr). At commit that cache is copied into the binlog file in one piece, and the comment says the position is left at 0 so that it need not be recomputed for every event at that point. Gtid and Xid are written directly at commit, so they carry real positions. A rolled-back transaction that changed only tables of a transactional engine like InnoDB only needs its cache thrown away, so nothing of it reaches the binlog.

6. Keeping the two logs in step — two-phase commit and group commit

With the binlog on, one commit has to leave traces in two files. What happens if the server dies in between?

• If it dies after InnoDB has committed but before the binlog has it: the row exists on this server but never reaches the replicas that read the binlog.
• If it dies after the binlog has it but before InnoDB has committed: the replicas have the row but this server does not.

Either way, the servers diverge. So MariaDB ties InnoDB and the binlog together with two-phase commit and uses the binlog as the deciding record. Look at ha_commit_trans(), the centre of commit on the server side. First, if there is only one participant, it skips the two phases.

  if (trans->no_2pc || (rw_ha_count <= 1))
  {

sql/handler.cc lines 1978–1979

rw_ha_count is the number of participants that actually wrote something in this transaction. With the binlog off and only InnoDB changed, it is 1, so the commit goes straight to ha_commit_one_phase() (which is why the tc.log of section 4 was not used). With the binlog on, binlog_tp registers as a participant too, the count becomes 2, and the code goes on below.

  for (Ha_trx_info *hi= ha_info; hi; hi= hi->next())
  {
    transaction_participant *ht= hi->ht();
    // ...
    if (! hi->is_trx_read_write())
      continue;
    /* We do not need to 2pc the binlog with the engine that implements it. */
    if (ht == opt_binlog_engine_hton)
      continue;
    // ...
    if (unlikely(prepare_or_error(ht, thd, all)))
      goto err;

    need_prepare_ordered|= (ht->prepare_ordered != NULL);
    need_commit_ordered|= (ht->commit_ordered != NULL);
  }
  DEBUG_SYNC(thd, "ha_commit_trans_after_prepare");
  DBUG_EXECUTE_IF("crash_commit_after_prepare", DBUG_SUICIDE(););
  // ...
  cookie= tc_log->log_and_order(thd, xid, all, need_prepare_ordered,
                                need_commit_ordered);
  // ...
  DBUG_EXECUTE_IF("crash_commit_after_log", DBUG_SUICIDE(););

  error= commit_one_phase_2(thd, all, trans, is_real_trans) ? 2 : 0;
  // ... (WSREP block omitted)
  DBUG_EXECUTE_IF("crash_commit_before_unlog", DBUG_SUICIDE(););
  if (tc_log->unlog(thd, cookie, xid))
    error= 2;                                /* Error during commit */

sql/handler.cc lines 2028–2108

Three steps.

1. prepare. prepare is called on every participant that wrote. InnoDB's innobase_xa_prepare() (ha_innodb.cc line 17721) uses trx_prepare() to switch the undo log header's state to PREPARED and record the XID (trx_undo_set_state_at_prepare(); that change is an mtr too, so it lands in redo), and then, if innodb_flush_log_at_trx_commit is not 0, writes the log up to that LSN (with 1 or 3, all the way to fsync; with 2, write only — the same & 1 test as in section 2, trx0trx.cc lines 1990–1992). InnoDB now holds on disk a state that "could still be committed or rolled back".
2. log_and_order. The coordinator (MYSQL_BIN_LOG when the binlog is on) writes the transaction to the binlog and calls the participants' commit_ordered in binlog order. The moment the Xid event is written to the binlog is this transaction's commit point.
3. commit. commit_one_phase_2() calls commit on every participant: innobase_commit() for InnoDB, the empty lambda we saw for the binlog. Finally unlog() tells the coordinator "this XID is done".

Lines like DBUG_EXECUTE_IF("crash_commit_after_prepare", DBUG_SUICIDE();); are planted between the steps. In a Debug build, turning a name on through debug_dbug makes the server kill itself right at that spot. They exist so that MariaDB's tests can exercise exactly these gaps (for example mysql-test/suite/innodb/t/group_commit_crash.test), and example 4 uses them.

The two grey bands labelled "crash point" are where example 4 kills the server. The fsync notes assume the default innodb_flush_log_at_trx_commit=1.

Example 4: the order one commit takes, and killing it in both gaps

The example folder is ex/u12-two-phase-commit. We attached gdb to a server started with --log-bin and made it print just the function name at each stop and carry on, for every function one autocommit INSERT passes through (order.gdb, which detaches at the final unlog()). Each breakpoint got commands … printf … continue … end, and the one on log_write_up_to got the condition if $_caller_is("trx_prepare") so that only calls from prepare are printed. The result:

--- 1. call order of one autocommit INSERT (gdb)
>> ha_commit_trans(all=0)  thread_id=6  sql_command=5
>> ha_commit_trans(all=1)  thread_id=6  sql_command=5
>> ha_commit_trans(all=0)  thread_id=6  sql_command=5
>>   innobase_xa_prepare            InnoDB PREPARE
>>     log_write_up_to(durable=1)   called from trx_prepare
>>   MYSQL_BIN_LOG::log_and_order
>>     trx_group_commit_leader
>>     write_transaction_or_stmt      events -> binlog file
>>     flush_and_sync
>>     innobase_commit_ordered        InnoDB commit, in binlog order
>>   innobase_commit(commit_trx=0)
>>   MYSQL_BIN_LOG::unlog

1. In prepare, log_write_up_to(durable=1) — InnoDB fsynced the prepared state.
2. Inside log_and_order this thread became the group commit leader (trx_group_commit_leader), wrote the events to the binlog file (write_transaction_or_stmt), passed flush_and_sync, and called InnoDB's commit_ordered.
3. Then innobase_commit was called, but trx_flush_log_if_needed() was not called inside it (a breakpoint was set on it, and it never printed). That is the case 1: if (trx->active_commit_ordered && trx->active_prepare) return; line from section 2.

Next, on the same server, we turned on a crash point with debug_dbug, sent an INSERT, restarted, and looked at the error log and the rows.

# An example written for this post (not MariaDB source)
mariadb -e "SET SESSION debug_dbug='+d,crash_commit_after_prepare';
            INSERT INTO lab.t VALUES (2, 'crash after prepare')" 2>&1 || true

--- 2. crash after InnoDB PREPARE, before the binlog write
ERROR 2013 (HY000) at line 2: Lost connection to server during query
[Note] InnoDB: Starting crash recovery from checkpoint LSN=52245
[Note] InnoDB: Transaction 21 was in the XA prepared state.
[Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
[Note] Recovering after a crash using mysql-bin
[Note] Starting table crash recovery...
[Note] InnoDB: Transaction 21 in prepared state after recovery
[Note] InnoDB: 1 transactions in prepared state after recovery
[Note] Crash table recovery finished.
[Note] InnoDB: Starting in background the rollback of recovered transactions
[Note] InnoDB: Rolled back recovered transaction 21
[Note] InnoDB: Rollback of non-prepared transactions completed
+----+--------+
 id | note   |
+----+--------+
  1 | traced |
+----+--------+
--- 3. crash after the binlog write, before InnoDB commit
ERROR 2013 (HY000) at line 2: Lost connection to server during query
[Note] InnoDB: Starting crash recovery from checkpoint LSN=52261
[Note] InnoDB: Transaction 27 was in the XA prepared state.
...
[Note] Recovering after a crash using mysql-bin
...
[Note] Crash table recovery finished.
+----+--------------------+
 id | note               |
+----+--------------------+
  1 | traced             |
  3 | crash after binlog |
+----+--------------------+
--- 4. which INSERTs are in the binlog
# mysql-bin.000001
INSERT INTO lab.t VALUES (1, 'traced')
Xid = 5
COMMIT/*!*/;
# mysql-bin.000002
INSERT INTO lab.t VALUES (3, 'crash after binlog')
Xid = 5
COMMIT/*!*/;
# mysql-bin.000003

We dropped the statement lines the client echoes and the error log timestamps, and shortened the lines in case 3 that repeat case 2 to .... trx ids and LSNs may differ depending on the environment (a re-run gave the same values).

1. In both cases InnoDB resurrected the transaction in the XA prepared state. Looking at InnoDB alone, the two are identical.
2. What separated them was the binlog. Opening the binlog, the server saw that the last file had not been closed cleanly (Recovering after a crash using mysql-bin), collected that file's Xid events and matched them against InnoDB's prepared XIDs.
   • Case 2 (right after prepare): the XID is not in the binlog, so roll back. Row 2 is absent, and absent from the binlog too.
   • Case 3 (right after the binlog write): the XID is in the binlog, so commit. Row 3 is present, and present in the binlog too.
3. Either way, InnoDB and the binlog tell the same story. That is the promise two-phase commit keeps.

The code that decides by the binlog

When the server opens the binlog and the first event (Format_description) still carries the "in use" flag (LOG_EVENT_BINLOG_IN_USE_F), it concludes there was a crash and calls recover() (log.cc lines 14792–14796). recover() first collects the engines' prepared XIDs with ha_recover(), then reads the binlog and marks an XID "to be committed" every time it meets that Xid event.

      case XID_EVENT:
      if (do_xa)
      {
        Xid_log_event *xid_ev= (Xid_log_event*) ev;

        xid_recovery_member *member= (xid_recovery_member *)
          my_hash_search(&xids, (uchar*) &xid_ev->xid, sizeof(my_xid));
#ifndef HAVE_REPLICATION
        {
          if (member)
            member->decided_to_commit= true;
        }

sql/log.cc lines 14323–14334

In an ordinary build with replication, the #else branch's Recovery_context::decide_or_assess() (line 14336) also weighs cases such as a semi-sync replica (we did not follow those details). Once everything is read, each engine gets commit_by_xid or recover_rollback_by_xid (rollback_by_xid if that is missing) according to the mark (xarecover_do_commit_or_rollback(), handler.cc lines 2992–2998). InnoDB's recover_rollback_by_xid (innobase_recover_rollback_by_xid()) does not roll back on the spot; it only switches the transaction to ACTIVE. The actual rollback is done by the background rollback of section 4 — which is why, in case 2 of the example, Rolled back recovered transaction 21 came after Crash table recovery finished. (the comment at ha_innodb.cc lines 17842–17845).

Group commit — line up, write once

Writing to the binlog and fsyncing separately for every commit is slow. On the way to writing the binlog cache to the file, log_and_order() lines transactions up with queue_for_group_commit().

/*
  Put a transaction that is ready to commit in the group commit queue.
  The transaction is identified by the ENTRY object passed into this function.

  To facilitate group commit for the binlog, we first queue up ourselves in
  this function. Then later the first thread to enter the queue waits for
  the LOCK_log mutex, and commits for everyone in the queue once it gets the
  lock. Any other threads in the queue just wait for the first one to finish
  the commit and wake them up. This way, all transactions in the queue get
  committed in a single disk operation.

sql/log.cc lines 10199–10208

The first thread in the queue (the leader) takes LOCK_log in trx_group_commit_leader() (line 10777), takes the whole queue including everyone who joined while it waited, writes them to the file one after another (write_transaction_or_stmt()) and calls flush_and_sync() once. It then takes LOCK_commit_ordered, calls run_commit_ordered() for each transaction in queue order so that InnoDB commits them in the same order, and wakes the other threads. It is the same idea as InnoDB's log_write_up_to(), where "one thread writes".

flush_and_sync() writes the cache to the file (flush_io_cache()) and fsyncs with mysql_file_sync() only at the interval sync_binlog sets (lines 7206–7212). As example 3's output showed, the default is sync_binlog=0, so the binlog only does write() and leaves the fsync to the operating system. With sync_binlog=1 it fsyncs once per group.

Easy to get wrong: with the binlog on, InnoDB's commit does not fsync (with setting 1)

Look again at what case 3 of example 4 showed. innodb_flush_log_at_trx_commit=1, yet there was no fsync in InnoDB's commit step. Why that is fine is explained in the description of the handlerton's commit_checkpoint_request slot.

    An engine that does implement commit_checkpoint_request() is also
    expected to implement commit_ordered(), so that ordering of commits is
    consistent between 2pc participants. Such engine is no longer required to
    durably flush to disk transactions in commit(), provided that the
    transaction has been successfully prepare()d and commit_ordered(); thus
    potentially saving one fsync() call. (Engine must still durably flush
    to disk in commit() when no prepare()/commit_ordered() steps took place,
    at least if durable commits are wanted; this happens eg. if binlog is
    disabled).

sql/handler.h lines 1471–1479

If prepare has already been fsynced and the binlog has the Xid, then even if the commit record is lost, recovery can look at the binlog and commit again (case 3 of example 4 was exactly that). So one fsync is saved. In exchange, before a binlog file can be removed the server must know that its transactions really are committed to disk in InnoDB, so when it rotates the binlog it calls commit_checkpoint_request and asks InnoDB to "tell me once you have fsynced this far" (InnoDB's side is innodb_log_flush_request(), ha_innodb.cc line 4983). innodb_flush_log_at_trx_commit=3 is the setting that skips this shortcut and fsyncs at commit too (the shortcut exists only under case 1:).

Easy to get wrong: three ha_commit_trans() calls for one INSERT

In example 4's output, ha_commit_trans was printed three times, and two-phase commit happened only on the third. Printing backtraces for all three in ex/u12-commit-callers shows that the first two came from read_statistics_for_tables() → THD::commit_whole_transaction_and_close_tables() (sql_class.cc lines 6852 and 6860), which reads and closes the engine-independent statistics tables (mysql.table_stats and friends) while the INSERT opens its table; their participant list (ha_list) was empty, so they ended at once. The third is trans_commit_stmt() at the end of the statement (transaction.cc line 499).

==== call 3 all=0 ha_list=0x779e6c003bc0
#0  ha_commit_trans at /usr/src/mariadb/sql/handler.cc:1788
#1  trans_commit_stmt at /usr/src/mariadb/sql/transaction.cc:499
#2  mysql_execute_command at /usr/src/mariadb/sql/sql_parse.cc:6039
...

It is a statement commit (all=0), yet it became a real commit because of this line.

  bool is_real_trans= ((all || thd->transaction->all.ha_list == 0) &&
                       !(thd->variables.option_bits & OPTION_GTID_BEGIN));

sql/handler.cc lines 1802–1803

Under autocommit, the participant list of the whole transaction (all.ha_list) is empty, so the statement commit is the transaction commit. Wrap the work in BEGIN … COMMIT and all=0 is still called at the end of every statement, but is_real_trans is false, so two-phase commit happens only at COMMIT's all=1. The address (ha_list=…) differs from run to run.

7. The recent binlog_storage_engine, and a taste of replication

Keeping the binlog inside InnoDB

The reference commit has a --binlog-storage-engine option added in recent versions (Sys_binlog_storage_engine, sys_vars.cc lines 2741–2746, described as "a more efficient binlog implementation integrated with the storage engine"). Give it innodb and the binlog is written to files InnoDB manages (binlog-000000.ibb …), and writing the binlog itself becomes an InnoDB mtr protected by redo (mtr_t::write_binlog(), called from fsp_binlog.cc, buf0flu.cc line 2290). The implementation is in storage/innobase/handler/innodb_binlog.cc (about 5,000 lines) and storage/innobase/fsp/fsp_binlog.cc. Then there is no need for two-phase commit between InnoDB and the binlog. That is the line in ha_commit_trans() we saw in section 6 — if (ht == opt_binlog_engine_hton) continue; ("no need to 2PC the binlog with the engine that implements it"). In ex/u12-binlog-in-innodb we ran the same gdb script as example 4.

--- 1. call order of one autocommit INSERT (gdb)
>> ha_commit_trans(all=0)  thread_id=5  sql_command=5
>> ha_commit_trans(all=1)  thread_id=5  sql_command=5
>> ha_commit_trans(all=0)  thread_id=5  sql_command=5
>>   MYSQL_BIN_LOG::log_and_order
>>     trx_group_commit_leader
>>     write_transaction_or_stmt      events -> binlog file
>>     innobase_commit_ordered        InnoDB commit, in binlog order
>>   innobase_commit(commit_trx=0)
>>     trx_flush_log_if_needed
>>   MYSQL_BIN_LOG::unlog
--- 2. binlog files and events
...
+-------------------+------------+
 Log_name          | File_size  |
+-------------------+------------+
 binlog-000000.ibb | 1073741824 |
 binlog-000001.ibb | 1073741824 |
+-------------------+------------+
...

innobase_xa_prepare and flush_and_sync are gone, and in their place trx_flush_log_if_needed is back in InnoDB's commit step. Instead of the prepare fsync plus (with sync_binlog=1) the binlog file fsync, there is one fsync of InnoDB redo, which now carries the binlog as well. The binlog files are created up front, two of them, at max_binlog_size (1GB by default) (the size is set in ibb_set_max_size(), innodb_binlog.cc lines 1619–1634). The two ... in the output stand for the table printing @@binlog_storage_engine (innodb) and for the SHOW BINLOG EVENTS table and file-size lines that follow. SHOW BINLOG EVENTS also shows the events, but every Pos came out as 0 (we did not check what a file position means in the new implementation). This feature arrived in recent versions, and we did not check whether other versions have it.

A taste of replication

The binlog's first use is replication. This series only notes the names and places.

• The sending side (primary): when a replica sends COM_BINLOG_DUMP, that connection thread reads the binlog files in mysql_binlog_send() (sql_repl.cc line 3735) and sends the events one after another. When there are no new events, it waits for the binlog to grow.
• The receiving side (replica): the IO thread handle_slave_io() (slave.cc line 4536) receives events and writes them to the relay log (the replica's local copy of the received binlog), and the SQL thread handle_slave_sql() (line 5200) reads the relay log and calls do_apply_event() (log_event.h line 1855) for each event. A Query_log_event re-runs its SQL; a Rows_log_event finds the row and changes it directly through the handler (ha_write_row() and ha_update_row() from part 9).
• Parallel apply: handing event groups out to several workers is sql/rpl_parallel.cc. When several transactions are bundled into one group in section 6's group commit, the leader picks one commit id (trx_group_commit_with_engines(), log.cc line 10845) and writes it into each Gtid event ("groups with the same commit_id are part of the same group commit", log_event.h lines 3536–3539), and parallel replication uses that value. This post does not follow how.

The functions in the list above, laid out in the order the events flow. Parallel apply (rpl_parallel.cc) is not drawn.

What this post leaves out

• The format of redo records (record types WRITE, MEMSET, MEMMOVE, INIT_PAGE, FREE_PAGE, EXTENDED … and the length encoding): storage/innobase/include/mtr0types.h, the writing side include/mtr0log.h, the reading side recv_sys_t::parse() log0recv.cc line 3015
• Applying in several batches when there are more pages to recover than fit in the buffer pool (multi-batch): recv_sys_t::apply_batch() line 4421
• The doublewrite buffer that repairs half-written pages: storage/innobase/buf/buf0dblwr.cc, buf_dblwr.recover() during recovery
• Log archiving (innodb_log_archive) and resizing at run time: log_t::set_archive(), log_t::resize_start() (log0log.cc)
• What each level of innodb_force_recovery skips: SRV_FORCE_* in include/srv0srv.h
• User XA (XA START … XA PREPARE … XA COMMIT) and the binlog's XA_PREPARE_LOG_EVENT: sql/xa.cc, TC_LOG::log_xa_prepare()
• Serializing events for the binlog (Log_event::write(), Log_event_writer) and checksums: sql/log_event_server.cc
• Semi-sync replication (repl_semisync_master), GTID state (rpl_gtid.cc), and the details of parallel replication: sql/semisync_master.cc, sql/rpl_gtid.cc, sql/rpl_parallel.cc
• Aria's own transaction log (aria_log.00000001) and its recovery: storage/maria/ma_loghandler.c, ma_recovery.c

Recap

Wrapping up the series

With this post, all 12 parts from the map in Part 1 are written. Here is the whole series.

The life of one query, one more time

In part 2 we drew, as a map, the boxes one query passes from the connection to the engine. Here we draw it again, adding startup before it and this post's commit and logs after it. Each box names the part that covered it.

This post was the two green boxes.

When mariadbd starts, mysqld_main() reads the options and brings up the plugins, and engines such as InnoDB fill in their handlerton at that point (part 3). InnoDB answers that it is ready only after this post's redo apply and transaction resurrection are done. When a connection arrives, one thread (or a thread pool worker) takes it, carrying a THD (part 4), reads packets and, for COM_QUERY, hands the statement to the parser (part 5). The parser turns the statement into LEX and Item trees (part 6), and preparation checks privileges, opens tables, takes MDL and ties names to columns (part 7). Once the optimizer picks the join order and access methods (part 8), the executor's nested loop calls the handler to fetch or write rows in the engine (part 9). Inside the engine, pages and B-trees (part 10) and transactions and locks (part 11) do the work, and every change piles up in the redo log buffer, mtr by mtr. Finally, when COMMIT comes, ha_commit_trans() commits InnoDB and the binlog in two phases, and the moment the redo log is fsynced, that commit survives even if the server dies (this post).

Three things kept coming back across the twelve parts. The boundary of handler and handlerton split server from engine not only in query execution (part 9) but also in startup (part 3), transactions (part 11), and commit and recovery (this post). Even this post's binlog joined transactions as a transaction_participant of the same shape. Putting everything about a connection in one THD meant the parser's LEX, preparation's open tables and the participant list at commit (thd->transaction) all come out of one object. Memory first, disk later was there in the buffer pool (part 10), undo and read views (part 11), and redo and the binlog cache (this post), and what makes that "later" safe is the log. Knowing these three, you can guess where to start reading even a MariaDB feature you have never seen.

Compared with the httpd, Tomcat and Spring series

This blog has already read Digging into Spring's Source (27 parts), Digging into Apache httpd's Source (16 parts) and Digging into Tomcat's Source (16 parts).

• As a server, it has the same skeleton as httpd and Tomcat. Accepting connections and handing them to threads was the same problem as httpd part 8's MPMs and Tomcat part 5's endpoint, and MariaDB's thread pool resembles the event MPM. MEM_ROOT, which frees memory all at once per request (statement), is the same idea as httpd part 4's APR pools, and the handlerton that lets you swap engines as plugins slots in other people's code through a table of function pointers, like httpd part 6's modules and hooks.
• The difference is that it keeps state on disk. httpd and Tomcat may forget a request once it ends, but a database must remember what was committed even if the server dies. This post's redo, undo, binlog and two-phase commit were a kind of code the three earlier series did not have. If the "logs" of httpd part 16 were records that tell people what happened, the logs in this post are records the server itself reads back to restore its state.
• Spring is the floor above this series. The Connection.commit() that Spring part 17's @Transactional calls at the end of a method reaches the server as a COMMIT through the JDBC driver (this series did not read the driver side), passes part 5's dispatch_command(), and becomes this post's ha_commit_trans(). One line of SQL sent by Spring part 18's JdbcTemplate runs along the road of parts 6–9. It is the same transaction, seen from above and from below.

What this blog reads next

After nginx and MariaDB, this blog's open-source reading moves on to Gradle. So far we have read servers that take requests and guard data; next is a tool that builds code. The gradle.properties we opened to find the version in Spring part 1 was in fact a Gradle settings file.

• Gradle Part 1: How I Read It with AI, and the Map — the first post of the next series
• MariaDB Part 1: How I Read It with AI, and the Map
• MariaDB Part 2: The Big Picture — the Server Layer, Storage Engines, and the Life of One Query
• Spring Part 17: @Transactional — Who Opens a Transaction and Who Closes It