help with Desync logs

[BunkerBlaster]

I hosted my first 10 player game today. I'm trying to understand the desync logs.
After 37 minutes I kicked player 7 because game gave me (zzz 7) almost entire time.
When I did kick player 7 the game immediately went out of sync for remainder of game...2+2=5
Total game time was 50 min

I wanted to analyze the logs up to the time I kicked player 7 but I do not see any game times in the desync logs.
Instead I combined the desync logs for the entire 50 minutes into one file and did a count. I expected to find a high number of entries for player 7. Instead player 7 had the lowest amount of entries.

So my questions is

1) " = p7;pos" in the desync logs, is this the same as player 7 when the games gives me the zzz 7

Basicly what Im trying to do is go back and look at who had the most lag, Who lagged 2nd, 3rd, etc. If I can do this maybe I can be a better host.


Edit: Think I figured out my confustion
1) since player 7 was kicked there is not a desync log for player 7.
2) combining the logs also my mistake.

Perhaps somebody can post a link to a thread that explains the logs. I could not find one.

Thanks

[Cyp]

A desynch log is meaningless on its own. To see what happened, you have to look at the difference(s) between two different desynch logs (from the same tick). The one with the earliest game time is the interesting one.

If it happened when you kicked a player (or when a player dropped), then the issue is probably that some clients didn't process the GAME_PLAYER_LEFT message at the right time. No idea why that happens, and can't reproduce when testing locally. Tried messing with the game speed of individual clients, but didn't help with reproducing.

[BunkerBlaster]

Thank you Cyp My mistake was I should have kicked player 7 twenty minutes earlier as Wisler suggested but I did not because ping was only 170ms and I did not feel the lag until just before I kicked. I should have known better because ping by itself is meaningless. Game started out at 120 fps and had fallen to 20 fps just before kicking. After kicking my fps came up to 70 with the remaining 9 players. Kicking a player when there are up to 1300 units on map not such a good idea.

I compared the results as you suggested and I can see the difference in droid location, speed, power, etc. I would think all to be expected with the exception of this (only for this game desync and not any other)

[mapUpdate] Extinguished tile{32, 12}
[mapUpdate] Extinguished tile{38, 21}

Map was 10c-NTW10 and the location was my base where I had the oil generators built. One location also happens to be the same place I had a traffic jam earlier in the game. I should also report that when I kicked player 7 all players stopped. Pings for all players did not update and showed ??? or 1000 on the alliance menu ( I'm aware ping last priority). After exiting the alliance menu the bottom half of the Warzone screen turned a transparent blue for a couple seconds as if there was a see thru dialog box there. It recovered and the game went on with the desync 2+2=5

Just so you know I kind of produced this and some other results deliberately by letting in players that I had blocked for many lost packets in version 2.3.9. If I host the way I have always done by blocking those that lag (a lost packet percentage that I came up with) there is not any desync. So it is apparent that I have to continue blocking the same players. (don't get me wrong, I love the netcode for the main reason it prevents most cheats).

I will test more, what I have not tested is

1) I have not yet tested by raising the percentage of lag I allow by increasing it a small percentage (I did this for other version, not 3.1 yet)

2) I have not yet tested players that had unknown droids in other version (a big source of lag irrelevant to lost packets, and when unknown droids existed in other version it was always a compiled game, why I don’t know, virtual machines maybe)

3) I have not yet tested by forcing smaller packet size. (I noticed the game tolerates some players with more lost packets than others, without lagging. Those players will have a smaller packet size and the lost packets are evenly spread out. What I don’t know is if I force a smaller packet size for all players if the same would hold true. Probably not but worth a try I guess.)

[BunkerBlaster]

If it happened when you kicked a player (or when a player dropped), then the issue is probably that some clients didn't process the GAME_PLAYER_LEFT message at the right time. No idea why that happens, and can't reproduce when testing locally. Tried messing with the game speed of individual clients, but didn't help with reproducing.

Actually it happens every time I kick in large games, and the resulting CRC errors can be 4 out of 10 players. I have noticed other hosts do not kick but choose to play with the lag.

I wish to prevent the crc errors so I will no longer kick. If you have any suggestions on how to prevent the zzz icon it would be greatly appreciated.

