Shinoyuki-BetterAutoSave

v0.20.0 — Making main-thread sync chunk loads and inter-tick pauses observable

0.20.0 adds two diagnostic features that observe and never intervene: detection of main-thread synchronous chunk loads, and monitoring of long pauses between ticks. Both are on by default, and both builds have them

1. Why these two stalls were invisible

A production server with 74 players online froze. In the spark profile, BetterAutoSave's own save path on the main thread (NbtIo writes) accounted for 0.03% — saving was not the cause. The two actual sources were:

• One main-thread synchronous chunk load, triggered by third-party code, blocking for 5.2 seconds
• Two pauses that happened between ticks, 17.1 seconds and 14.8 seconds

The second kind is the harder one. MSPT only measures time spent inside a tick; the wait between two ticks is not counted, so those 17 seconds are invisible on the TPS graph and on every ordinary monitoring dashboard — the dashboard looks healthy while players are timing out. Digging both out of spark's inclusive call tree took hours of manual work. 0.20.0 makes the server report them by itself

2. Main-thread synchronous chunk loads

When a chunk is not in memory and something on the main thread asks for it directly, the main thread waits in place until the disk read — and if needed, terrain generation — has finished. The whole server is frozen for that duration. Vanilla rarely takes this path during normal play; what usually triggers it is third-party logic fetching a chunk by coordinates inside an event callback, a scheduled task or a command

BAS times the "wait until the chunk is ready" call inside vanilla's ServerChunkCache.getChunk. A wait of at least diagnostics.syncLoadThresholdMs (default 50 ms, one game tick) is recorded with its duration, chunk coordinates, dimension, and the first non-vanilla class on the call stack:

[BetterAutoSave] main-thread sync chunk load: 5188ms at (120,-340) in minecraft:overworld, called from com.example.protection.RegionScanner

Each distinct source prints one line the first time it appears; after that it only accumulates into the table, so a player exploring new terrain cannot flood the log

The instrumented call sits on the branch taken after vanilla's four-slot chunk cache misses: when the requested chunk is already cached, execution never reaches it. On a miss it costs two extra System.nanoTime() calls (tens of nanoseconds), and a stack is captured only once the wait actually exceeds the threshold — during normal operation none is ever captured

3. Inter-tick pauses

Between the end of one tick and the start of the next, the server waits for the next tick while draining its task queue. That time is not part of MSPT. If something in the queue stalls — a task submitted by another mod, a chunk system callback, a command — MSPT can stay perfectly healthy while players have been frozen for ten seconds or more

The default mode takes one timestamp at the start and one at the end of each tick, and records a gap of at least diagnostics.tickGapThresholdMs (default 1000 ms):

[BetterAutoSave] inter-tick gap: 17100ms after tick 148213 (this time is not counted in MSPT)

The default mode reports how long the gap was and which tick it followed, not who caused it. To get down to individual tasks, turn on diagnostics.tickGapDeepAttribution (off by default): it times every task in the server task queue and files those taking more than a tenth of the threshold (100 ms by default) under their actual Runnable type. That mode adds two nanosecond reads per task and the server runs hundreds of tasks per tick, so turn it on only while narrowing down a gap that has already been reported, then turn it back off

4. On how attribution is worded

The detection reports which call chain the block happened on, not who has a bug. Fetching a chunk synchronously is a perfectly reasonable thing to write in many situations; its cost simply scales with server size, view distance and disk speed. Within a 5-second wait, the disk, terrain generation and other load on the same host can each be the dominant factor. Stalls reported by this feature usually reflect another mod's call pattern and are not by themselves evidence of a defect in that mod

Treat attribution as the starting point of an investigation, not its conclusion. The command output carries the same sentence every time:

note: stalls listed above are attributed to the call site, not to a defect in the owning mod.

5. Three ways to read the data

/betterautosave diagnose [count] (default 10, accepts 1-50) prints the running totals and the top N attributions; /betterautosave diagnose reset clears both tables and re-arms the once-per-source log de-duplication. A full sample of the output is in section 8 of docs/CONFIGURATION.en.md

Reset deliberately leaves the cumulative counters (bas_sync_load_stalls_total and friends) alone: Prometheus counters must stay monotonic, and zeroing them breaks rate(). The command reply says so

The periodic diagnostic summary (diagnostics.diagnosticLogging, on by default) gains two lines:

