Multiplayer Woes

[AIAndy]

Some more OOS logs. Apparently her computer doesn't ALWAYS throw the ini file - it just so happened to do so twice. But there is an interesting anomaly on the python logs regarding a module being loaded by one but not the other.

Also, again, the random log seems to show that the random goes off course during ai defensive evaluations. Something leading to that point apparently is still going non-deterministic.

Side note, the rev version on these has not changed since I updated after the last OOS fix. They have grown increasingly frequent again and it ends up happening turn after turn once more.

Here's the logs!

I keep watching these fixes in the code, learning a little more every time. But it does help that you've been explaining your processes in fixing these. I feel like I'm beginning to have a shallow understanding on some of it. What really got me on the first fix was having no idea HOW you found the problem there in the first place!

These OOS are all because of the position of Town Watchmen of the AI players. This means that there is some issue in Koshling's new AI code for property control by units. The result of where to move them seems to have a non deterministic aspect.

 

[Koshling]

These OOS are all because of the position of Town Watchmen of the AI players. This means that there is some issue in Koshling's new AI code for property control by units. The result of where to move them seems to have a non deterministic aspect.

There should be no random numbers involved at all in that. The TW's don't search for a target, they just respond to contracts out out by cities (and again no random numbers involved in the contract resolution), so essentially it's a city production decision. That probably implies use of some unsync'd rand somewhere in the city production choice code, that causes something to be ordered before/after property control.

 

[Thunderbrd]

There should be no random numbers involved at all in that. The TW's don't search for a target, they just respond to contracts out out by cities (and again no random numbers involved in the contract resolution), so essentially it's a city production decision. That probably implies use of some unsync'd rand somewhere in the city production choice code, that causes something to be ordered before/after property control.

From what I can tell, it has nothing to do with the Production Choice. It's about how they choose to move on the map that runs across something non-deterministic...

 

[AIAndy]

There should be no random numbers involved at all in that. The TW's don't search for a target, they just respond to contracts out out by cities (and again no random numbers involved in the contract resolution), so essentially it's a city production decision. That probably implies use of some unsync'd rand somewhere in the city production choice code, that causes something to be ordered before/after property control.

Sn0bb's logs have a similar issue with a javelineer and a town watchman at different positions and he also has the BBAI logs.
The difference in the logs is this:
Computer 1:

Unit Javelineer (557102) for player 3 (Dutch Empire) at (22,64) found work at (17,62) [to join -1]
Unit Town Watchmen (565322) for player 3 (Dutch Empire) at (20,59) - no work available

Computer 2:

Unit Javelineer (557102) for player 3 (Dutch Empire) at (22,64) - no work available
Unit Town Watchmen (565322) for player 3 (Dutch Empire) at (20,59) found work at (17,62) [to join -1]
Unit Town Watchmen (group 712780 with 1 units) for player 3 (Dutch Empire) at (19,60) leaves garrison for city Utrecht

 

[Koshling]

Sn0bb's logs have a similar issue with a javelineer and a town watchman at different positions and he also has the BBAI logs.
The difference in the logs is this:
Computer 1:

Unit Javelineer (557102) for player 3 (Dutch Empire) at (22,64) found work at (17,62) [to join -1]
Unit Town Watchmen (565322) for player 3 (Dutch Empire) at (20,59) - no work available

Computer 2:

Unit Javelineer (557102) for player 3 (Dutch Empire) at (22,64) - no work available
Unit Town Watchmen (565322) for player 3 (Dutch Empire) at (20,59) found work at (17,62) [to join -1]
Unit Town Watchmen (group 712780 with 1 units) for player 3 (Dutch Empire) at (19,60) leaves garrison for city Utrecht

Interesting. I'll look through that code, but I'm pretty sure it has no random number throwing in it whatsoever. However, the allocation of work to advertising units happens each time a new unit advertises (that allocates those that have not yet been allocated to available work as each work item is added), so if the units advertise in a different order that might cause this. Could you post the full BBA logs for that AI player for that turn please (just that player on that turn) for each computer.

 

[AIAndy]

Interesting. I'll look through that code, but I'm pretty sure it has no random number throwing in it whatsoever. However, the allocation of work to advertising units happens each time a new unit advertises (that allocates those that have not yet been allocated to available work as each work item is added), so if the units advertise in a different order that might cause this. Could you post the full BBA logs for that AI player for that turn please (just that player on that turn) for each computer.

