ExportXMLWordPrintableJSON

    • Type: Improvement
    • Resolution: Unresolved
    • Priority: Minor - P4
    • None
    • Affects Version/s: None
    • Component/s: Logging
    • None
    • Storage Engines - Persistence
    • 423.042
    • StorEng - Defined Pipeline
    • None

      When __wt_log_flush waits for earlier closed log slots to finish writing, it sleeps for at least 1 ms and forces out the active slot on every iteration. This change replaces the sleep and redundant forced slot switches with a timed wait of up to 200 usec on log->log_write_cond followed by __wti_log_wrlsn. This removes unnecessary slot writes and cuts the wait loop duration from ~1.5 ms to ~0.31 ms under slow sync operations.

      Problem

      Line numbers reference develop 50c032ba6. __wt_log_flush (src/log/log.c:2840-2881) is called by WT_SESSION::log_flush (src/session/session_api.c:1213) and by checkpoints when logging is enabled (src/checkpoint/checkpoint_txn.c:1560). It forces out the active slot, assigns alloc_lsn to last_lsn (log_close_lsn if the log moved to a new file), and waits until write_lsn reaches it (log.c:2866-2869):

      while (__wt_log_cmp(&last_lsn, &lsn) > 0) {
          __wt_sleep(0, WT_THOUSAND);
          WT_RET(__wt_log_flush_lsn(session, &lsn, false));
      }
      

      The loop runs when a slot below last_lsn has closed but has not finished writing. Worker threads close slots when a write reaches half the slot buffer size (log.c:2721-2723, 128 KB with the default 256 KB buffer, log_slot.c:466-467) or for records exceeding that threshold (log_slot.c:574-576). The last thread to release the slot writes it out.

      Each loop iteration currently incurs:

      • A sleep of at least 1 ms (select() with a 1000 usec timeout took 1095 usec at p50 on the Linux host and 1511 usec on the loaded Mac host).
      • A redundant forced switch of the active slot: acquiring log_slot_lock, looping on EBUSY, and issuing a pwrite of that slot under the lock (log_slot.c:376-383).
      • A call to __wti_log_wrlsn under log_writelsn_lock.

      The additional forced slot switch is unnecessary. At loop entry, all slots below last_lsn are already closed (alloc_lsn only advances when a slot closes, log_slot.c:187), and the thread releasing each slot performs the write. Slots released without WTI_SLOT_FLUSH or WTI_SLOT_SYNC* are marked written without signaling (log.c:1949-1958). write_lsn advances when the wrlsn thread or a log_flush caller executes __wti_log_wrlsn (log_mgr.c:754-872), which signals log_write_cond on each advance (log_mgr.c:860).

      The same loop exists in mongodb-8.0 (cd0025dd3, src/log/log.c:2854).

      When it shows up in MongoDB

      JournalFlusher is the only thread that makes the journal durable. Under steady w:"majority" or j:true write workloads, waitUntilDurable calls WT_SESSION::log_flush("sync=on") back-to-back, with callers waiting for the ongoing round plus the subsequent round. Because mongod does not set log.file_max, the slot buffer defaults to 256 KB. The loop adds at least 1 ms per round whenever more than 128 KB of journal data arrives during the round, or when an individual oplog entry exceeds 128 KB.

      Measurements

      Microbenchmark running directly against WiredTiger. N writer threads each commit one 200-byte insert per transaction (one 256-byte log record, transaction_sync disabled, log=(file_max=100MB)). A flusher thread calls log_flush("sync=on") as soon as at least one transaction commits since the previous call started, modeling JournalFlusher behavior. Runs used a 2 s warm-up and 8 s measurement period, alternating build order across rounds. Evaluated on release builds of 50c032ba6 (develop) and develop with the patch (branch). Cells report medians across rounds, with [min-max] ranges where noted.

      Environment:

      Host CPU, memory OS, compiler File system, device fsync in these runs Load
      Mac Apple M4 Pro, 14 cores (10P + 4E), 24 GB macOS 26.5.2 (25F84), Apple clang 21.0.0 APFS, internal SSD, 95% full F_FULLFSYNC, 5.5-22.5 ms average per run shared machine: 1-minute load average 8.4-97.8 at run start, 18-1143 MB/s written by other processes in the second before a run; AC power
      dev-m KVM guest, 4 vCPU AMD EPYC-Genoa, 7.6 GB Ubuntu, Linux 7.0.0-15-generic, gcc 15.2.0 ext4 (relatime) on a virtio disk (QEMU HARDDISK, non-rotational, mq-deadline) fdatasync, 0.8-1.7 ms average per run (1.8-2.8 ms with 64 KB records) idle apart from the benchmark (1-minute load average 0.1-8.1 at run start, left by the previous run)

      Mac, 5 rounds:

      Writers Build log_flush/s log_flush p50 us log_flush p99 us Commits/s
      4 develop 87 9,896 [7,832-13,304] 31,588 [26,083-54,788] 438,985
      4 branch 125 6,455 [5,145-8,028] 26,346 [21,889-32,637] 541,624
      8 develop 73 10,027 [8,454-10,420] 42,205 [36,438-175,112] 645,426
      8 branch 72 7,832 [6,980-9,765] 58,982 [29,753-112,722] 554,870
      16 develop 82 8,716 [7,963-9,372] 44,827 [30,540-101,188] 1,088,441
      16 branch 91 7,832 [7,111-9,896] 44,302 [25,297-58,982] 1,118,091

      Mac, wait loop isolated with temporary instrumentation counters, 3 rounds. "signal" includes this change plus signaling wrlsn.cond prior to each wait, matching __log_wait_for_earlier_slot:

      Writers Build Calls that ran the loop, % Loop time p50 in those calls, us Loop share of log_flush time, % log_write_lsn_skip/s
      4 develop 90.8 1,516 16.6 847
      4 signal 94.6 309 4.8 3,909
      4 branch 93.8 313 5.0 275
      8 develop 90.8 1,516 14.3 433
      8 signal 91.5 313 4.2 4,550
      8 branch 91.8 309 4.2 586
      16 develop 82.0 1,532 16.4 228
      16 signal 77.2 313 5.3 6,987
      16 branch 81.4 317 6.6 524

      Signaling wrlsn.cond does not decrease loop time. It wakes the wrlsn thread, which then yields up to 1000 times without work (log_write_lsn_skip is 8-14x higher than branch). The patch therefore does not signal wrlsn.cond.

      dev-m (Linux), series A, 5 rounds. "Loop iterations per call" for develop is calculated as (log_force_write - log_flush) / log_flush minus the corresponding branch value:

      Writers Build log_flush/s log_flush p50 us log_flush p99 us Commits/s Loop iterations per call log_write_lsn_skip/s
      2 develop 932 1,057 [946-1,155] 2,474 [2,245-2,900] 474,423 0.01 747
      2 branch 1,010 938 [823-979] 2,114 [2,040-2,179] 442,351 - 0
      2 signal 1,034 913 [807-1,057] 2,007 [1,892-2,277] 519,416 - 11,753
      4 develop 691 1,237 [1,188-1,302] 4,145 [3,981-4,358] 834,248 0.03 1,466
      4 branch 639 1,384 [1,270-1,450] 4,112 [3,948-4,293] 751,924 - 1,170
      4 signal 557 1,614 [1,434-1,663] 4,751 [4,227-4,948] 687,458 - 2,836
      8 develop 589 1,384 [1,286-1,614] 5,341 [5,079-5,866] 770,519 0.06 982
      8 branch 565 1,499 [1,319-1,581] 5,014 [4,817-5,931] 736,835 - 368
      8 signal 590 1,483 [1,302-1,581] 4,948 [4,424-5,210] 803,766 - 1,886

      dev-m, series A2, 8 rounds, measuring develop twice to capture run-to-run variation:

      Writers Build log_flush p50 us log_flush p99 us Commits/s
      4 develop 1,360 [1,172-1,434] 4,489 [3,916-4,882] 763,610
      4 branch 1,393 [1,172-1,499] 4,063 [3,621-4,424] 743,546
      4 develop again 1,384 [1,106-1,417] 4,653 [3,719-5,014] 740,149
      8 develop 1,458 [1,139-1,679] 5,603 [4,080-5,996] 764,594
      8 branch 1,360 [1,172-1,532] 4,620 [4,014-5,014] 731,476
      8 develop again 1,278 [1,139-1,499] 4,588 [4,014-5,603] 854,176

      dev-m, series L: 4 writers, 64 KB records, 3,000 commits/s total (188 MB/s log output), 6 rounds:

      Build log_flush p50 us log_flush p99 us Loop iterations per call
      develop 2,441 [2,089-2,802] 5,997 [5,931-6,848] 0.09
      branch 2,769 [1,696-2,867] 6,292 [5,079-6,980] -
      develop again 2,490 [2,073-3,031] 6,357 [5,734-6,586] 0.11

      On the Mac, the loop executes in 82-91% of log_flush calls, taking 14-17% of total flush time. The change lowers loop time from ~1.5 ms to ~0.31 ms and improves log_flush p50 by 10-35%. On dev-m, the loop executes in only 1-6% of calls (~10% with 64 KB records) because fdatasync is fast enough that closed slots are written before the next round begins; performance deltas stay within develop run-to-run variance (up to 12% at p50). The change benefits workloads where slot writes are slow relative to a flush round, such as on APFS with F_FULLFSYNC, with no measurable overhead when the loop is bypassed.

      Proposed change

      PR: https://github.com/wiredtiger/wiredtiger/pull/14950.
      In the wait loop, wait on log->log_write_cond for up to 200 usec (the same timeout used by __log_wait_for_earlier_slot), call __wti_log_wrlsn, and re-read write_lsn. Check for panics before waiting. Do not force out the active slot and do not signal the wrlsn thread. The loop exit condition, log_close_lsn handling, and __wt_log_force_sync remain unchanged.

      Local testing

      Tested on the PR branch, based on 50c032ba6. macOS arm64, Apple clang 21.0.0, RelWithDebInfo with HAVE_DIAGNOSTIC=1, ENABLE_STRICT=1 (-Werror), and Python:

      • run.py -j 4 txn log test_backup07.py test_backup09.py test_backup10.py test_backup24.py test_backup25.py test_prepare02.py test_readonly03.py test_schema08.py test_timestamp03.py test_timestamp07.py test_truncate21.py: Ran 458 tests, OK (skipped=13).
      • ctest ex_log, test_truncated_log, test_random_abort, test_timestamp_abort, test_schema_abort: 5 of 5 passed.
      • test/format/t -1 logging=1 logging.remove=1 runs.timer=2 runs.type=row checkpoint=on: passed (29 tables, 20 threads, logging.file_max=499635).
      • dist/s_all with clang-format 23.1.2: no modifications to src/log/log.c. Unrelated reformats in bench/workgen/workgen.cpp, ext/page_log/palite/palite.cpp, and test/catch2/misc_tests/test_rec_upd_select.cpp were discarded. ruff_check.py and s_docs were skipped as Ruff and Doxygen are not installed; this change touches no Python or documentation files.

            Assignee:
            Unassigned
            Reporter:
            Mikhail Sotnikov (EXT)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated: