BZC DLL Lag Debugging

Moderators: GSH, VSMIT, Red Devil, Commando

Post Reply
User avatar
General BlackDragon
Flying Mauler
Posts: 2408
Joined: Sat Feb 19, 2011 6:37 am
Contact:

BZC DLL Lag Debugging

Post by General BlackDragon »

So, with enough logging and debugging, I managed to isolate a lag spike possibly caused by DLL, or game's Goto command, but I can't determine why it lags.

The map in question is 2048x2048 with the following objects:

Total Objects: 370
--Scrap: 287
--Pools: 25
--Spawns: 5
--The rest are props and a few bolt mines.

The game had 4 AI teams, so 5 recyclers total including the player spawned at start. 4 AI start building things, but overall shouldn't build more then a few scavs, fighters, and beginning of base before the lag occurs, so number of objects only goes up by about 30 or so.

The logging in my Log file says:

Code: Select all

DIAG|            iconsole:529  |18:35:59|870565 |[CONSOLE] Index is: 44, DispatchMode is: 1, DispatchMethod is: 1
DIAG|            iconsole:529  |18:35:59|870565 |[CONSOLE] CPU Clock Time: 870.000000, ClocksSinceLast: 16786, DispatchHelper::Idle Turret 1 1.
DIAG|            iconsole:529  |18:35:59|870565 |[CONSOLE] CPU Clock Time: 870.000000, ClocksSinceLast: 16786, DispatchHelper::Idle Turret 1 1.
DIAG|            iconsole:529  |18:35:59|870565 |[CONSOLE] Index is: 44 Mode is: 1 Method is: 1 Spot is: 344.459015 4.278688 -176.542465
DIAG|            iconsole:529  |18:35:59|870598 |[CONSOLE] Uhoh- want to overwrite moves for 0/'Vadam' at 15669 (pos 309). Old TS 15157, lastResync -990.
DIAG|            iconsole:529  |18:35:59|870598 |[CONSOLE] WorldCount=1. Turns = 15167, 012 = 15167 0 0. Now = 15669. nextCopy = 0

DIAG|            iconsole:529  |18:35:59|870598 |[CONSOLE] Movelag forced quit. Slowest=Vadam @ 15157..15668
DIAG|            iconsole:529  |18:35:59|870598 |[CONSOLE]  local=15157..15668 CTS=15669
DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE] Uhoh- want to overwrite moves for 0/'Vadam' at 15670 (pos 310). Old TS 15158, lastResync -990.
DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE] WorldCount=1. Turns = 15167, 012 = 15167 0 0. Now = 15670. nextCopy = 0

DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE] Movelag forced quit. Slowest=Vadam @ 15157..15668
DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE]  local=15157..15668 CTS=15670
DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE] Uhoh- want to overwrite moves for 0/'Vadam' at 15671 (pos 311). Old TS 15159, lastResync -990.
DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE] WorldCount=1. Turns = 15167, 012 = 15167 0 0. Now = 15671. nextCopy = 0

DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE] Movelag forced quit. Slowest=Vadam @ 15157..15668
DIAG|            iconsole:529  |18:35:59|870599 |[CONSOLE]  local=15157..15668 CTS=15671
DIAG|      MissionHandler:3487 |18:35:59|870654 |Updated 11 turns at once. That's enough. Ought to render something now...
DIAG|      MissionHandler:3487 |18:35:59|870745 |Updated 11 turns at once. That's enough. Ought to render something now...
DIAG|      MissionHandler:3487 |18:35:59|870818 |Updated 11 turns at once. That's enough. Ought to render something now...
Below is the excerpt of the code running. According to the logging the code printed, the clock() function reportedly took 16786 cpu clocks to execute the below code. All other areas that pop up in the logging (which currently prints if the clock() took > 10 between calls) only take, at most, 300 or so. CLOCKS_PER_SEC is defined as 1000, which means 16,786 clocks is roughly 16 seconds, which is waaaay too long. So, without further adieu:

