intercept Arma Script Profiler

[Dedmen 2704]

 

Disclaimer: If you don't use unscheduled scripts or you don't know what "unscheduled" means this won't be useful for you. If you are a beginner in Scripting this is also likely nothing for you.

This is a tool aimed to help intermediate/advanced Programmers. Also No Battleye!

 

I'm proud to present the first public Intercept based mod!

I have a tiny script performance OCD so when I had the Idea about this last week I couldn't stop myself.

Arma Script Profiler is a mod that allows you to profile scripts in a way that wasn't possible like this before.

ASP replicates what the profiling binary already provides via it's diag_captureFrame commands but instead of only showing Engine Internals it shows Scripts.

 

Features:

- Shows exact execution time of unscheduled script functions

- Can show engine Profiling data (when you are running profiling build)

- Displays Network traffic estimate (number of bytes sent out via publicVariable and similar)

- Can profile scripts down to single Instructions

 

For more updates see my forum posts below, this tool evolved quite a lot since its Inception.

But enough talking, lets start showing:

 

 

 

Download:

You can get the Mod here: https://steamcommunity.com/sharedfiles/filedetails/?id=1652506957

 

In case of Game crashes (Though these have become really rare now) please PM me your crash report or crashdump files.

For bugs and feature requests please refer to the Github page.

 

This is also on Reddit!

I'm not really good in writing fancy forum posts. If someone wants to make this more splendid feel free to PM me.

Uploading this to Armaholic, withSix, Steam workshop or similar is not allowed! Please refer to the License.

 

Here is some text about the old version of the Profiler that I don't want to delete...

Spoiler

In fact it is even using it's UI. Which sadly means that you also need to use the Profiling Binary to use ASP to it's full potential.

I wrote a full Wiki page explaining how to use it.

 

Let me show you how it looks like instead of rambling on further.
Here is an example of what happens when you place a Vehicle in Zeus while using ACE and CBA:

 

Let me explain what you are seeing here. If you ever used diag_captureFrame This Interface will be familiar to you.

 

Right at the top we have a graphical representation of the different Frames. The first row is always just the "total" bar which shows the total length of time that was captured.

Under that there are one or more rows for each Frame that was captured. In this example there is only one but there are ways to capture more than one.
This gives you a visual representation of when in the Frame a script was executed.

 

In the lower part of the window we come to the real meat of this. Here we have a Tree view of all "Scopes" that were executed that Frame.

The first element here is again the "total" time you can ignore it.
Next we have the first Frame.

 

There are 2 kinds of elements that can be displayed in the Tree. Scopes and Log messages.

The first scope inside that Frame is "ace_interact_menu_fnc_render". That is the Name of the Script function that the scope belongs to. You can choose the displayed Name yourself when you instrument your own Scripts.

Right next to that there are 2 "times".
    The first time shows the number of milliseconds since the start of the Capture/Frame.
    The second time shows how long everything inside that scope took to execute. Basically the runtime of that function.

    Both times are with nanosecond precision but I truncate them to 5 decimal places when writing to clipboard and the in-game UI truncates them again to 3 decimal places.

The next number is just the number of sub--elements of that scope. You can ignore it.

After that we have again the Name of the scope. I might add a way so you can define both names independently of each other in the future.

 

You can click on the Arrow to expand a Scope. Like I did with "CBA_xeh_fnc_init" in this example. That will show you which scopes are below that scope.
Essentially this gives you a full list of what functions your function called and how long each of them took.

At the Arrow you can see an example of a log message. This shows the output of a ACE TRACE macro.

You can use log message to print _this for example. So you can get a Calltrace of all your functions together with the arguments passed to the functions.

By using math and the "Time since start of frame" you can also calculate how much time was spent between 2 log messages. Log messages are precise to 2 microseconds.

 

 

 

This only works with unscheduled scripts. Because it measures the time between the start and end of a scope. And you can imagine how useless it would be if your scope starts and only ends several frames later.

 

 

To see all script commands added by ASP you can check the wiki but here are the most important ones:

createProfileScope is the heart of ASP. You use this to create your Scopes. It returns a custom Variable Type. You have to store the result in a private local variable!
When the variable goes out of scope, the scope is also ended. This is how ASP measures the time.

profilerCaptureFrame works just like diag_captureFrame.

It tells ASP to record from the start of the next frame till it's end and will then post the captured (A Capture is a frame that was recorded and is displayed. I will refer to it as Capture from now on) data into your Clipboard.
If you are using the Profiling Binary it will automatically open the UI and you have to press "PASTE ALL" on the bottom to paste the data and display it.

 

 

