getLastEventTime() has different behavior for client/module bots

[dgant]

There are two issues with the current implementation of getLastEventTime():

1. getLastEventTime() works differently for client bots and module bots
2. getLastEventTime() uses a low-resolution timer that may misjudge the bot's performance

getLastEventTime() works differently for client bots and module bots

Module bots use the following procedure, as implemented in GameEvents.cpp as called from Server.cpp:

1. Start a stopwatch: dwLastEventTime = GetTickCount()
2. Run the module bot event handler: SendClientEvent(client, e) -- don't be thrown off by the name
3. Stop the stopwatch and record the duration: this->lastEventTime = GetTickCount() - dwLastEventTime
4. Run the tournament module event handler: SendClientEvent(tournamentAI, e)

Clients use a different procedure in Server::update():

1. Start a stopwatch
2. Flip a bit in shared memory to indicate to the client that the newest frame is ready
3. (Client does whatever it wants; presumably this includes handling events and writing commands to shared memory)
4. Client indicates that it's done with the frame
5. Stop the stopwatch and record the duration: BroodwarImpl.setLastEventTime(GetTickCount() - onFrameStart)

This means that when the tournament module calls getLastEventTime():

• For a module bot, it gets the duration the bot spent handling that event
• For a client bot, it gets the duration the bot spent on everything, in total

Let's say there's a bot that spends 1ms on each onUnitShow and 20ms on each onFrame. On a frame where two units show, and the bot takes 22ms to handle all its events. If the tournament manager adds up getLastEventTime()s for each event:

• If it's a module bot, the tournament manager sees the bot take 22ms (correct)
• If it's a client bot, the tournament manager sees the bot take 66ms

Note that it's not possible for BWAPI to time client events individually, as clients can do whatever they want with the events provided, so no matter how this discrepancy is resolved, per-event measurements aren't a possibility.

getLastEventTime() uses a low-resolution timer that may misjudge the bot's performance

BWAPI's timing uses GetTickCount() which is a Windows API function:

The resolution of the GetTickCount function is limited to the resolution of the system timer, which is typically in the range of 10 milliseconds to 16 milliseconds."
If you need a higher resolution timer, use a multimedia timer or a high-resolution timer.

16 milliseconds is a lot, especially considering that any timer the bot might be using to regulate their performance may have error in the opposite direction; 16ms is 29% of the time allowed on frames in COG or AIIDE, for instance.

[N00byEdge]

Ah yes, the obvious solution to this is to return 0; for getLastEventTime() if we're running a client bot and we're not in the onFrame event, since we can't time client events anyways. Maybe we should use a better timer too.

[chriscoxe]

@N00byEdge are you talking about changing the logic in the TM, or changing the logic in bwapi? If it's the former, I agree. If it's the latter, I don't really understand how bwapi would be able to determine whether getLastEventTime() is being called in the onFrame event for a client bot - remember that it would be called from the TM's onFrame method (the TM is an AIModule object), not from the bot.

In bwapi, I suggest mentioning in the documentation for getLastEventTime() that "for client bots it returns the total wall-clock time between when bwapi finishes making the current frame's game state information available to the bot and when the bot returns control back to bwapi (which may include processing for multiple events, not just the last event)" or something like that.

Perhaps also consider giving TournamentModule's a way to distinguish client bots from non-client bots, so that the TM can interpret things like getLastEventTime() correctly.

[N00byEdge]

@chriscoxe What you're suggesting sounds like a no-compromise solution, but it would leave TMs to have work to do for porting to 4.5+ and it would break source compatibility for any existing TMs, you would need to have one version of the source for 4.5 and one for 4.4 (since there is no isClientBot at this moment). That's why I'm thinking the most compatible thing you could do is to deliver the real frame time only once. Does anyone have any opinion on this?

[chriscoxe]

@N00byEdge I'm still trying to understand what you're proposing, and whether you're talking about changing the TM, or bwapi, or both. You only mentioned the case where it's a client bot (and as I said, I don't understand what you're proposing for this case). What about the case where it's not a client bot - are you proposing different logic in this case?

[chriscoxe]

Maybe there was a typo in your proposal? Maybe you meant changing bwapi to "return 0; for getLastEventTime() if we're not running a client bot and we're not in the onFrame event, since we can't time client events anyways"?

Personally, for non-client bots, I'd rather that bwapi times all events (not just onFrame()) to avoid the risk of slow bots from potentially slowing down competitions/ladders to a crawl. I'd rather that TMs not have to implement their own timing logic just to guard against that kind of problem.

[N00byEdge]

I agree with your points but no, that was not a mistake, and I think you should reread it. Remember that "not running a client bot" means module.

What I'm suggesting is that if the TM asks for the event time on a client bot, it should return 0 if it's not onFrame. That way we would only need to change this one functions implementation and not have to break existing TMs.

[chriscoxe]

(Edited) After looking at the src a few times I think I understand what you mean, and I agree it would solve the problem. (I got confused because I mistakenly thought onFrame meant the client's onFrame event handling logic, but now I realize you meant the TM's onFrame callback).

[chriscoxe]

On a related note, in BWAPI 4.4.0, it seems inconsistent that DLL bots (I'm talking about the bot specifically, not the TM) can use getLastEventTime(), and that the TM can get a non-zero value for both DLL and client bots, but that it always returns 0 when called by a client bot. I expect client bots might want to use it to track how much time BWAPI thinks the bot used.

I think the documentation that says @retval 0 When called from an AI module. in Game.h should be corrected to say @retval 0 When called from a client bot. because it looks like a typo. If any changes are made in BWAPI, I suggest updating the documentation in AIModule.h and Game.h that refers to getLastEventTime() to also explain how timing works for client bots.

[heinermann]

I think the documentation that says @retval 0 When called from an AI module. in Game.h should be corrected to say @retval 0 When called from a client bot. because it looks like a typo.

The doc is correct here. If your AI module (not TM) calls getLastEventTime() it will(should?) return 0.

[chriscoxe]

@heinermann Sorry, you are right that it returns 0. I was mistaken.

[dgant]

I made a bot which just does the following:

      auto beforeGetTickCount = GetTickCount();
      Sleep(50);
      std::cout << GetTickCount() - beforeGetTickCount<< std::endl;

This is a sample of the result:

47
63
47
46
47
63
47
62
47
47
62
47
47
47
47
46
63
47
47
62
47
47
47
47
47
47

Note the granular outputs of { 47, 62, 63 }. This highlights the low resolution of GetTickCount(). A caveat is that Sleep() has precision limitations of its own, but the granularity of this output matches the documented precision of GetTickCount().

[dgant]

Here's an updated version, which compares the outputs of different timers:

1. GetTickCount()
2. std::chrono::system_clock::now()
3. std::chrono::steady_clock::now()
4. std::chrono::high_resolution_clock::now()

This may indicate that the std::chrono timers are more precise, but might also mean that the duration of Sleep() correlates with the std::chrono times. But in general this result causes me to have more confidence in std::chrono.

[heinermann]

Yeah GetTickCount() is just a relic of pre-C++11.