Code: Select all

						CheckLag("DispatchHelper::Idle Start."); // LagLogging. (this resets the clock count)

						// If it's idle timer's up, and it's not currently doing something, lets figure out what to tell it to do.
						if( (BZ1Helper::m_TurnCounter >= iter->IdleTime) && 
							(IsIdle(iter->DispatchObject)) && //(GetCurrentCommand(iter->DispatchObject) == CMD_NONE) && 
							((iter->SkipAIPCheck) || (teamInfo.m_CPUDoDispatch)))
						{
							switch (iter->DispatchType)
							{
							case DispatchType_Turret: // Turrets, randomly go to either A: Near Our Base, B: Scrap Fields, or C: Near Enemy Base. Units, just pick a random target.
								{
									Handle Enemy = GetNearestEnemy(iter->DispatchObject);
									Vector EnemyPosition = GetPosition(Enemy);

									// If it's a Turret, and there are no enemies nearby.
									if (GetDistance2DSquared(Position, EnemyPosition) > Squared(iter->EngageRange + 50.0f))
									{
										// Friendly: Find farthest away building, get random building within 50-100m of that range, get position further from it, and go to.

										// Scrap: Randomly pick a piece of scrap to getpositionnear(), min 10, max 50. 

										// Enemy: Find the closest enemy, randomly pick until we find one within randomfloat of 50-100 of that range, (close to enemy front
										// lines?) and go to it. Stop outside it's engage range, + randomfloat of 50-150m. 
										/*
										Mode 0: Friendly Base Defence.
										- Method 0: Furthest away building.
										- Method 1: Random friendly building.
										- Method 2: Random base slot building (recy/fact/armory)
										Mode 1: Goto Scrap.
										- Method 0: Closest.
										- Method 1: Random.
										- Method 2: Farthest.
										Mode 2: Siege Enemy Base.
										- Method 0: Closest enemy building.
										- Method 1: Random Enemy building.
										- Method 2: Enemy base slot building.
										*/

										int DispatchMode = GetRandomInt(2); // floor(GetRandomFloat(3.0f)));
										int DispatchMethod = GetRandomInt(2);
										iter->DispatchTarget = 0; // Don't save a target to compare distance to for base defence.
										Handle TempTarget = 0;
										float TempDist = 0.0f;
										int Random = 0;
										int RandomTeam = GetRandomTeam(TeamFilter_Enemies, Team, true);
										Handle EnemyBase = 0;
										Vector EnemyBasePosition = Vector(0, 0, 0);

										const BZ1Helper::TeamInfo &EnemyteamInfo = BZ1Helper::Get().GetTeamInfo(RandomTeam);
										if(EnemyteamInfo.Recy)
											EnemyBase = EnemyteamInfo.Recy;
										else if(EnemyteamInfo.Muf)
											EnemyBase = EnemyteamInfo.Muf;
										else if(EnemyteamInfo.Cnst)
											EnemyBase = EnemyteamInfo.Cnst;
										else if(EnemyteamInfo.Slf)
											EnemyBase = EnemyteamInfo.Slf;

										if (EnemyBase)
											EnemyBasePosition = GetPosition(EnemyBase);

										if(Logging)
											FormatLogMessage("Index is: %d, DispatchMode is: %d, DispatchMethod is: %d", iter-DispatchList.begin(), DispatchMode, DispatchMethod); 

										switch (DispatchMode)
										{
										case 1: // Scrap Field, Go to a position "near" a Random piece of Scrap. :)
											{
												TempDist = FLT_MAX; //Start off big, we're looking for closest.
												int NumScrap = ScrapHelper::Get().GetNumScrapObjects();

												switch (DispatchMethod)
												{
												case 1: // Select Random Scrap to go to.
													{
														if(NumScrap > 0)
														{
															Random = GetRandomInt(NumScrap - 1);
															Handle ScrapPiece = ScrapHelper::Get().RefScrapHandle(Random);

															//if(IsAround(ScrapPiece))
															iter->DispatchTarget = ScrapPiece;
														}
													}

													CheckLag("DispatchHelper::Idle Turret 1 1."); // LagLogging.

													break;


Sub Functions:

Code: Select all

int GetRandomInt(const int Min, const int Max)
{
	if(Max < Min)
		return Min;

	//Math.Min(Math.floor(GetRandFloat(Max)),Max-1);
	int value = Min + int(GetRandomFloat(float(Max - Min + 1)));
	value = clamp(value, Min, Max);

	return value;
}

Code: Select all

int GetRandomTeam(const int TeamFilter, const int Team, const bool ActiveTeamsOnly, const bool SkipTeamZero)
{
	const int TempTeamFilter = TeamFilter ? TeamFilter : -1;
	//int TempTeam = -1;

	int Start = GetRandomInt(MAX_TEAMS-1);
	int x = Start;
	do
	{
		if(((Team < 0) || (TeamFilterCheck(TempTeamFilter, x, Team))) && // Team matches.
			((!ActiveTeamsOnly) || ( // ActiveTeamOnly, If they have a Player, or any BaseSlot 1 - 9 items.
			(GetPlayerHandle(x)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_RECYCLER)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_FACTORY)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_ARMORY)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_BASE4)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_BASE5)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_BASE6)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_BASE7)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_BASE8)) || 
			(GetObjectByTeamSlot(x, DLL_TEAM_SLOT_BASE9)))) &&
			((!SkipTeamZero) || (x > 0))) // SkipTeamZero matches.
		{
			//TempTeam = x;
			return x;
		//	break;
		}
		++x;
		if (x == MAX_TEAMS-1)
			x = 0;
	}
	while (x != Start);

	return -1; //TempTeam; // Didn't find anything.
}