It is sometimes hard to find the Frame you are interested in. That's why ASP has the Trigger capture mode.

Using profilerCaptureTrigger you can start the Trigger mode. In this mode ASP will record every frame and look for a Trigger event. If a Frame contains a Trigger it will display it to you.
profilerTrigger is that trigger. If you call it while in Trigger mode the current frame will be captured.

Using this you can just place the trigger inside the script you want to profile. Then just start Trigger mode and wait till your script executes.

 

Currently ASP hooks into compile and compileFinal script commands and automatically adds a Scope to every compiled script. I will probably disable that in the Future.

But this way you can immediately start profiling all your scripts without having to instrument them before.

 

If you find some nice optimizations by using this please share :3

 

ASP was already successfully used to find and fix performance problems in ACE. And will most likely help prevent them in the future.

 

Edited February 7, 2020 by Dedmen
New layout

[TGR.hitman 0]

Great!

[das attorney 858]

Thanks DM - appreciate the work - will get to checking things out  :)

[Dedmen 2704]

Big update going on for the last few months. Didn't find time to report about it here.

The profiler got brofiler integration and is now WAY more powerful than just the ingame profiling view. With brofiler you also don't need profiling branch anymore to use it.

Here are a couple screenshots:

 

 

As you can see in the tooltip. It also stores parameters passed to script functions so you can also use this to see what exactly happened in your code.

Brofiler can also profile over the network (By default TCP port 31313). Meaning now you can load the profiler mod on your Arma server. And just connect the Brofiler GUI to it over the network and profile the scripts on your server.

 

This stuff is still in "beta" but only because I'd like to make some performance improvements and maybe add some more features before a full release. For example in combination with my Debugger I might be able to add profiling of scheduled scripts too.
You can get it on the Profiler Github: https://github.com/dedmen/ArmaScriptProfiler/releases/tag/RC6

It uses a special version of Brofiler which is included in the download.

 

If you want to get REALLY crazy with it. The new Profiler also has integration of my SQF-Assembly mod. So you could profile your scripts down to every single SQF VM instruction or command call or variable assignment.

This is enabled by default I think. But this will generate huge amounts of data. You can disable it by just removing the sqf assembly plugin from the intercept folder.

[Sparker 185]

So, could we load it on a linux arma 3 server and remotely profile it? I'd like see what the engine is doing every frame. because we often have huge performance drops down to ~3 FPS and it would be very interesting to know what the hell is going on.

[Dedmen 2704]

On 28.7.2018 at 6:46 PM, Sparker said:

So, could we load it on a linux arma 3 server and remotely profile it?

If I would compile my plugin for Linux then yes. :D Which I didn't try yet. Shouldn't be alot of work though.
 

 

On 28.7.2018 at 6:46 PM, Sparker said:

I'd like see what the engine is doing every frame. because we often have huge performance drops down to ~3 FPS

My profiler only profiles scripts. You might want Arma profiling build and use it's tools to create a dump of the frame onto the server. You can then pull the dump as a text file and copy-paste it into the dialog of the profiling build client.

[Sparker 185]

Thanks! You are very much right... I was looking for something like  the profiling build does actually.

Profiling, Performance, Arma Script Profiler, these things are so confusing!

[Dedmen 2704]

New big update is out.

 

On 1.8.2018 at 1:32 AM, Sparker said:

I was looking for something like  the profiling build does actually.

I can do that too now!

On 31.7.2018 at 10:06 AM, Dedmen said:

My profiler only profiles scripts.

Not anymoooore!

 

 

 

https://github.com/dedmen/ArmaScriptProfiler/releases/tag/1.0.28

with professional wiki page https://github.com/dedmen/ArmaScriptProfiler/wiki

Here are some example videos or screenshots:

 

https://cdn.discordapp.com/attachments/105464579600977920/537591450783842305/2019-01-23_12-14-56.mp4 A look at the default output, general script profiling.

https://cdn.discordapp.com/attachments/105464579600977920/537595406096400385/2019-01-23_12-31-30.mp4 A look at the most often called functions, live updating. With histogram for their runtimes

https://cdn.discordapp.com/attachments/105464579600977920/537730483748864016/2019-01-23_21-28-12.mp4  Profiling binary engine profiling now also visible!

 

 

 

[syscrash 1]

Even though I'm still new to scripting I was already thinking of a tool like this and how useful it would be. THANK YOU so much. Great work. I'm following you on Github, impressive stuff!

 

[Dedmen 2704]

I also integrated profiling branch engine profiling into my profiler so you can now also do engine profiling in the UI.

 

I will push a new Release with all the latest bling bling today and I will update the wiki with new start parameters.

There will also be a Steam workshop release pushed today to make the Profiler more easily accessible for everyone.

ASP now also has support for remote engine profiling on a linux dedicated server.

 

I've spent the last couple days speeding up the mission start time with ACE/CBA by several seconds with the help of the latest iteration of my profiler. It has never been better before, and I hope I continue getting new ideas and will further improve it.

 

Steam Workshop: https://steamcommunity.com/sharedfiles/filedetails/?id=1652506957

Github Downloads: https://github.com/dedmen/ArmaScriptProfiler/releases

Wiki: https://github.com/dedmen/ArmaScriptProfiler/wiki

[auge103 18]

Just awesome. It was never that easy to debug and improve the performance of missions and functions, thank you very much!
One of the most useful tools for Arma right now.

[Dedmen 2704]

On 2/13/2019 at 12:17 AM, auge103 said:

Just awesome. It was never that easy to debug and improve the performance of missions and functions, thank you very much!
One of the most useful tools for Arma right now.

I guess one of the left over problems considering missions is that it doesn't support scheduled scripts, which is what most mission makers use.

 

But these can only run for 3ms anyway and thus cannot drag down your perf really.

Because of that they are not high on my todo list. Certainly possible to implement that though, just didn't get to it yet.

You can still see what they are doing by implementing instruction level profiling, so that's enough of a workaround for me for now.

 

If anyone can bring up a sensible reason why he needs to be able to profile scheduled scripts then step forward.

 

On the up side... I think with engine profiling enabled you can even see the runtime of triggers in there. I should test that. There are tons of things I didn't test out yet, I only focused on profiling ACE/CBA/TFAR stuff so far.

[Dedmen 2704]

New update coming in probably today. Ability to profile network traffic by the profiler displaying to you which script does publicVariable/remoteExec/setVariable when and where and how big the transmitted data roughly is.

Even with callstack!

Here is the publicVariable from the cba settings initialization from Diwako's DUI mod as example.

 

 

On the top you have the normal profiler view, on the right you can see the callstack of the publicVariable call that was logged.

On the bottom in the messages you can see the contents of the variable which is being sent away. Here we can see its CBAs (CBA event) with the event name "cba_settings_refreshSetting" and the setting name "diwako_dui_indicators_icon_medic"

totalling up to about 150 bytes being sent over the network.

 

There is a counter running which counts up the total size of bytes transferred via publicVariable/remoteExec/setVariable

If you were searching for problematic areas, you'd just zoom out, and check when that counter is increasing fast.

Like here for example
 

 

Here we can see it counter quickly climbing from 3,6KB at the start, up to 40KB. In the trace we can see its caused by ACE initializing its CBA settings. Now 40KB once at game start is nothing to worry about, but you can see how this can be used.

 

 

Due to it being a SCRIPT profiler, it will only show you traffic caused by script commands like publicVariable, publicVariableClient, publicVariableServer, remoteExec, setVariable with public flag.

It will only show you how much data you push into that script command, it can't differentiate between sending it to one client and sending it to every client, so these values do not exactly represent the load on the engine, but it will show you hotspots in your code.

 

 

It can be enabled with the -profilerEnableNetwork start parameter.

If you additonally run ArmaDebugEngine (to be found on my steam workshop) you will get full callstacks like shown in the first picture, without it you won't have callstacks.

[Dedmen 2704]

Now that ASP's network profiler already found its first bug I wanna go through how I used ASP to do that.

 

I started by doing a trace recording, and then went into a multiplayer mission (in my case BMR Insurgency on Takistan) and just waited for something to happen, which happend relatively quickly. I scrolled a bit through the trace and found this:

 

 

The number of setVariable with public flag bytes suddenly jumped up by about 3KB, that seems a bit much, what is sending 3KB of variables over the network in such a short burst?

Let's scroll into the offending section.

 

We can see its a cba_xeh_fnc_init, a XEH init eventhandler which gets called when a new unit is spawned.

The unit was spawned by the mission, on the serverside, so variables should really only be initalized on the server? Why is it sending variables from my client?

 

There are two bursts of variables, one at the start, then a big ace_dragging_fnc_initPerson section in the middle which isn't pushing any variables, and then a second burst at the end.

Let's scroll in to the burst at the end

 

Ah so kat_aceBreathing and kat_aceCirculation are initializing the unit, and while doing that sending variables.

That doesn't seem right, the unit is local to the server, it should only be initialized on the server.

If my client initializes its variables, then so does every client.

Meaning if you spawn a AI unit on the server, while 20 players are playing, every player sends about 3KB of variables to the server, which distributes it to all clients again.
Let's calculate this up quick.
20 players initialize the units, that makes 3*20 KB = 60KB of variables being sent from all the clients to the server. But the server has to then redistribute the variables which came from one player, to all the other players.

So the server gets 60KB and needs to send it out again to 19 of the 20 players, that is 1140KB or about 1MB of data being sent out from the server, because every client is initalizing variables which should only be initialized on serverside.

 

If we look at the kat source on Github, we'll see that there is no:

if (!local _unit) exitWith {};

 

There is no check whether the unit is local (the unit can only be local on one machine at a time) so every machine connected to the server initializes the unit, even if it doesn't own it, causing a heckload of unnecessary network traffic.
The solution is adding the local check, which will make sure the unit is only initialized once wherever its spawned, reducing the data transmitted from 1200KB down to 60KB in my 20 player example.

 

There are probably many more bugs like these in all kinds of mission frameworks or mods and we can find and fix them now.

[Whalenator 15]

okay this is epic

[Sparker 185]

This tool is great. But one drawback of Tracy is that it compares strings only by their pointer, which means that if you create a a profile scope with a dynamic name like...
 

private _profilerScope = createProfileScope format ["UpdateObject_%1", _object];

Then when you will try to find scopes with same _object, Tracy will display all profile scopes as separate scopes, and you won't be able to see the nice execution time distribution graph.

 

 

Here's a simple workaround:

gStaticStringHashmap = [false] call CBA_fnc_createNamespace; // Create some object if you don't want to use CBA
misc_fnc_createStaticString = {
  params ["_str"];
  private _strFound = gStaticStringHashmap getVariable [_str, ""];
  if (_strFound == "") then {
      gStaticStringHashmap setVariable [_str, _str];
      _str
  } else {
      _strFound
  };
};

Code above returns the same string with same address every time, so you can use it like this for dynamic scope names:

createProfileScope ([format ["UpdateObject_%1", _object]] call misc_fnc_createStaticString);

 

[Dedmen 2704]

You have an object anyway already, it would be more efficient to store the scope name as a variable on the object, instead of using a seperate namespace.
But the namespace solution if ofc way more universal.

[Sparker 185]

Yes, good point. In my specific case _object is a string-ref to an OOP object and that data is stored in missionNamespace anyway, that's why I wrote the function this way.

[gc8 977]

Hi  @Dedmen looks cool but  I get this error:

 

---------------------------
Tracy.exe - System Error
---------------------------
The program can't start because VCRUNTIME140_1.dll is missing from your computer. Try reinstalling the program to fix this problem. 
---------------------------
OK   
---------------------------
 

obviously I need to install some VC runtime not sure which one though

 

I have win 7 64bit

[Dedmen 2704]

Tracy was supposed to not have that requirement, seems like I goofed when compiling.

https://support.microsoft.com/en-gb/help/2977003/the-latest-supported-visual-c-downloads

The 2019 vc_redist.x64

[gc8 977]

12 minutes ago, Dedmen said:

Tracy was supposed to not have that requirement, seems like I goofed when compiling.

https://support.microsoft.com/en-gb/help/2977003/the-latest-supported-visual-c-downloads

The 2019 vc_redist.x64

 

Installed that, runs now. thx!

[gc8 977]

Hi @Dedmen, sorry to bother you again but I'm trying with IP 127.0.0.1 to connect arma running SP from editor but it won't connect, just says "waiting for connection".

[gc8 977]

Hi @DedmenI got this working with my windows 10 PC. just didn't work with win 7  for some reason.

question, do I need to define scopes in script like explained in here to actually debug my code, or should there be data available already? I can see some script functions appear in the graph but mostly just 3den stuff and not my mission

thx!

[Dedmen 2704]

6 minutes ago, gc8 said:

or should there be data available already?

If you use CfgFunctions or CBA's function system, it should auto-detect them and add scopes by itself.

[gc8 977]

22 minutes ago, Dedmen said:

If you use CfgFunctions or CBA's function system, it should auto-detect them and add scopes by itself.

 

not using those but it's showing up some function calls in my mission

 

Is the frame count supposed to rise when paused?

 

Also sorry if this is stupid question but why cant I see the peak in this screenshot (peak should be in middle):

https://ibb.co/gzSjZ76