[BetterAutoSave]   |- syncLoad: stalls=37 totalBlocked=48210ms tracked=2 top=examplemod=31400ms x12, com.example.map.RegionCache=14600ms x19
[BetterAutoSave]   `- tickGap: exceeded=2 max=17100ms last=14800ms after tick 148213 deepTasks=0

The Prometheus exporter gains four metrics:

Metric	Type	Meaning
bas_sync_load_stalls_total	counter	Main-thread synchronous chunk loads over the threshold
bas_sync_load_stall_seconds_total	counter	Cumulative seconds blocked in those loads
bas_tick_gap_exceeded_total	counter	Inter-tick gaps over the threshold
bas_tick_gap_max_seconds	gauge	Longest inter-tick gap since server start

6. New settings

Key	Default	Effect
diagnostics.syncLoadDetection	true	Master switch for main-thread sync chunk load detection
diagnostics.syncLoadThresholdMs	50	Minimum single-load block time to record, in milliseconds (1 - 60000)
diagnostics.syncLoadTrackLimit	64	Max tracked (attribution, stack) pairs, LRU beyond that. Takes effect at startup
diagnostics.syncLoadStackDepth	24	Non-vanilla stack frames retained per record (4 - 128)
diagnostics.tickGapDetection	true	Master switch for inter-tick gap detection
diagnostics.tickGapThresholdMs	1000	Minimum gap to record, in milliseconds (50 - 600000)
diagnostics.tickGapDeepAttribution	false	Deep mode: time individual tasks to attribute a gap
diagnostics.tickGapDeepTrackLimit	64	LRU limit for the deep-mode table; ignored while deep mode is off. Takes effect at startup

Everything except the two TrackLimit keys is hot-reloadable and takes effect immediately

7. Known limits

• If a mod that rewrites the chunk-fetch path (something in the C2ME family) is installed alongside, the instrumented call may no longer exist and the probe cannot attach. Sync load detection then silently does nothing instead of failing the server's startup — a purely observational feature is not worth a boot crash. Whether the injection point still exists is guarded by build-time tests rather than a runtime hard check
• Attribution uses the first non-vanilla class on the stack, replaced with a mod id when it can be matched against the loader's mod file scan data and left as the class name when it cannot. When the call chain crosses an event bus, that class may be the subscriber rather than the original caller; the deeper frames are printed under each row in the command output
• The deep-mode "one tenth of the threshold" factor has no measured basis. It is an engineering estimate that a single task contributing to a one-second gap is usually in the 100 ms range. If real servers show too many mid-sized tasks slipping through, it will be promoted to its own setting in a later version
• Both TrackLimit values are frozen when the server starts; changing them requires a restart

8. Behavior change

The periodic diagnostic summary now keeps printing during degraded pipeline sessions, where it used to stop along with the pipeline. Sync loads and inter-tick gaps come from external call patterns and have nothing to do with whether BAS itself is degraded — and a degraded session is often exactly when the data is needed. The side effect is that the save-metrics summary also keeps printing in that state

9. Upgrading

• Drop in the new jar; the on-disk format and every existing setting are unchanged
• Order matters: replace the jar and restart first so the new build writes the 8 new keys into common.toml, then edit them. Editing the config before swapping the jar lets the running old build delete keys it does not recognize
• To opt out, set diagnostics.syncLoadDetection and diagnostics.tickGapDetection to false; both take effect immediately

10. Verification

• The sliding window, p99, LRU eviction and concurrent writes of the tables, the stack filter rules, and the accumulate / keep-maximum semantics of the four new metrics are covered by unit tests, each checked by removing the logic under test and confirming the test fails
• Each build carries a build-time ASM gate asserting that the probe really wraps that wait call and that both the timing and the stack capture happen after it returns — so a later change cannot quietly undo the "no stack captured during normal operation" property
• One honest gap in coverage: the table that turns a class name into a mod id depends on the loader's runtime mod file scan and has no unit test. It falls back to the fully qualified class name when no match is found

11. Why this release adds diagnostics instead of more performance work

BAS has been evaluated to the end of what it can do here: under the extreme compatibility constraints it holds itself to, there is no meaningful async chunk optimization left to take. Where room does remain, taking it would break that compatibility — producing data-safety problems and conflicts between mods

The same 74-player stress test, sampled over 550 seconds: NbtIo writes took 0.03% of main-thread time, ChunkSerializer serialization 0.67%, and everything BAS itself does 1.42% in total. Some room genuinely remains — copySections unconditionally makes two PalettedContainer.copy calls even for empty sections, about 0.1 pp, and batching the POI replay, about 0.1 to 0.2 pp — but all of it is down in the noise, and what can be taken without changing the compatibility premise adds up to less than half a percentage point

Nor can it be said that chunk loading has stopped being the bottleneck. The opposite is true: the bottleneck sits in the half of the chunk system BAS cannot reach. In that same sample, DistanceManager distance-field propagation consumed 82% of the chunk system's main-thread budget, and the tasks actually driving loads forward only 18%

The cost of each further step is concrete. Moving ForgeCaps onto a worker thread belongs to the same family as the data loss in issue #8: mods that attach a chunk capability lose data silently. Moving ChunkDataEvent.Load onto a worker thread calls every listener off the main thread; it throws nothing and simply rots over time. Moving POI / SectionStorage onto a worker thread corrupts villager AI data silently, because SectionStorage is not thread-safe. Taking over DistanceManager means a state machine that is not thread-safe, and a head-on conflict with C2ME. Requiring installation on both sides, or forcing everything async, means giving up single-side installation, opt-in and instant rollback

Performance has reached the limit compatibility allows, so this release changes direction: instead of chasing those last fractions of a percent, the server now says for itself where the stalls come from. The full reasoning is under "明确不做及其理由" in docs/ROADMAP.md