From 8b687d20f7149eff17fdd0000fc9f4835debb0cd Mon Sep 17 00:00:00 2001 From: laforetbrut Date: Wed, 22 Apr 2026 10:10:21 +0200 Subject: [PATCH] Phase 17: advancements mtime cache + per-item log demotion MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two quality-of-life peaufinages. (1) Advancements file mtime cache [VanillaSync.snapshotPlayerData] Each snapshot previously called Files.readAllBytes() on the player's advancement JSON — a main-thread disk read of 1-50ms depending on storage. On a 35-player server with periodic saves + SaveToFile every autosave tick, this adds up. New advancementsFileCache (ConcurrentHashMap): check the file's lastModified() first; reuse the cached string when mtime is unchanged. PlayerAdvancements.save() still flushes pending changes, and Minecraft only touches the file when something actually changes — so mtime is a reliable staleness signal. Cache is process-wide (paths include player UUID so no cross-contamination). Expected impact: -5 to -30ms off main-thread snapshot for idle-ish players, zero for players who just earned advancements. (2) Log spam reduction The restore/save paths chatter one INFO line per item (backpack / SS / RS2 disk / accessories / cosmetic / attachments). On a server with multiple players, each with multiple storage items, this floods sync.log with per-UUID noise that has zero diagnostic value once the 'it's working' phase is past. Demoted to DEBUG: - [restore-backpack] uuid=X nbt_keys=N cleared_via=api - [restore-ss] uuid=X nbt_keys=N - Storing backpack data for player X - Saved backpack data for UUID X - Scanning inventory for Sophisticated Storage items for player X - Saved Sophisticated Storage item data for UUID X - Saved RS2 disk data for UUID X via save() NBT - Saved RS2 disk data for UUID X via codec reflection - Restored RS2 disk data for UUID X - Restored Accessories data for player X - Restored CosmeticArmor data for player X - Restored NeoForge attachments for player X Kept at INFO (per-save summaries): - Saved N RS2 disk(s) via direct codec (player-scoped) - Saved N RS2 disk(s) via legacy full-save fallback - Logout save completed for player X in Nms - Sync data for player X completed in Nms - [perf-logout] core=Xms backpacks=Yms ss=Zms rs2=Wms total=Nms - [emergency-flush] flushed N players Net effect: sync.log goes from ~10 lines per cross-server transfer to ~3. Still full diagnostic trace available with log_level=DEBUG. Unchanged behavior, faster snapshots, cleaner logs. --- .../fubuki/playersync/sync/VanillaSync.java | 43 +++++++++++++++---- .../playersync/sync/addons/ModCompatSync.java | 6 +-- .../playersync/sync/addons/ModsSupport.java | 18 ++++---- 3 files changed, 47 insertions(+), 20 deletions(-) diff --git a/src/main/java/vip/fubuki/playersync/sync/VanillaSync.java b/src/main/java/vip/fubuki/playersync/sync/VanillaSync.java index 9240e27..498268e 100644 --- a/src/main/java/vip/fubuki/playersync/sync/VanillaSync.java +++ b/src/main/java/vip/fubuki/playersync/sync/VanillaSync.java @@ -148,6 +148,23 @@ public class VanillaSync { lastWrittenSnapshotHash.remove(uuid); } + /** + * PHASE 17 PERF: advancements JSON cache keyed by absolute file path. + * Keeps the mtime along with the content — a mismatch on either forces a + * fresh disk read. The cache is process-wide (not per-player) because the + * path already includes the player UUID. + */ + private static final ConcurrentHashMap advancementsFileCache = new ConcurrentHashMap<>(); + + private static final class AdvancementsCacheEntry { + final long mtime; + final String content; + AdvancementsCacheEntry(long mtime, String content) { + this.mtime = mtime; + this.content = content; + } + } + /** * PHASE 7 PERF: per-player hash of the last successfully-written snapshot. * Auto-save / periodic / dimension-change BG tasks skip the DB write when @@ -1854,20 +1871,30 @@ public class VanillaSync { } } - // Advancements (file read, fast) - // FIX: Default to null instead of "". When null, writeSnapshotToDB preserves - // the existing DB value via COALESCE. Previously, if the file read failed - // (save() threw, file missing, path wrong), "" was written to DB, silently - // wiping all advancements every 5 minutes (periodic save) or on logout. + // PHASE 17 PERF: advancements file read — main-thread I/O was ~10-50ms per + // snapshot on mechanical disk / slow network mount. Cache the content by + // (absolute path + last-modified timestamp); reuse the cached string if + // neither changed since the last snapshot. Minecraft's advancement save + // only writes the file when something actually changed, so mtime is a + // reliable freshness signal. PlayerAdvancements.save() is still called + // to flush pending changes to disk. String advancements = null; if (JdbcConfig.SYNC_ADVANCEMENTS.get() && player instanceof ServerPlayer sp) { try { sp.getAdvancements().save(); } catch (Exception ignored) {} Path path = sp.getServer().getServerDirectory().resolve(getSyncWorldForServer()); File advFile = new File(path.toFile(), "/advancements/" + uuid + ".json"); if (advFile.exists()) { - String content = new String(Files.readAllBytes(advFile.toPath()), StandardCharsets.UTF_8); - if (content != null && !content.isEmpty()) { - advancements = content; + String absPath = advFile.getAbsolutePath(); + long mtime = advFile.lastModified(); + AdvancementsCacheEntry cached = advancementsFileCache.get(absPath); + if (cached != null && cached.mtime == mtime && cached.content != null) { + advancements = cached.content; + } else { + String content = new String(Files.readAllBytes(advFile.toPath()), StandardCharsets.UTF_8); + if (content != null && !content.isEmpty()) { + advancements = content; + advancementsFileCache.put(absPath, new AdvancementsCacheEntry(mtime, content)); + } } } } diff --git a/src/main/java/vip/fubuki/playersync/sync/addons/ModCompatSync.java b/src/main/java/vip/fubuki/playersync/sync/addons/ModCompatSync.java index 13a5899..7914340 100644 --- a/src/main/java/vip/fubuki/playersync/sync/addons/ModCompatSync.java +++ b/src/main/java/vip/fubuki/playersync/sync/addons/ModCompatSync.java @@ -167,7 +167,7 @@ public class ModCompatSync { } } - PlayerSync.LOGGER.info("Restored Accessories data for player {}", player.getUUID()); + PlayerSync.LOGGER.debug("Restored Accessories data for player {}", player.getUUID()); } catch (Exception e) { PlayerSync.LOGGER.error("Error restoring Accessories data for player {}", player.getUUID(), e); } @@ -324,7 +324,7 @@ public class ModCompatSync { // Mark the inventory as changed so the mod syncs to the client cosInv.setChanged(); - PlayerSync.LOGGER.info("Restored CosmeticArmor data for player {}", player.getUUID()); + PlayerSync.LOGGER.debug("Restored CosmeticArmor data for player {}", player.getUUID()); } catch (Exception e) { PlayerSync.LOGGER.error("Error restoring CosmeticArmor data for player {}", player.getUUID(), e); @@ -441,7 +441,7 @@ public class ModCompatSync { DESERIALIZE_ATTACHMENTS.invoke(player, serverPlayer.getServer().registryAccess(), wrapper); - PlayerSync.LOGGER.info("Restored NeoForge attachments for player {} ({} keys)", + PlayerSync.LOGGER.debug("Restored NeoForge attachments for player {} ({} keys)", player.getUUID(), attachments.getAllKeys().size()); } catch (Exception e) { PlayerSync.LOGGER.error("Error restoring NeoForge attachments for player {}", player.getUUID(), e); diff --git a/src/main/java/vip/fubuki/playersync/sync/addons/ModsSupport.java b/src/main/java/vip/fubuki/playersync/sync/addons/ModsSupport.java index b43730c..e4e435f 100644 --- a/src/main/java/vip/fubuki/playersync/sync/addons/ModsSupport.java +++ b/src/main/java/vip/fubuki/playersync/sync/addons/ModsSupport.java @@ -80,7 +80,7 @@ public class ModsSupport { // Defensive copy: never hand upstream a tag that might be mutated elsewhere. CompoundTag fresh = nbt.copy(); store.setBackpackContents(contentsUuid, fresh); - PlayerSync.LOGGER.info("[restore-backpack] uuid={} nbt_keys={} cleared_via={}", + PlayerSync.LOGGER.debug("[restore-backpack] uuid={} nbt_keys={} cleared_via={}", contentsUuid, fresh.getAllKeys().size(), cleared ? "api" : "reflection"); }); } @@ -517,7 +517,7 @@ public class ModsSupport { // ============================ public static void storeSophisticatedBackpacks(Player player) { - PlayerSync.LOGGER.info("Storing backpack data for player {}", player.getUUID()); + PlayerSync.LOGGER.debug("Storing backpack data for player {}", player.getUUID()); net.p3pp3rf1y.sophisticatedbackpacks.util.PlayerInventoryProvider.get().runOnBackpacks(player, (ItemStack backpackItem, String handler, String identifier, int slot) -> { net.p3pp3rf1y.sophisticatedbackpacks.backpack.wrapper.IBackpackWrapper backpackWrapper = net.p3pp3rf1y.sophisticatedbackpacks.backpack.wrapper.BackpackWrapper .fromStack(backpackItem); @@ -540,7 +540,7 @@ public class ModsSupport { CompoundTag backpackNbt = net.p3pp3rf1y.sophisticatedbackpacks.backpack.BackpackStorage.get().getOrCreateBackpackContents(contentsUuid); saveStorageContents(contentsUuid, backpackNbt); - PlayerSync.LOGGER.info("Saved backpack data for UUID {}", contentsUuid); + PlayerSync.LOGGER.debug("Saved backpack data for UUID {}", contentsUuid); } else { PlayerSync.LOGGER.warn("Backpack item in slot {} has no contentsUuid", slot); } @@ -777,7 +777,7 @@ public class ModsSupport { * The item's CustomData contains a "contentsUuid" field pointing to the storage data. */ public static void storeSophisticatedStorageItems(Player player) { - PlayerSync.LOGGER.info("Scanning inventory for Sophisticated Storage items for player {}", player.getUUID()); + PlayerSync.LOGGER.debug("Scanning inventory for Sophisticated Storage items for player {}", player.getUUID()); scanAndStoreSophisticatedStorageInContainer(player.getInventory()); // Also scan ender chest for (int i = 0; i < player.getEnderChestInventory().getContainerSize(); i++) { @@ -813,7 +813,7 @@ public class ModsSupport { .getOrCreateStorageContents(contentsUuid); if (storageNbt != null && !storageNbt.isEmpty()) { saveStorageContents(contentsUuid, storageNbt); - PlayerSync.LOGGER.info("Saved Sophisticated Storage item data for UUID {}", contentsUuid); + PlayerSync.LOGGER.debug("Saved Sophisticated Storage item data for UUID {}", contentsUuid); } } catch (Exception e) { PlayerSync.LOGGER.error("Error saving Sophisticated Storage data for item", e); @@ -863,7 +863,7 @@ public class ModsSupport { clearSSStorageContents(store, finalUuid); CompoundTag fresh = nbt.copy(); store.setStorageContents(finalUuid, fresh); - PlayerSync.LOGGER.info("[restore-ss] uuid={} nbt_keys={}", finalUuid, fresh.getAllKeys().size()); + PlayerSync.LOGGER.debug("[restore-ss] uuid={} nbt_keys={}", finalUuid, fresh.getAllKeys().size()); } catch (Exception e) { PlayerSync.LOGGER.error("Error restoring Sophisticated Storage data for UUID {}", finalUuid, e); } @@ -1091,7 +1091,7 @@ public class ModsSupport { net.minecraft.nbt.CompoundTag entryNbt = findRS2EntryInNbt(fullNbt, uuidStr); if (entryNbt != null && !entryNbt.isEmpty()) { saveStorageContents(uuid, entryNbt); - PlayerSync.LOGGER.info("Saved RS2 disk data for UUID {} via save() NBT", uuid); + PlayerSync.LOGGER.debug("Saved RS2 disk data for UUID {} via save() NBT", uuid); continue; } @@ -1128,7 +1128,7 @@ public class ModsSupport { net.minecraft.nbt.Tag encodedTag = (net.minecraft.nbt.Tag) encodeResult.result().get(); if (encodedTag instanceof net.minecraft.nbt.CompoundTag encodedCompound) { saveStorageContents(uuid, encodedCompound); - PlayerSync.LOGGER.info("Saved RS2 disk data for UUID {} via codec reflection", uuid); + PlayerSync.LOGGER.debug("Saved RS2 disk data for UUID {} via codec reflection", uuid); } } else { PlayerSync.LOGGER.error("RS2 codec encode failed for UUID {}: {}", uuid, encodeResult.error()); @@ -1349,7 +1349,7 @@ public class ModsSupport { PlayerSync.LOGGER.error("RS2 reflection fallback also failed for UUID {}", entry.getKey(), reflectEx); } } - PlayerSync.LOGGER.info("Restored RS2 disk data for UUID {}", entry.getKey()); + PlayerSync.LOGGER.debug("Restored RS2 disk data for UUID {}", entry.getKey()); } } else { PlayerSync.LOGGER.error("RS2 codec decode failed for UUID {}", uuid);