R3944Realms/PlayerSync
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Phase 17: advancements mtime cache + per-item log demotion

Browse Source 
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<absPath, (mtime, content)>):
    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.
This commit is contained in:
laforetbrut 2026-04-22 10:10:21 +02:00
parent 3a908ae131
commit 8b687d20f7
3 changed files with 47 additions and 20 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

43
src/main/java/vip/fubuki/playersync/sync/VanillaSync.java
View File

@ -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<String, AdvancementsCacheEntry> 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));
}
}
}
}

6
src/main/java/vip/fubuki/playersync/sync/addons/ModCompatSync.java
View File

@ -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);

18
src/main/java/vip/fubuki/playersync/sync/addons/ModsSupport.java
View File

@ -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);