Code: Select all

// Determine TeamFilter passing.
bool TeamFilterCheck(const int TeamFilter, const int Team1, const int Team2)
{
	if(Team1 < 0 || Team1 >= MAX_TEAMS || Team2 < 0 || Team2 >= MAX_TEAMS)
		return false;

	return ((((TeamFilter & 1) == TeamFilter_SameTeam) && Team1 == Team2) ||  // Same Team Only
			((Team1 != Team2) && // Not same Team.
			((((TeamFilter & 2) == TeamFilter_Allies) && (IsTeamAllied(Team1, Team2))) ||  // Allies Only
			(((TeamFilter & 4) == TeamFilter_Enemies) && (!IsTeamAllied(Team1, Team2))))));  // Enemies Only
}

Code: Select all

bool CheckLag(const char *format, ...)
{
	// Format the string.
	va_list ap;
	va_start(ap, format);
	char tempstr[2 * MAX_MESSAGE_LENGTH] = { 0 };
	vsnprintf_s(tempstr, sizeof(tempstr), sizeof(tempstr), format, ap);
	va_end(ap);

	// Check the clock time, compare against old clock time.
	clock_t currtime = clock();
	clock_t difftime = currtime - LastCPUClockTime;
	LastCPUClockTime = currtime; // Update the current time for next comparison.

	if ((difftime) > 10) // > 10 clocks was expended since last call to this function.
	{
		if (tempstr[0])
		{
			FormatConsoleMessage("CPU Clock Time: %f, ClocksSinceLast: %d, %s", float(currtime / CLOCKS_PER_SEC), difftime, tempstr);
			FormatLogMessage("CPU Clock Time: %f, ClocksSinceLast: %d, %s", float(currtime / CLOCKS_PER_SEC), difftime, tempstr);
		}

		return true; // Does it laggle?
	}

	return false; // Yay! No laggles!
}

Code: Select all

bool FormatLogMessage(const char *format, ...)
{
	va_list ap;
	va_start(ap, format);
	char tempstr[MAX_MESSAGE_LENGTH] = {0};
	vsnprintf_s(tempstr, sizeof(tempstr), sizeof(tempstr), format, ap);
	va_end(ap);

	time_t Time = 0;
	time(&Time);
	struct tm LocalTimestamp;
	localtime_s(&LocalTimestamp, &Time);

	char TimeStamp[MAX_ODF_LENGTH] = {0};
	strftime(TimeStamp, sizeof(TimeStamp), "%H:%M:%S", &LocalTimestamp);

	if(!LogFile)
		OpenLogFile();

	if(LogFile)
	{
		fprintf(LogFile, "%s | %f \t| %s\n", TimeStamp, GetTime(), tempstr);

		if(GetVarItemInt("network.session.ivar115")) // If logging is on, print to console.
			PrintConsoleMessage(tempstr);

		return true;
	}
	else
	{
		char Message[MAX_MESSAGE_LENGTH] = {0};
		sprintf_s(Message, "ERROR: Unable to open Log File! Reporting: %s", tempstr);
		PrintConsoleMessage(Message);
		return false;
	}
}

