diff --git a/Minecraft.Client/MinecraftServer.cpp b/Minecraft.Client/MinecraftServer.cpp index 297ed6a6..94fff020 100644 --- a/Minecraft.Client/MinecraftServer.cpp +++ b/Minecraft.Client/MinecraftServer.cpp @@ -85,6 +85,9 @@ vector MinecraftServer::s_sentTo; int MinecraftServer::s_slowQueuePlayerIndex = 0; int MinecraftServer::s_slowQueueLastTime = 0; bool MinecraftServer::s_slowQueuePacketSent = false; +#ifdef MINECRAFT_SERVER_BUILD +int MinecraftServer::s_dedicatedChunkSendsThisTick = 0; +#endif #endif unordered_map MinecraftServer::ironTimers; @@ -1770,6 +1773,12 @@ void MinecraftServer::run(int64_t seed, void *lpParameter) int64_t unprocessedTime = 0; while (running && !s_bServerHalted) { +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + // Full wall-clock cost of one run loop iteration (catch-up ticks + // + setTime handlers + XUI delayed actions + Sleep). + int64_t outerIterStart = getCurrentTimeMillis(); + int64_t outerIterTickWork = 0; +#endif int64_t now = getCurrentTimeMillis(); // 4J Stu - When we pause the server, we don't want to count that as time passed @@ -1807,15 +1816,39 @@ void MinecraftServer::run(int64_t seed, void *lpParameter) while (unprocessedTime > MS_PER_TICK) { unprocessedTime -= MS_PER_TICK; +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + // Per-iteration pre/tick/post timing. + int64_t iter_t0 = System::currentTimeMillis(); +#endif chunkPacketManagement_PreTick(); - // int64_t before = System::currentTimeMillis(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t iter_t1 = System::currentTimeMillis(); +#endif tick(); - // int64_t after = System::currentTimeMillis(); - // PIXReportCounter(L"Server time",(float)(after-before)); - +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t iter_t2 = System::currentTimeMillis(); +#endif chunkPacketManagement_PostTick(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t iter_t3 = System::currentTimeMillis(); + int64_t iter_total = iter_t3 - iter_t0; + outerIterTickWork += iter_total; + if (iter_total > 60) + { + ServerRuntime::LogInfof("perf", + "iter total=%lldms pre=%lld tick=%lld post=%lld", + (long long)iter_total, + (long long)(iter_t1 - iter_t0), + (long long)(iter_t2 - iter_t1), + (long long)(iter_t3 - iter_t2)); + } +#endif } - lastTime = getCurrentTimeMillis(); + // Do NOT reset lastTime here. Resetting discards the wall + // time spent in the catch-up so passedTime restarts from + // post-tick, capping effective TPS at 1000 / (MS_PER_TICK + // + avgTickBody). Runaway after a real freeze is bounded + // by the passedTime > MS_PER_TICK * 40 cap above. // int64_t afterall = System::currentTimeMillis(); // PIXReportCounter(L"Server time all",(float)(afterall-beforeall)); // PIXReportCounter(L"Server ticks",(float)tickcount); @@ -2101,6 +2134,73 @@ void MinecraftServer::run(int64_t seed, void *lpParameter) } Sleep(1); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t outerIterTotal = getCurrentTimeMillis() - outerIterStart; + + // Distribution histogram (gated). Buckets every outer iter, dumps + // the bucket counts + a self-computed TPS every ~10 seconds. + if (ServerRuntime::g_serverPerfTrace) + { + static const int kBucketCount = 14; + static int64_t s_bucketEdges[kBucketCount] = { + 2, 5, 10, 20, 30, 40, 50, 60, 80, 100, 200, 500, 1000, INT64_MAX + }; + static unsigned int s_buckets[kBucketCount] = {0}; + static int64_t s_histWindowStartMs = 0; + static int s_histWindowStartTick = 0; + static int64_t s_histTotalIterMs = 0; + static unsigned int s_histTotalIters = 0; + static unsigned int s_histTickIters = 0; + int64_t nowMsForHist = getCurrentTimeMillis(); + if (s_histWindowStartMs == 0) + { + s_histWindowStartMs = nowMsForHist; + s_histWindowStartTick = (int)tickCount; + } + for (int b = 0; b < kBucketCount; b++) + { + if (outerIterTotal <= s_bucketEdges[b]) + { + s_buckets[b]++; + break; + } + } + s_histTotalIterMs += outerIterTotal; + s_histTotalIters++; + if (outerIterTickWork > 0) s_histTickIters++; + int ticksThisWindow = (int)tickCount - s_histWindowStartTick; + if (ticksThisWindow >= 200) + { + int64_t windowMs = nowMsForHist - s_histWindowStartMs; + double calcTps = windowMs > 0 ? (ticksThisWindow * 1000.0) / windowMs : 0.0; + double avgIterMs = s_histTotalIters > 0 ? (double)s_histTotalIterMs / s_histTotalIters : 0.0; + ServerRuntime::LogInfof("perf", + "histogram window: %d ticks in %lldms calcTps=%.2f iters=%u tickIters=%u avgIter=%.2fms | " + "<=2:%u <=5:%u <=10:%u <=20:%u <=30:%u <=40:%u <=50:%u <=60:%u <=80:%u <=100:%u <=200:%u <=500:%u <=1000:%u >1000:%u", + ticksThisWindow, (long long)windowMs, calcTps, + s_histTotalIters, s_histTickIters, avgIterMs, + s_buckets[0], s_buckets[1], s_buckets[2], s_buckets[3], + s_buckets[4], s_buckets[5], s_buckets[6], s_buckets[7], + s_buckets[8], s_buckets[9], s_buckets[10], s_buckets[11], + s_buckets[12], s_buckets[13]); + for (int b = 0; b < kBucketCount; b++) s_buckets[b] = 0; + s_histWindowStartMs = nowMsForHist; + s_histWindowStartTick = (int)tickCount; + s_histTotalIterMs = 0; + s_histTotalIters = 0; + s_histTickIters = 0; + } + } + + if (outerIterTotal > 60) + { + ServerRuntime::LogInfof("perf", + "outerIter total=%lldms tickWork=%lld postTickOverhead=%lld", + (long long)outerIterTotal, + (long long)outerIterTickWork, + (long long)(outerIterTotal - outerIterTickWork)); + } +#endif } } //else @@ -2155,6 +2255,17 @@ void MinecraftServer::broadcastStopSavingPacket() void MinecraftServer::tick() { + // Per-substep wall-clock timing. Logs one summary line when total tick + // exceeds TICK_SLOW_THRESHOLD_MS. + const int64_t TICK_SLOW_THRESHOLD_MS = 60; + const int kMaxLevelsRecorded = 8; + int64_t tickStart = System::currentTimeMillis(); + int64_t lvlTickMs[kMaxLevelsRecorded] = {0}; + int64_t lvlEntMs[kMaxLevelsRecorded] = {0}; + int64_t lvlTrkMs[kMaxLevelsRecorded] = {0}; + int lvlDimId[kMaxLevelsRecorded] = {0}; + unsigned int recordedLevels = 0; + vector toRemove; for ( auto& it : ironTimers ) { @@ -2206,11 +2317,21 @@ void MinecraftServer::tick() { players->broadcastAll(std::make_shared(level->getGameTime(), level->getDayTime(), level->getGameRules()->getBoolean(GameRules::RULE_DAYLIGHT)), level->dimension->id); } + // Gate the per-level tick body on dimension activity. Empty + // dimensions skip Level::tick / tickEntities / tracker tick so + // stale chunks loaded by a prior visit do not consume budget. + // Gametime and weather pause for empty dimensions until a + // player returns. + bool dimensionActive = (players->getPlayerCount(level) > 0) || level->hasEntitiesToRemove(); + // #ifndef __PS3__ static int64_t stc = 0; int64_t st0 = System::currentTimeMillis(); PIXBeginNamedEvent(0,"Level tick %d",i); - static_cast(level)->tick(); + if (dimensionActive) + { + static_cast(level)->tick(); + } int64_t st1 = System::currentTimeMillis(); PIXEndNamedEvent(); PIXBeginNamedEvent(0,"Update lights %d",i); @@ -2218,11 +2339,7 @@ void MinecraftServer::tick() int64_t st2 = System::currentTimeMillis(); PIXEndNamedEvent(); PIXBeginNamedEvent(0,"Entity tick %d",i); - // 4J added to stop ticking entities in levels when players are not in those levels. - // Note: now changed so that we also tick if there are entities to be removed, as this also happens as a result of calling tickEntities. If we don't do this, then the - // entities get removed at the first point that there is a player count in the level - this has been causing a problem when going from normal dimension -> nether -> normal, - // as the player is getting flagged as to be removed (from the normal dimension) when going to the nether, but Actually gets removed only when it returns - if( ( players->getPlayerCount(level) > 0) || ( level->hasEntitiesToRemove() ) ) + if (dimensionActive) { #ifdef __PSVITA__ // AP - the PlayerList->viewDistance initially starts out at 3 to make starting a level speedy @@ -2239,17 +2356,34 @@ void MinecraftServer::tick() } PIXEndNamedEvent(); + int64_t stEntDone = System::currentTimeMillis(); + PIXBeginNamedEvent(0,"Entity tracker tick"); - level->getTracker()->tick(); + if (dimensionActive) + { + level->getTracker()->tick(); + } PIXEndNamedEvent(); int64_t st3 = System::currentTimeMillis(); // printf(">>>>>>>>>>>>>>>>>>>>>> Tick %d %d %d : %d\n", st1 - st0, st2 - st1, st3 - st2, st0 - stc ); stc = st0; // #endif// __PS3__ + + // Record per-level breakdown for the slow-tick summary. + if (i < kMaxLevelsRecorded) + { + lvlTickMs[i] = st1 - st0; // Level::tick (mob spawner, chunk source, tile ticks, etc.) + lvlEntMs[i] = stEntDone - st2; // tickEntities (per-entity AI/physics) + lvlTrkMs[i] = st3 - stEntDone; // EntityTracker::tick (visibility & broadcasts) + lvlDimId[i] = level->dimension->id; + recordedLevels = i + 1; + } } } + int64_t afterLevels = System::currentTimeMillis(); Entity::tickExtraWandering(); // 4J added + int64_t afterExtraW = System::currentTimeMillis(); // Process player disconnect/kick queue BEFORE ticking connections. // PendingConnection::handleLogin rejects duplicate XUIDs, so the old @@ -2258,9 +2392,11 @@ void MinecraftServer::tick() PIXBeginNamedEvent(0,"Players tick"); players->tick(); PIXEndNamedEvent(); + int64_t afterPlayers = System::currentTimeMillis(); PIXBeginNamedEvent(0,"Connection tick"); connection->tick(); PIXEndNamedEvent(); + int64_t afterConn = System::currentTimeMillis(); // 4J - removed #if 0 @@ -2274,6 +2410,35 @@ void MinecraftServer::tick() // } catch (Exception e) { // logger.log(Level.WARNING, "Unexpected exception while parsing console command", e); // } + + int64_t totalMs = System::currentTimeMillis() - tickStart; +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + if (totalMs > TICK_SLOW_THRESHOLD_MS) + { + // Build a single one-line breakdown so it greps cleanly. Per-level: + // Level::tick / tickEntities / tracker tick. Then global subsystems. + char buf[512]; + int n = 0; + for (unsigned int i = 0; i < recordedLevels && n >= 0 && n < (int)sizeof(buf); i++) + { + n += snprintf(buf + n, sizeof(buf) - n, + " L%d:tick=%lld ent=%lld trk=%lld", + lvlDimId[i], + (long long)lvlTickMs[i], + (long long)lvlEntMs[i], + (long long)lvlTrkMs[i]); + } + ServerRuntime::LogInfof("perf", + "slow tick total=%lldms%s | extraW=%lld players=%lld conn=%lld", + (long long)totalMs, + buf, + (long long)(afterExtraW - afterLevels), + (long long)(afterPlayers - afterExtraW), + (long long)(afterConn - afterPlayers)); + } +#else + (void)totalMs; +#endif } void MinecraftServer::handleConsoleInput(const wstring& msg, ConsoleInputSource *source) @@ -2417,7 +2582,9 @@ bool MinecraftServer::chunkPacketManagement_CanSendTo(INetworkPlayer *player) if( player == nullptr ) return false; #ifdef MINECRAFT_SERVER_BUILD - return true; + // Cap chunk-data sends per tick. Other players are served on later ticks + // via the per-tick rotation in ServerConnection::tick. + return s_dedicatedChunkSendsThisTick < DEDICATED_MAX_CHUNK_SENDS_PER_TICK; #else int time = GetTickCount(); DWORD currentPlayerCount = g_NetworkManager.GetPlayerCount(); @@ -2436,10 +2603,16 @@ bool MinecraftServer::chunkPacketManagement_CanSendTo(INetworkPlayer *player) void MinecraftServer::chunkPacketManagement_DidSendTo(INetworkPlayer *player) { s_slowQueuePacketSent = true; +#ifdef MINECRAFT_SERVER_BUILD + s_dedicatedChunkSendsThisTick++; +#endif } void MinecraftServer::chunkPacketManagement_PreTick() { +#ifdef MINECRAFT_SERVER_BUILD + s_dedicatedChunkSendsThisTick = 0; +#endif } void MinecraftServer::chunkPacketManagement_PostTick() diff --git a/Minecraft.Client/MinecraftServer.h b/Minecraft.Client/MinecraftServer.h index aa0c4a37..6b76c194 100644 --- a/Minecraft.Client/MinecraftServer.h +++ b/Minecraft.Client/MinecraftServer.h @@ -258,6 +258,12 @@ private: static int s_slowQueuePlayerIndex; static int s_slowQueueLastTime; static bool s_slowQueuePacketSent; +#ifdef MINECRAFT_SERVER_BUILD + // Cap on chunk-data packet sends per tick. Paired with per-tick rotation + // in ServerConnection::tick so every player gets a turn even when bound. + static int s_dedicatedChunkSendsThisTick; + static const int DEDICATED_MAX_CHUNK_SENDS_PER_TICK = 10; +#endif #endif bool IsServerPaused() { return m_isServerPaused; } diff --git a/Minecraft.Client/PlayerChunkMap.cpp b/Minecraft.Client/PlayerChunkMap.cpp index be8143d8..9ac67927 100644 --- a/Minecraft.Client/PlayerChunkMap.cpp +++ b/Minecraft.Client/PlayerChunkMap.cpp @@ -13,6 +13,14 @@ #include "../Minecraft.World/System.h" #include "PlayerList.h" #include +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) +#include "../Minecraft.Server/ServerLogger.h" + +// Per-tick accumulators for tickAddRequests timing. +static int64_t g_findUsAccum = 0; +static int64_t g_addUsAccum = 0; +static int g_addCount = 0; +#endif PlayerChunkMap::PlayerChunk::PlayerChunk(int x, int z, PlayerChunkMap *pcm) : pos(x,z) { @@ -74,7 +82,7 @@ void PlayerChunkMap::PlayerChunk::add(shared_ptr player, bool send players.push_back(player); - player->chunksToSend.push_back(pos); + player->chunksToSend.insert(pos); #ifdef _LARGE_WORLDS parent->getLevel()->cache->dontDrop(pos.x, pos.z); // 4J Added; @@ -118,7 +126,7 @@ void PlayerChunkMap::PlayerChunk::remove(shared_ptr player) parent->getLevel()->cache->drop(pos.x, pos.z); } - player->chunksToSend.remove(pos); + player->chunksToSend.erase(pos); // 4J - I don't think there's any point sending these anymore, as we don't need to unload chunks with fixed sized maps // 4J - We do need to send these to unload entities in chunks when players are dead. If we do not and the entity is removed // while they are dead, that entity will remain in the clients world @@ -369,6 +377,15 @@ ServerLevel *PlayerChunkMap::getLevel() void PlayerChunkMap::tick() { +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + // Substep timing for slow chunkMap diagnostics. + const int64_t CHUNKMAP_SLOW_THRESHOLD_MS = 50; + int64_t cm_t0 = System::currentTimeMillis(); + int cm_addReqStart = (int)addRequests.size(); + g_findUsAccum = 0; + g_addUsAccum = 0; + g_addCount = 0; +#endif int64_t time = level->getGameTime(); if (time - lastInhabitedUpdate > Level::TICKS_PER_DAY / 3) @@ -385,6 +402,9 @@ void PlayerChunkMap::tick() chunk->updateInhabitedTime(); } } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t cm_t1 = System::currentTimeMillis(); +#endif // 4J - some changes here so that we only send one region update per tick. The chunks themselves also // limit their resend rate to once every MIN_TICKS_BETWEEN_REGION_UPDATE ticks @@ -404,11 +424,35 @@ void PlayerChunkMap::tick() i++; } } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t cm_t2 = System::currentTimeMillis(); +#endif for( unsigned int i = 0; i < players.size(); i++ ) { tickAddRequests(players[i]); } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t cm_t3 = System::currentTimeMillis(); + int64_t cm_total = cm_t3 - cm_t0; + if (cm_total > CHUNKMAP_SLOW_THRESHOLD_MS) + { + ServerRuntime::LogInfof("perf", + "L%d chunkMap total=%lldms inhabited=%lld changed=%lld addReq=%lld | players=%d addReqQueue=%d->%d | adds=%d findUs=%lld addUs=%lld avgAddUs=%lld", + this->dimension, + (long long)cm_total, + (long long)(cm_t1 - cm_t0), + (long long)(cm_t2 - cm_t1), + (long long)(cm_t3 - cm_t2), + (int)players.size(), + cm_addReqStart, + (int)addRequests.size(), + g_addCount, + (long long)g_findUsAccum, + (long long)g_addUsAccum, + g_addCount > 0 ? (long long)(g_addUsAccum / g_addCount) : 0LL); + } +#endif // 4J Stu - Added 1.1 but not relevant to us as we never no 0 players anyway, and don't think we should be dropping stuff //if (players.isEmpty()) { @@ -490,7 +534,11 @@ void PlayerChunkMap::getChunkAndRemovePlayer(int x, int z, shared_ptr player) for (int processed = 0; processed < CHUNKS_PER_PLAYER_PER_TICK; processed++) { +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + LARGE_INTEGER qpcFreq, qpcA, qpcB, qpcC; + QueryPerformanceFrequency(&qpcFreq); + QueryPerformanceCounter(&qpcA); +#endif // Find the nearest chunk request to the player int minDistSq = -1; auto itNearest = addRequests.end(); @@ -522,12 +575,21 @@ void PlayerChunkMap::tickAddRequests(shared_ptr player) } } } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + QueryPerformanceCounter(&qpcB); + g_findUsAccum += (qpcB.QuadPart - qpcA.QuadPart) * 1000000 / qpcFreq.QuadPart; +#endif // If we found one, process it and continue; otherwise done if( itNearest != addRequests.end() ) { getChunk(itNearest->x, itNearest->z, true)->add(itNearest->player); addRequests.erase(itNearest); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + QueryPerformanceCounter(&qpcC); + g_addUsAccum += (qpcC.QuadPart - qpcB.QuadPart) * 1000000 / qpcFreq.QuadPart; + g_addCount++; +#endif } else { @@ -781,7 +843,7 @@ bool PlayerChunkMap::isPlayerIn(shared_ptr player, int xChunk, int else { auto it1 = find(chunk->players.begin(), chunk->players.end(), player); - auto it2 = find(player->chunksToSend.begin(), player->chunksToSend.end(), chunk->pos); + auto it2 = player->chunksToSend.find(chunk->pos); return it1 != chunk->players.end() && it2 == player->chunksToSend.end(); } diff --git a/Minecraft.Client/ServerConnection.cpp b/Minecraft.Client/ServerConnection.cpp index 7bf05a9b..9ebf7259 100644 --- a/Minecraft.Client/ServerConnection.cpp +++ b/Minecraft.Client/ServerConnection.cpp @@ -13,6 +13,8 @@ #if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) #include "../Minecraft.Server/Security/SecurityConfig.h" #include "../Minecraft.Server/ServerLogManager.h" +#include "../Minecraft.Server/ServerLogger.h" +#include "../Minecraft.World/System.h" #endif ServerConnection::ServerConnection(MinecraftServer *server) @@ -129,16 +131,45 @@ void ServerConnection::tick() vector< shared_ptr > tempPlayers = players; LeaveCriticalSection(&players_cs); - for (unsigned int i = 0; i < tempPlayers.size(); i++) +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + // Substep timing for chunk / tick / flush across all players. + LARGE_INTEGER scFreq, scA, scB, scC, scD; + QueryPerformanceFrequency(&scFreq); + int64_t sc_chunkUs = 0; + int64_t sc_tickUs = 0; + int64_t sc_flushUs = 0; + int64_t sc_loopT0 = System::currentTimeMillis(); +#endif + + // Rotate the per-tick start offset so the chunk-send cap doesn't + // starve players at the back of the vector. + static unsigned int s_chunkRotationOffset = 0; + s_chunkRotationOffset++; + size_t playerCount = tempPlayers.size(); + size_t startIdx = playerCount > 0 ? (s_chunkRotationOffset % playerCount) : 0; + + for (unsigned int k = 0; k < tempPlayers.size(); k++) { + unsigned int i = (unsigned int)((startIdx + k) % playerCount); shared_ptr player = tempPlayers[i]; shared_ptr serverPlayer = player->getPlayer(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + QueryPerformanceCounter(&scA); +#endif if( serverPlayer ) { serverPlayer->updateFrameTick(); serverPlayer->doChunkSendingTick(false); } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + QueryPerformanceCounter(&scB); + sc_chunkUs += (scB.QuadPart - scA.QuadPart) * 1000000 / scFreq.QuadPart; +#endif player->tick(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + QueryPerformanceCounter(&scC); + sc_tickUs += (scC.QuadPart - scB.QuadPart) * 1000000 / scFreq.QuadPart; +#endif if (player->done) { EnterCriticalSection(&players_cs); @@ -150,7 +181,28 @@ void ServerConnection::tick() { player->connection->flush(); } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + QueryPerformanceCounter(&scD); + sc_flushUs += (scD.QuadPart - scC.QuadPart) * 1000000 / scFreq.QuadPart; +#endif } + +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + int64_t sc_loopTotal = System::currentTimeMillis() - sc_loopT0; + if (sc_loopTotal > 50) + { + ServerRuntime::LogInfof("perf", + "conn playerLoop total=%lldms players=%d chunkUs=%lld tickUs=%lld flushUs=%lld | avg chunk=%lld tick=%lld flush=%lld", + (long long)sc_loopTotal, + (int)tempPlayers.size(), + (long long)sc_chunkUs, + (long long)sc_tickUs, + (long long)sc_flushUs, + tempPlayers.size() > 0 ? (long long)(sc_chunkUs / tempPlayers.size()) : 0LL, + tempPlayers.size() > 0 ? (long long)(sc_tickUs / tempPlayers.size()) : 0LL, + tempPlayers.size() > 0 ? (long long)(sc_flushUs / tempPlayers.size()) : 0LL); + } +#endif } } diff --git a/Minecraft.Client/ServerLevel.cpp b/Minecraft.Client/ServerLevel.cpp index f2a5c75f..7d34f7cc 100644 --- a/Minecraft.Client/ServerLevel.cpp +++ b/Minecraft.Client/ServerLevel.cpp @@ -41,6 +41,7 @@ #include "PlayerChunkMap.h" #if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) #include "../Minecraft.Server/FourKitBridge.h" +#include "../Minecraft.Server/ServerLogger.h" #endif WeighedTreasureArray ServerLevel::RANDOM_BONUS_ITEMS; @@ -197,6 +198,14 @@ ServerLevel::~ServerLevel() void ServerLevel::tick() { +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + // ts[N] = wall-clock at substep N. Logged when level total exceeds + // LEVEL_SLOW_THRESHOLD_MS to pinpoint the dominant substep. + const int64_t LEVEL_SLOW_THRESHOLD_MS = 50; + int64_t ts[13]; + ts[0] = System::currentTimeMillis(); +#endif + Level::tick(); if (getLevelData()->isHardcore() && difficulty < 3) { @@ -218,6 +227,9 @@ void ServerLevel::tick() } awakenAllPlayers(); } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[1] = System::currentTimeMillis(); +#endif PIXBeginNamedEvent(0,"Mob spawner tick"); // for Minecraft 1.8, spawn friendlies really rarely - 4J - altered from once every 400 ticks to 40 ticks as we depend on this a more than the original since we don't have chunk post-process spawning @@ -233,6 +245,9 @@ void ServerLevel::tick() mobSpawner->tick(this, finalSpawnEnemies, finalSpawnFriendlies, finalSpawnPersistent); } PIXEndNamedEvent(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[2] = System::currentTimeMillis(); +#endif PIXBeginNamedEvent(0,"Chunk source tick"); chunkSource->tick(); PIXEndNamedEvent(); @@ -248,6 +263,9 @@ void ServerLevel::tick() } } } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[3] = System::currentTimeMillis(); +#endif //4J - temporarily disabling saves as they are causing gameplay to generally stutter quite a lot @@ -263,6 +281,9 @@ void ServerLevel::tick() save(false, nullptr); PIXEndNamedEvent(); } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[4] = System::currentTimeMillis(); +#endif // 4J : WESTY : Changed so that time update goes through stats tracking update code. //levelData->setTime(time); @@ -278,19 +299,31 @@ void ServerLevel::tick() setDayTime(levelData->getDayTime() + 1); } } +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[5] = System::currentTimeMillis(); +#endif PIXBeginNamedEvent(0,"Tick pending ticks"); // if (tickCount % 5 == 0) { tickPendingTicks(false); PIXEndNamedEvent(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[6] = System::currentTimeMillis(); +#endif PIXBeginNamedEvent(0,"Tick tiles"); MemSect(18); tickTiles(); MemSect(0); PIXEndNamedEvent(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[7] = System::currentTimeMillis(); +#endif chunkMap->tick(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[8] = System::currentTimeMillis(); +#endif PIXBeginNamedEvent(0,"Tick villages"); //MemSect(18); @@ -298,18 +331,50 @@ void ServerLevel::tick() villageSiege->tick(); //MemSect(0); PIXEndNamedEvent(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[9] = System::currentTimeMillis(); +#endif PIXBeginNamedEvent(0,"Tick portal forcer"); portalForcer->tick(getGameTime()); PIXEndNamedEvent(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[10] = System::currentTimeMillis(); +#endif // repeat after tile ticks PIXBeginNamedEvent(0,"runTileEvents"); runTileEvents(); PIXEndNamedEvent(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[11] = System::currentTimeMillis(); +#endif // 4J Added runQueuedSendTileUpdates(); +#if defined(_WINDOWS64) && defined(MINECRAFT_SERVER_BUILD) + ts[12] = System::currentTimeMillis(); + int64_t levelTotal = ts[12] - ts[0]; + if (levelTotal > LEVEL_SLOW_THRESHOLD_MS) + { + ServerRuntime::LogInfof("perf", + "L%d substep total=%lldms base=%lld spawn=%lld chunkSrc=%lld save=%lld time=%lld pending=%lld tiles=%lld chunkMap=%lld villages=%lld portal=%lld evt=%lld sendTU=%lld", + dimension->id, + (long long)levelTotal, + (long long)(ts[1] - ts[0]), + (long long)(ts[2] - ts[1]), + (long long)(ts[3] - ts[2]), + (long long)(ts[4] - ts[3]), + (long long)(ts[5] - ts[4]), + (long long)(ts[6] - ts[5]), + (long long)(ts[7] - ts[6]), + (long long)(ts[8] - ts[7]), + (long long)(ts[9] - ts[8]), + (long long)(ts[10] - ts[9]), + (long long)(ts[11] - ts[10]), + (long long)(ts[12] - ts[11])); + } +#endif } Biome::MobSpawnerData *ServerLevel::getRandomMobSpawnAt(MobCategory *mobCategory, int x, int y, int z) diff --git a/Minecraft.Client/ServerPlayer.cpp b/Minecraft.Client/ServerPlayer.cpp index 932f5976..d619383a 100644 --- a/Minecraft.Client/ServerPlayer.cpp +++ b/Minecraft.Client/ServerPlayer.cpp @@ -474,28 +474,82 @@ void ServerPlayer::doTickA() } // 4J - split off the chunk sending bit of the tick here from ::doTick so we can do this exactly once per player per server tick +// +// Find-nearest uses spiral iteration from the player's chunk position with +// O(1) hash lookups against chunksToSend. A bounded fallback walk covers +// the rare case of a stale entry outside the spiral radius. void ServerPlayer::doChunkSendingTick(bool dontDelayChunks) { // printf("[%d] %s: sendChunks: %d, empty: %d\n",tickCount, connection->getNetworkPlayer()->GetUID().getOnlineID(),sendChunks,chunksToSend.empty()); if (!chunksToSend.empty()) { - ChunkPos nearest = chunksToSend.front(); + ChunkPos nearest(0, 0); bool nearestValid = false; - - // 4J - reinstated and optimised some code that was commented out in the original, to make sure that we always - // send the nearest chunk to the player. The original uses the bukkit sorting thing to try and avoid doing this, but - // the player can quickly wander away from the centre of the spiral of chunks that that method creates, long before transmission - // of them is complete. double dist = DBL_MAX; - for(ChunkPos chunk : chunksToSend) + + const int px = (int)floor(x) >> 4; + const int pz = (int)floor(z) >> 4; + // Bound on spiral radius. Configured view distance is much smaller. + const int kMaxSpiralRadius = 32; + + // Inline distance: ChunkPos::distanceToSqr is non-const so it can't + // be called on the const refs we get when iterating an unordered_set. + auto chunkDistSq = [&](int cx, int cz) -> double { + double xPos = cx * 16.0 + 8.0; + double zPos = cz * 16.0 + 8.0; + double xd = xPos - this->x; + double zd = zPos - this->z; + return xd * xd + zd * zd; + }; + + // Ring r=0: the player's own chunk. { - if( level->isChunkFinalised(chunk.x, chunk.z) ) + ChunkPos cp(px, pz); + auto it = chunksToSend.find(cp); + if (it != chunksToSend.end() && level->isChunkFinalised(cp.x, cp.z)) { - double newDist = chunk.distanceToSqr(x, z); - if ( (!nearestValid) || (newDist < dist) ) + nearest = cp; + dist = chunkDistSq(cp.x, cp.z); + nearestValid = true; + } + } + + // Rings r>=1: Chebyshev perimeter. First ring with a match wins; + // within it pick the closest by true Euclidean distance. + for (int r = 1; r <= kMaxSpiralRadius && !nearestValid; r++) + { + for (int dx = -r; dx <= r; dx++) + { + for (int dz = -r; dz <= r; dz++) { - nearest = chunk; - dist = chunk.distanceToSqr(x, z); + int adx = dx < 0 ? -dx : dx; + int adz = dz < 0 ? -dz : dz; + if ((adx > adz ? adx : adz) != r) continue; // perimeter only + ChunkPos cp(px + dx, pz + dz); + if (chunksToSend.find(cp) == chunksToSend.end()) continue; + if (!level->isChunkFinalised(cp.x, cp.z)) continue; + double d = chunkDistSq(cp.x, cp.z); + if (!nearestValid || d < dist) + { + nearest = cp; + dist = d; + nearestValid = true; + } + } + } + } + + // Fallback for chunks outside the spiral radius (rare). + if (!nearestValid) + { + for (const ChunkPos& cp : chunksToSend) + { + if (!level->isChunkFinalised(cp.x, cp.z)) continue; + double d = chunkDistSq(cp.x, cp.z); + if (!nearestValid || d < dist) + { + nearest = cp; + dist = d; nearestValid = true; } } @@ -564,7 +618,7 @@ void ServerPlayer::doChunkSendingTick(bool dontDelayChunks) { ServerLevel *level = server->getLevel(dimension); int flagIndex = getFlagIndexForChunk(nearest,this->level->dimension->id); - chunksToSend.remove(nearest); + chunksToSend.erase(nearest); bool chunkDataSent = false; diff --git a/Minecraft.Client/ServerPlayer.h b/Minecraft.Client/ServerPlayer.h index 1b2111dd..2ba663f6 100644 --- a/Minecraft.Client/ServerPlayer.h +++ b/Minecraft.Client/ServerPlayer.h @@ -25,7 +25,9 @@ public: MinecraftServer *server; ServerPlayerGameMode *gameMode; double lastMoveX, lastMoveZ; - list chunksToSend; + // Hash set for O(1) membership/erase. Find-nearest is done via + // spiral iteration in ServerPlayer::doChunkSendingTick, not a sweep. + unordered_set chunksToSend; vector entitiesToRemove; unordered_set seenChunks; int spewTimer; diff --git a/Minecraft.Server/ServerLogger.cpp b/Minecraft.Server/ServerLogger.cpp index 175b7fea..f8d29c7c 100644 --- a/Minecraft.Server/ServerLogger.cpp +++ b/Minecraft.Server/ServerLogger.cpp @@ -15,6 +15,8 @@ static volatile LONG g_minLogLevel = (LONG)eServerLogLevel_Info; static FILE *g_logFile = NULL; static std::once_flag g_logFileOnce; +bool g_serverPerfTrace = false; + static void OpenLogFile() { if (g_logFile != NULL) diff --git a/Minecraft.Server/ServerLogger.h b/Minecraft.Server/ServerLogger.h index 89b820e6..d5d35bce 100644 --- a/Minecraft.Server/ServerLogger.h +++ b/Minecraft.Server/ServerLogger.h @@ -41,4 +41,9 @@ namespace ServerRuntime void LogStartupStep(const char *message); void LogWorldIO(const char *message); void LogWorldName(const char *prefix, const std::wstring &name); + + // When true, noisy [perf] sampling output (histograms, per-iter samples) + // is enabled. Threshold-fired warnings remain always-on. Toggled via the + // -perftrace CLI flag. + extern bool g_serverPerfTrace; } diff --git a/Minecraft.Server/Windows64/ServerMain.cpp b/Minecraft.Server/Windows64/ServerMain.cpp index c2a03899..33eecfde 100644 --- a/Minecraft.Server/Windows64/ServerMain.cpp +++ b/Minecraft.Server/Windows64/ServerMain.cpp @@ -166,6 +166,7 @@ static void PrintUsage() ServerRuntime::LogInfo("usage", " -maxplayers <1-8> Public slots (default: server.properties:max-players)"); ServerRuntime::LogInfo("usage", " -seed World seed (overrides server.properties:level-seed)"); ServerRuntime::LogInfo("usage", " -loglevel debug|info|warn|error (default: server.properties:log-level)"); + ServerRuntime::LogInfo("usage", " -perftrace Enable noisy [perf] sampling output (histograms, per-iter samples)"); ServerRuntime::LogInfo("usage", " -help Show this help"); } @@ -272,6 +273,10 @@ static bool ParseCommandLine(int argc, char **argv, DedicatedServerConfig *confi return false; } } + else if (_stricmp(arg, "-perftrace") == 0) + { + ServerRuntime::g_serverPerfTrace = true; + } else { LogErrorf("startup", "Unknown or incomplete argument: %s", arg); diff --git a/tools/stress-test/test_fourkit_steady.bat b/tools/stress-test/test_fourkit_steady.bat new file mode 100644 index 00000000..4a6250a0 --- /dev/null +++ b/tools/stress-test/test_fourkit_steady.bat @@ -0,0 +1,29 @@ +@echo off +REM FourKit steady-state TPS validation: 50 concurrent moving bots that stay +REM connected for the full duration with NO disconnect/reconnect rotation. The +REM "real workload" complement to test_fourkit_chunk.bat. Isolates steady-state +REM per-tick cost from the mass-disconnect cleanup spikes that bot rotation +REM triggers. Validates that chunk-send throttles hold 20 TPS at scale once +REM the initial scatter chunk-load wave has drained. +REM +REM Suggested in-game routine while this is running: +REM 1. Wait ~10s for bots to fully join. +REM 2. Run /fktest scatter to spread them across the world. +REM 3. Wait ~30-60s for chunk-load wave to drain. +REM 4. Run /fktest tps and read the 5s/30s/60s windows. +REM +REM Set require-secure-client=false in server.properties before running. The +REM 100-tick cipher handshake grace cannot keep up with 50 simultaneous bot +REM joins, which is unrelated to what this test is measuring. +set /p HOST="Server IP [127.0.0.1]: " || set HOST=127.0.0.1 +set /p PORT="Server Port [25565]: " || set PORT=25565 +if "%HOST%"=="" set HOST=127.0.0.1 +if "%PORT%"=="" set PORT=25565 +REM --hold 99999 99999 : bots never reach the hold timeout during the run, so +REM they stay connected for the full duration. +REM --cycles 0 : the spawner keeps launching until --bots is reached. +REM (cycles is a global spawn counter, NOT a per-bot +REM reconnect cap; cycles=1 would cap total spawns at 1.) +REM --duration 600 : 10-minute run; cap at whatever you need +python "%~dp0stress_test.py" %HOST% %PORT% --bots 50 --burst 10 --move --hold 99999 99999 --ramp 0.5 --duration 600 --cycles 0 --quiet +pause