[Cyp]

This should prevent the desynch: 35f301b1ba7f76be1bbfc80d8cdb924f12d6ae7e. Only the host needs that patch to prevent the desynch on player dropping/quitting/getting kicked/leaving/disconnecting/falling/self destructing/crashing/getting abducted by aliens.

Preventing the Zzz is hard, since it can require upgrading someone's internet connection so that they reliably have less than a 1 second ping (for comparison, if they're half way to the moon, they would have about a 1.3 second ping, and if they're somewhere on earth, it should be possible to have a ping of at most 0.13 seconds), or maybe even upgrading someone's computer if it's extremely slow (way over 20x slower than modern computers, that is). Although just removing the Zzz icon itself would be easy.

[BunkerBlaster]

The Zzz icon is very much needed and I was in no way asking it be removed. As a host I have to exclude players that lag, I have no choice as its always been that way. When I asked how to prevent the Zzz I did not ask properly and I apologize. What I should have written was how to analyze the frequency of the Zzz so that I can prevent the Zzz by excluding players.

I have had fiber optic internet for a few years now. I think I get what your saying, tcp is tcp and some things are not going to change. Geographic location is a consideration but not a factor by itself. Some Countries I can host a larger percentage of players than others. On the other hand sometimes the biggest lagger is the one closest to me, just a few cities away, while all the other players that did not lag were all from other countries.

It is my understanding that Warzone may be waiting for players that are slow, but may also be because someone is to fast. I can not do this by measuring lag which makes Warzone a better measurement tool if the data is there. I have looked at times by importing only the game times to a spread sheet and cannot figure it out.

For the duplicate game times, individual times only vary by 100.
When the game time updates, individual times may still vary by 100.
Am I looking at the data wrong or is the data I'm looking for actually not there?

[Cyp]

Players can't cause lag by being too fast.

How it works is that ideally, every 100ms, the gameTime is advanced by 100ms. The GAME_* messages are processed in a specified order, and order processing for a player halts once that player's GAME_GAME_TIME message with a specified execution time (checkTime + latencyTicks * GAME_TICKS_PER_UPDATE) in the future is processed. If the GAME_GAME_TIME messages that halt order processing to not arrive in time for the gameTime to update, the gameTime (and the game) pauses (and the Zzz icon is shown).

The clients try to guess a good value of the latencyTicks parameter which matches the actual network latency. Higher value (max 1 second) means less risk of Zzz. Lower value means less time between clicking and the tanks actually moving. High jitter makes it harder to find a value of latencyTicks that avoids Zzz without the time between clicking and the tanks actually moving being excessive.

If one computer is somehow actually too slow to simulate the game in real time, then that will be misinterpreted as network lag, and latencyTicks will end up at the max value in a futile attempt to make the slow computer respond faster. If one computer is too slow, there's nothing that can be done to keep the game running at full speed (other than kicking the player).

[BunkerBlaster]

Thank you for the thorough explanation. As you can tell my ability to understand the logging by looking at the code is rather limited. The log entries I said were duplicates are actually not duplicates. I have a much better understanding now, again Thank you. I will test the desync patch over next couple days.

[BunkerBlaster]

I host from Windows because I like drivers for Windows better. Having that said I installed Warzone on linux and installed the desync patch. I hosted 4 games and kicked in two games. In both games that I kicked the 2+2=5 icon is displayed for a few seconds then goes away. So I assume the patch works because the game recovers from desync after kicking, where before it didn’t.

This is great because the kick is needed, as a last resort. There is still something else needed though so that the kick is not a way of life so to speak. I wish I new what that “something else is” but I don’t.

As far as what I was asking for, the pause counter, or Zzz counter. I guess that would be meaningless without knowing what the latency is. And a min. max. avg. latency for each player would also be nice but that would be of little usable value without the frequency and durations. So I see why these statistics are not in the logs already and I need to rethink this. Thank You Cyp

[BunkerBlaster]

Is it possible for the next beta you can create a log entry so that for each time the latency is adjusted to also report each players FPS? So the log would look something like this.

[updateLatency:348] Adjusting latency 700 -> 800
Player 1 fps 60
Player 2 fps 80
Player 3 fps 40
Player 4 fps 20
Player 5 fps 50
Player 6 fps 30
Player 7 fps 45
Player 8 fps 70
Player 9 fps 25