So, Between the start of the excerpted code, ( CheckLag("DispatchHelper::Idle Start."); reset the comparison clock() time) and the end of the excerpted code ( CheckLag("DispatchHelper::Idle Turret 1 1."); ), 16786 cpu clocks were spent.

I've posted all the code executed between the two checklag calls. Can anyone tell me how that could possibly take so long?

I'm going to try to catch it in a debugger's Break All to see if it's doing anything in here or elsewhere in game/pc code.
Battlezone Classic Public Forums
*****General BlackDragon*****
User avatar
GSH
Patch Creator
Posts: 2485
Joined: Fri Feb 18, 2011 4:55 pm
Location: USA
Contact:

Re: BZC DLL Lag Debugging

Post by GSH »

Some comments:
- Use GetTickCount()/GetTickCount64 and subtract to get the # of milliseconds. That's far more accurate than clock(). Slice & dice by doing an entry
const DWORD startTicks = GetTickCount();

then a number of log lines after then, e.g.
(s|f)printf("%d ms to line %d\n", GetTickCount() - startTicks, __LINE__);

or even a little block like this pasted in:
{
const DWORD elapsedTicks = GetTickCount();
if(elapsedTicks > 5)
(s|f)printf("%d ms to line %d\n", elapsedTicks , __LINE__);
}

Using such a pattern, you can move lines around and hone in on the slow section with repeated runs.

- Too much logging can slow things down. You should aim to have no more than about 10 calls to GetTickCount() per execute call. Don't go opening lots of files all the time. Note my second block spams only after things go slow.

- Are you spawning anything? If it's not preloaded, BZ2 can take a long time to load it.

- I'd pay attention to your calls like ScrapHelper::Get().GetNumScrapObjects(). Don't iterate over lots of things all time time.

- Install a free sampling profiler like AMD's CodeXL. This works best if you have a savegame (e.g. IA) that repros the problem shortly after loading. Have CodeXL do the running of BZ2, including commandline params, etc. Set a startup delay of say 30-40 seconds, then sample for 30 seconds. See where it's spending time.

-- GSH
User avatar
General BlackDragon
Flying Mauler
Posts: 2408
Joined: Sat Feb 19, 2011 6:37 am
Contact:

Re: BZC DLL Lag Debugging

Post by General BlackDragon »

I don't believe the mission is adding a whole lot at the time. I can check though.

There is no iterating over all the objects in this case, which is why im confused on what's lagging.

GetNumScrapObjects is just this:

Code: Select all

int GetNumScrapObjects() { return ScrapList.size(); }
Handle &RefScrapHandle(const int index) { return ScrapList[index].ScrapObject; }
All that does is returns the std::vector's size, and the handle ref one referrs the struct ScrapList's Handle variable. I'll try that profiler, I was using VerySleepy but it's sometimes hard to catch things with. (I have to wait till mission starts to load BZ2 so it loads the DLL pdb and then alt tab + start / stop it)
Battlezone Classic Public Forums
*****General BlackDragon*****
User avatar
General BlackDragon
Flying Mauler
Posts: 2408
Joined: Sat Feb 19, 2011 6:37 am
Contact:

Re: BZC DLL Lag Debugging

Post by General BlackDragon »

Resolved this:

GetRandomTeams could infinite loop due to the following:


int Start = GetRandomInt(MAX_TEAMS-1); // Could return max of 15.


++x; // This would increument before the comparison, so it would become 16 on first run.
if (x == MAX_TEAMS-1) // == would never match 15, should be >= just in case.
x = 0;
}
while (x != Start); // x > start, infinite loop?

So, That's one bug. Though, How the game could only freeze for 16 seconds and then unfreeze if this occurred seems impossible, so maybe that's not the only bug. :-/
Battlezone Classic Public Forums
*****General BlackDragon*****
Post Reply