I posted the only differences. There is no difference in the advertising order.
One possibility is this:
The contract broker uses
CvUnit::meetsUnitSelectionCriteria
which calls
CvUnitAI::AI_beneficialPropertyValueToCity
which calls
CvCity::getTotalUnitSourcedProperty
which uses a cache and is also called by
CvCityAI::buildingPropertiesValue
which is called by
CvCityAI::AI_buildingValueThresholdOriginal
which is called by
CvCityAI::AI_bestBuildingThreshold
which is a method that has a possible async context (given by a bool bAsync parameter).
So an async call to AI_bestBuildingThreshold can desync the cache in getTotalUnitSourcedProperty.

 

[Koshling]

I posted the only differences. There is no difference in the advertising order.
One possibility is this:
The contract broker uses
CvUnit::meetsUnitSelectionCriteria
which calls
CvUnitAI::AI_beneficialPropertyValueToCity
which calls
CvCity::getTotalUnitSourcedProperty
which uses a cache and is also called by
CvCityAI::buildingPropertiesValue
which is called by
CvCityAI::AI_buildingValueThresholdOriginal
which is called by
CvCityAI::AI_bestBuildingThreshold
which is a method that has a possible async context (given by a bool bAsync parameter).
So an async call to AI_bestBuildingThreshold can desync the cache in getTotalUnitSourcedProperty.

If the city in question is the capital I guess that code path is possible in a trade evaluation. I'll see what I can do about passing an async value down further and using that to inhibit the caching (of async values) similarly to what you did with the commerce caches.

 

[Sn0bb]

It's great to see that the logs gave some help on determinating the problem.

I remember of having one OOS error related to production too during the play. A missmatch again was shown in turn logs when compared to each other. One had Townwatch as a production choise in city and the other had Brick Mason.
I don't have logs of these anymore though as we just continued onwards by restarting the game and loading up the save.
So just saying that maybe there could be a bug there too that is worth checking out or keep tabs on.

 

[AIAndy]

It's great to see that the logs gave some help on determinating the problem.

I remember of having one OOS error related to production too during the play. A missmatch again was shown in turn logs when compared to each other. One had Townwatch as a production choise in city and the other had Brick Mason.
I don't have logs of these anymore though as we just continued onwards by restarting the game and loading up the save.
So just saying that maybe there could be a bug there too that is worth checking out or keep tabs on.

If our analysis of the problem was correct, then that is something that can happen as well. We will see if it still happens when Koshling has applied the fix described above.

 

[Thunderbrd]

I've still gotta compile the results here so I can upload them, but we collected some more OOS reports (the last few with BBAI logs) last night.

Two things of interest though:
1)We went out of synch as a result of the initial recalculation.
and
2)Soon as I pulled up next to a city and the AI troops standing outside decided to move into the city - blam, OOS.

 

[Koshling]

I posted the only differences. There is no difference in the advertising order.
One possibility is this:
The contract broker uses
CvUnit::meetsUnitSelectionCriteria
which calls
CvUnitAI::AI_beneficialPropertyValueToCity
which calls
CvCity::getTotalUnitSourcedProperty
which uses a cache and is also called by
CvCityAI::buildingPropertiesValue
which is called by
CvCityAI::AI_buildingValueThresholdOriginal
which is called by
CvCityAI::AI_bestBuildingThreshold
which is a method that has a possible async context (given by a bool bAsync parameter).
So an async call to AI_bestBuildingThreshold can desync the cache in getTotalUnitSourcedProperty.

Now I read this more closely I cannot see how it would cause a problem. Whether the value is cached by sync or async code, the cached value depends only on the units present in the city, which is independent of whether the code path is sync or async, so either way you arrive at the same cached value. If one machine causes the value to be cached async, and the other not at all, it still doesn't matter because when the sync'd call comes (in the path that actually control the fixing up of contracts) one will already have the value, and the other will calculate it and get the same result either way. For any query of this value in any code path to return a different value would require different units to be present, which would imply an earlier desync.

 

[AIAndy]

Now I read this more closely I cannot see how it would cause a problem. Whether the value is cached by sync or async code, the cached value depends only on the units present in the city, which is independent of whether the code path is sync or async, so either way you arrive at the same cached value. If one machine causes the value to be cached async, and the other not at all, it still doesn't matter because when the sync'd call comes (in the path that actually control the fixing up of contracts) one will already have the value, and the other will calculate it and get the same result either way. For any query of this value in any code path to return a different value would require different units to be present, which would imply an earlier desync.

