Experimental Performance Logging - Test #1

[pushedx]

How-to

0. Update to the latest Beta/Release.

1. Enable the "Performance Logging" option from the Global settings GUI: Gyazo - afa67fa7e85033a64ec86779281d9170.png

2. Start the bot with any bot implementation, preferably in Breach Leagues, or maps with a lot of items/mobs, but anything is fine.

3. Stop the bot after a run/area is complete, or after a large Breach encounter is completed. The longer you run, the more data and bigger picture can be painted, but too long and your file will need to be zipped due to size (which is ok for us, just a little more work for you!)

4. Attach the log(s) from the "PerformanceLogs" folder created (you will need to ZIP them if they are too large to attach on the forums). Alternatively, use a site like GitHub Gists and post a link. Once the data is uploaded/copied, you can delete the files to not confuse any future files made.
* NO sensitive or identifying information is in the logs!

5. Include any basic info in your post you care to share, such as os/hardware/vm. This is just more for reference and will not be used for anything in particular.

Disable the option when done to minimize any extra overhead required to make this work.

That's it! We'll start looking at these early results and keep working on changes and some new tools to help assist in identifying performance issues with the API/bots/routines/plugins.

Examples

In the following images, the bottom axis is the number of objects the client had in the object manager. This value will range from 0 to the max number of objects encountered at once. The left axis is the time in milliseconds it took GrayMagic to read them. This value will range from 0 - 2ms, as any higher values are being ignored currently in the viewer program.

Here's a test run I did in Standard Dried Lake with the Steam client: Gyazo - 0052972a7d8ae480d6722d2df1078df7.png
When there was around 30ish objects, it took GM <.2ms to read them. When there was over 270 objects, it took around .5ms. The key take away is that less than 300 total objects we're ever active at a time, and the average update time was less than 1ms.

Here's a test run done in Breach over several areas with the Normal client: Gyazo - 55ff7e0879969d3d401eb1d344b5f69e.png
When there was over 600 objects, it took GM ~1.3ms to read them. The key take away from this set of data is in comparison to Standard, how many more objects are possible, and how the access time starts to increase.

Purpose

The point of this little experimental logging and demonstration is to start working towards being able to fully identify and explain performance issues with hard data that users can see and interpret rather than us just explaining the problems and why certain things cannot be changed or don't improve. What is being profiled here is the lowest level memory reading for object pointers, so the bot knows the object ids and where in memory they are located. In other words, this is one of the most simplest, yet frequent set of memory reads being done each frame to drive the API that cannot be optimized; only changed.

There is one different implementation that could be used in place of this, but the results of both need to be able to be properly compared before a decision can be made to change anything, since each method isn't without its own set of drawbacks or side-effects. However, any changes done here will not result in any noticeable improvements, because the margins of possible improvement are too small to notice, which is useful in helping determine what actually needs more time spent on trying to be optimized. In other words, if we could magically make this section of code add no overhead, no one would be able to tell the difference! It's safe to say for now that this aspect of the API isn't a big contributor to massive frame spikes when there are a lot of objects on the screen, but here's the data to actually back it up.

That is basically the process being worked through to improve EB in regards to performance and design. There's still a lot to do, and a lot of changes will need to be made to do this properly, but we hope it will eventually lead to better overall performance or at least the understanding of why performance gets bad at times, since hardware and the current game client also affect that.

 

[Darox]

Awesome, performance is poor in the game without the bot running. I will try to give this a shot tonight when I get off work. Can 'baby sit' it a bit and post a log or two.

Below is my log

View attachment ObjectManager_RawAwakeNetworkObjects_1231441984_1568815491.txt

View attachment ObjectManager_RawAwakeNetworkObjects_1232128765_1798536695.txt

 

[clandestine]

Here's the log of a typical session running MapBot, runtime ~50minutes.

Enabled Plugins:

2017-01-05 22:56:03,926 [14] DEBUG Logger - [AdvancedItemFilter] Enable
2017-01-05 22:56:03,926 [14] DEBUG Logger - [Alcor75PlayerMover] Enable
2017-01-05 22:56:03,927 [14] DEBUG Logger - [AlerterReloaded] Enable
2017-01-05 22:56:03,927 [14] DEBUG Logger - [AutoLogin] Enable
2017-01-05 22:56:03,928 [14] DEBUG Logger - [Breaches] Enable
2017-01-05 22:56:03,928 [14] DEBUG Logger - [Chicken] Enable
2017-01-05 22:56:03,929 [14] DEBUG Logger - [EXtensions] Enable
2017-01-05 22:56:03,929 [14] DEBUG Logger - [FlaskHelper] Plugin Enabled
2017-01-05 22:56:03,929 [14] DEBUG Logger - [GemLeveler] Enable
2017-01-05 22:56:03,930 [14] DEBUG Logger - [Monoliths] Enable
2017-01-05 22:56:03,930 [14] DEBUG Logger - [Navali] Enable
2017-01-05 22:56:03,931 [14] DEBUG Logger - [StashBuddy] Enable
2017-01-05 22:56:03,931 [14] DEBUG Logger - [Stats] Enable

If you require the full client log, let me know.

 

[pushedx]

Thanks guys. Going to be doing more threads with updates soon with some changes, so closing this for now until next version.

Basically it'll be useful to know which frame the data came from, so correlate "over time" metrics. For example:

Objects (left) per Frame (bottom): Gyazo - 40b2708575cb5adf232c6e546df51035.png
Memory Access (milliseconds) (left) per Frame (bottom): Gyazo - 82bf25b571dddcd9b79323aa4f01ae7a.png

Those were from Twilight Strand, so pretty small/fast results. From what I'm seeing, there's no low native level optimizations needed, it's higher logic and user logic that will be the focus on profiling soon, but at least we can show it!