[vexed]

That kind of information isn't retrieved by the host at this time.
If you are seeing "Zzz" from a specific player, and their ping looks OK on your end, then you know what the problem is.

[BunkerBlaster]

Players can't cause lag by being too fast.).

The Zzz is being interpreted as lag

If one computer is somehow actually too slow to simulate the game in real time, then that will be misinterpreted as network lag, and latencyTicks will end up at the max value

Thats what I don't get. I don't see the max value in some games, yet I see the Zzz.

If you are seeing "Zzz" from a specific player, and their ping looks OK on your end, then you know what the problem is.

A slow computer? I don’t think its good to assume a slow computer is causing the Zzz each time, as I have asked them their FPS and they tell me it is up there. Sometimes they tell me low. While I have seen a max RTT of more than 1 second in some games it is not the problem with the Zzz the majority of the time. I think it is computers running faster than everyone else that is causing the Zzz most of the time.

This is from a 50 minute 7 player game.

Player 1 Min RTT=166 Max RTT=773 non-existent droids=95 Zzz a lot
Player 3 Min RTT=97 Max RTT=898 non-existent droids=28 Zzz did not notice any
Player 6 Min RTT=189 Max RTT=363 non-existent droid=177 Zzz a lot
Player 7 Min RTT=344 Max RTT=750 non-existent droid=2 Zzz some
(remaining players no problem)

Player 3 had highest RTT and no Zzz that I noticed.

Player 1 and player 6 had the most of Zzz. Player 6 had Max RTT of only 363ms but the most non-existent droids.

With ver 3.1 I assume players do not know they are running at different speeds, and it does not matter anyway because the unwanted Zzz takes care of it.

With ver 2.3.9 I assume they are knowingly cheating because they changed a hard coded value.

[Cyp]

...

Player 1 and player 6 had the most of Zzz. Player 6 had Max RTT of only 363ms but the most non-existent droids.

With ver 3.1 I assume players do not know they are running at different speeds, and it does not matter anyway because the unwanted Zzz takes care of it.

With ver 2.3.9 I assume they are knowingly cheating because they changed a hard coded value.

What are "non-existent droids"?

If a player runs too fast, only that player sees Zzz, if a player runs too slow, everyone except that player sees Zzz.

Think in 2.3.9, accidental cheating would be possible if the computer clock is running too fast (and accidental handicap if the computer clock is running too slow).

[BunkerBlaster]

What are "non-existent droids"?

That is my question , I assume they are not put into play because they are missing, but they also make the Zzz constantly flash. If the droid is skipped, why is it making the Zzz constantly flash?

from src/multibot.cpp

584 DROID *psDroid = IdToDroid(info.droidId, info.player);
585 if (!psDroid)
586 {
587 debug(LOG_NEVER, "Packet from %d refers to non-existent droid %u, [%s : p%d]",
588 queue.index, info.droidId, isHumanPlayer(info.player) ? "Human" : "AI", info.player);
589 syncDebug("Droid %d missing", info.droidId);
590 continue; // Can't find the droid, so skip this droid.

and here is a snip from a the log

never |03:55:16: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164499, [Human : p6]
never |03:55:21: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164689, [Human : p6]
never |03:55:21: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164693, [Human : p6]
never |03:55:21: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164847, [Human : p6]
never |03:55:21: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165141, [Human : p6]
never |03:55:33: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165455, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164489, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164613, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164625, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165063, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165225, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165301, [Human : p6]
never |03:55:36: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165355, [Human : p6]
never |03:55:39: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164251, [Human : p6]
never |03:55:39: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165047, [Human : p6]
never |03:55:39: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165161, [Human : p6]
never |03:55:39: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165295, [Human : p6]
never |03:55:46: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 164801, [Human : p6]
never |03:55:46: [recvDroidInfo:588] Packet from 6 refers to non-existent droid 165487, [Human : p6]

[Cyp]

That just means that the droid was killed between the order being sent, and the order being processed. It's actually a recently destroyed droid. Maybe the Zzz is due to a computer slowing down due to rendering lots of projectiles or something?