If the async value is written into the cache when X units with crime sources are in the city and then another unit enters the city, then the cache is async because evaluating it now would return a different value on one computer because the async cache is not cleared by the unit movement into the city. It is only cleared once per turn.
So an option would be to add the cache clear when a unit enters or leaves the city.

 

[Koshling]

If the async value is written into the cache when X units with crime sources are in the city and then another unit enters the city, then the cache is async because evaluating it now would return a different value on one computer because the async cache is not cleared by the unit movement into the city. It is only cleared once per turn.
So an option would be to add the cache clear when a unit enters or leaves the city.

Ah good point, it really should clear on unit entry - I'll do that and we can see if it helps.

 

[Thunderbrd]

Nice to see some fixes being worked on here. In the meantime, here's some additional OOS Logs.

The first is really interesting as it details an OOS we got from recalculating just after the game opened up! I think I screwed up on BB logs though... seem to not have gotten them somehow Sorry.

Note: I'm reading this stuff and I'm kinda following it... please point out to me what the revision is when you do the update on this fix Koshling. I really want to see in code what y'all are discussing. Caching and cache clearing... still don't have a strong grasp on all that stuff yet.

 

[Koshling]

Nice to see some fixes being worked on here. In the meantime, here's some additional OOS Logs.

The first is really interesting as it details an OOS we got from recalculating just after the game opened up! I think I screwed up on BB logs though... seem to not have gotten them somehow Sorry.

Note: I'm reading this stuff and I'm kinda following it... please point out to me what the revision is when you do the update on this fix Koshling. I really want to see in code what y'all are discussing. Caching and cache clearing... still don't have a strong grasp on all that stuff yet.

Update done - see SVN thread - there's nothing else in that rev so it should be easy for you to see the changes.

 

[Sn0bb]

Update done - see SVN thread - there's nothing else in that rev so it should be easy for you to see the changes.

Is it possible to use old save from previous svn? I have seen that in singleplayer you can update the save file to new version, even though the update utility is still in beta phase. So I was wondering if it is possible for the MP saves too. Or if the old save is compatible with the newest version.
Would you recommend doing so? Had a good game going on in that game before these OOS errors started to happen.

 

[Thunderbrd]

Just update both computers' files and you're good to go. Make sure they're both on the same revision.

 

[AIAndy]

Is it possible to use old save from previous svn? I have seen that in singleplayer you can update the save file to new version, even though the update utility is still in beta phase. So I was wondering if it is possible for the MP saves too. Or if the old save is compatible with the newest version.
Would you recommend doing so? Had a good game going on in that game before these OOS errors started to happen.

The savegame format of single and multiplayer is the same and while the recalculation says it is beta it has been used for many months now so there should be few bugs left in it.

 

[AIAndy]

Nice to see some fixes being worked on here. In the meantime, here's some additional OOS Logs.

The first is really interesting as it details an OOS we got from recalculating just after the game opened up! I think I screwed up on BB logs though... seem to not have gotten them somehow Sorry.

Note: I'm reading this stuff and I'm kinda following it... please point out to me what the revision is when you do the update on this fix Koshling. I really want to see in code what y'all are discussing. Caching and cache clearing... still don't have a strong grasp on all that stuff yet.

Hmm, the first one only differs by 3 culture of player 3 and you say it was after recalculation? Maybe the commerce caches should all be manually cleared after recalculation.

The last one is interesting. In the random log it starts to differ because of animal spawning but the reason there is that the number of owned plots in an area is different. That means that one plot has changed ownership from neutral to owned or vice versa, but only on one computer.
Was there anything specific like that going on that you can remember?

The other OOS are probably all caused by the same root issue as the earlier ones so they might be fixed now. At least they all involve at least one town watchman at different positions which can easily snowball.

 

[Thunderbrd]

Hmm, the first one only differs by 3 culture of player 3 and you say it was after recalculation? Maybe the commerce caches should all be manually cleared after recalculation.

The last one is interesting. In the random log it starts to differ because of animal spawning but the reason there is that the number of owned plots in an area is different. That means that one plot has changed ownership from neutral to owned or vice versa, but only on one computer.
Was there anything specific like that going on that you can remember?

The other OOS are probably all caused by the same root issue as the earlier ones so they might be fixed now. At least they all involve at least one town watchman at different positions which can easily snowball.

Well... I was doing some conquering. That probably would've sent some tiles into neutrality from ownership, so yeah.