After update to Companion 3.0.0-rc2, button actions do not play out immediately

[BBrazner]

I just updated to 3.0.0-rc2 (3.0.0-rc2+5989-stable-4d17e724) on Mac M1 Mini. vMix 4K 26.0.0.44 x64 is running on Windows 10 with all latest updates.

Prior to the Companion 3.0 update, I was running 2.4 and all was good. With the update to 3.0, button actions (e.g., preview input x, fade, etc. ) do not always play out immediately. Frequently, and at random times, there's a delay anywhere from 2 to 10 seconds before the actions start to play out. Sometimes the button actions play out immediately. That is to say, the problem can't be reproduced at will. Note: At the vMix computer, all mouse clicks and keyboard presses are responded to immediately.

Upon restarting Companion 3.0, button actions to vMix play out immediately. But after a period of time (indeterminate), the problem returns.

No other Companion modules are experiencing any problems.

I will provide the Companion log the next time the problem occurs.

[thedist]

Logs will help a lot to see if there are any errors that may be causing this. Additionally check your config vMix instance in Companion and try to increase the API Polling Interval and see if that has any impact as it could be with some of the additional instance variables and data processing we do your machine may be struggling polling that fast if it's a particularly large vMix production.

What would also be helpful is if you could provide your vMix API data when these issues occur so I can run it through some testing and see if I can find anything that may be problematic. This data can be found by going to the /api path of your vMix machine, with the port set to your Web Interface port. So if you're running vMix locally on port 8088 it'd be http://localhost:8088/api and then just copy/paste all of that into a text file.

[BBrazner]

I raised the API polling interval from 250ms to 1000ms. Again, Companion starts out ok, but eventually timeout errors start to appear in the log at a very fast rate. Eventually, the instance crashes apparently with an out of heap condition. I will attach files showing the timeout errors and the heap crash. I will also include the vMix api listing you requested. heap out of memory.txt Timeout errors.txt vmix api.txt

[BBrazner]

If I need to revert back to Companion 2.4, what is the procedure for that? I have the 2.4 dmg and a full export of the 2.4 config taken just before the upgrade to 3.0.0..

[greggibson]

Yes I have this exact same experience. Running RC2 on Win11 Pro and vMix26. vMix module response degrades over time and eventually crashes or becomes disabled. I am running the ATEM module and Vicreo Listener. They are not affected.

After restarting the vMix module it works again but after a short period of time the button response degrades again until eventual crash.

I am running vMix, Companion RC2/RC1, BlackMagic ATEM Control and Zoom client on the machine along with NDI Virtual webcam.

USB connected devices would be keyboard, mouse, StreamDeck, ATEM, headphones.

13900K CPU on z790 Asus mobo. 64gb RAM.

[psvail]

I'm running the last version of vmix 25, with close to 100 inputs, 3 ptz ndi cameras, and a qu16 audio mixer (usb). Same issue, except I have not seen it crash.

[thedist]

I've just pushed a performance fix that should help slower systems or those with exceptionally large vMix productions.

As well as some tweaks to how variables were handled, there's also a new config option to limit input variables to just the type selected (name, number, or GUID). If that limit is enabled it will dramatically reduce the number of variables that need to be processed, but will mean they will not be available at all to use, rather than just omitted from auto-complete.

I'll post an update when the module update is added to the Companion builds, and I'll continue to do further performance improvements but based on the vMix API data provided earlier I noticed about a 5x improvement in variable processing, 10x when limiting the input variables, so hopefully this should be sufficient.

[greggibson]

I'm definitely not on a slow system. The vMix preset I have loaded has about 100inputs and vMix is indicating 1-2% CPU use. Task manager shows about 10% CPU use.

Thanks much for pushing out and update. Appreciate your efforts!

[thedist]

What matters is the CPU usage of Companion and the process for the vMix instance. And keep in mind that each input can have hundreds of variables so a 100 input vMix production (which is regarded as a very large production as usually for performance/redundancy reasons such workload is commonly spread over multiple vMix machines) will result in tens of thousands of variables that will be updated each and every time the API is polled (so up to 10 timers per second).

On the vMix servers that I use, and the machines used at some of the large events where we run Companion, there's been no issue with even large vMix shows that have been running Companion v3 for many months now, it's now only that people are testing the Release Candidate days from it being released that a small number of users are encountering these issues and the common factor so far has been slower systems.

[Julusian]

@thedist perhaps a guard/check could be added to limit the number of in-progress polls? Something like dont call https://github.com/bitfocus/companion-module-studiocoast-vmix/blob/b90e171d6dd2497ac4134adeb4ae344f042d10dc/src/tcp.ts#L294-L296 until the update has finished executing. It will need some safeguards to avoid getting stuck, and I don't know if it will be possible to track the calls/responses as I am hoping.

Or perhaps a simpler approach, will be to wrap the update in a queue, so that at any time only one update an be running, with up to one being queued.

My thinking here is that either of these approaches will make the polling be more 'best effort' so that it will run at the specified rate when possible, but if will skip polls if the system appears to not be keeping up. Not the best metric for 'keeping up' as you are likely spawning other async tasks off in the update, but hopefully it will catch enough of it?

Also, don't forget that you can distribute the pkg folder produced by yarn companion-module-build, so if you have a testing version of the module you want others to try, they can drop that into their module dev folder (once they are told how to do that)

Is there anything I can do to try and reproduce this myself?

[thedist]

The issue with limiting the polling of the API is that it'll reduce the responsiveness of feedback, and parsing the XML into JSON and checking what has changed/checking feedbacks takes negligible time when testing uses Nodes own performance measuring module.

The slowest point seems to be variables (and the only thing that I could see slowing things down short of some actual error, but no one is seeing anything that indicates something other than CPU limitations and timing out). For example using one of the vMix XMLs posted earlier on an old laptop I was seeing around 39,000 variables and it taking 180ms, my recent patch reduces that to about 40ms, and if using the variable limiter config option it'll decrease to 20ms, or all the way down to 8ms if all input variables are disabled.

[Julusian]

The issue with limiting the polling of the API is that it'll reduce the responsiveness of feedback, and parsing the XML into JSON and checking what has changed/checking feedbacks takes negligible time when testing uses Nodes own performance measuring module.

My intention there was to only slow it down when the system wasnt keeping up, to avoid a backlog of processing. So it shouldnt reduce responsiveness. But if that part is being quick, then maybe it isnt necessary. With the queue proposal it would only skip a poll if it is still processing one, and one is queued, in which case the currently queued update would be replaced with a more recent update. So just as responsive, but is less likely to leak memory and max out the cpu.
module-base is using similar concepts for handling feedbacks, to avoid excess feedback checks

The slowest point seems to be variables (and the only thing that I could see slowing things down short of some actual error, but no one is seeing anything that indicates something other than CPU limitations and timing out). For example using one of the vMix XMLs posted earlier on an old laptop I was seeing around 39,000 variables and it taking 180ms, my recent patch reduces that to about 40ms, and if using the variable limiter config option it'll decrease to 20ms, or all the way down to 8ms if all input variables are disabled.

Do you know what part about it is slow? your code, module-base the companion side, or the ipc?

[thedist]

So just as responsive, but is less likely to leak memory and max out the cpu.

I'll work on adding that next then, I think the best option may be to have the variables side of things queued, but still let the JSON parsing and checking feedbacks continue (or perhaps have that as it's own queue too).

Do you know what part about it is slow? your code, module-base the companion side, or the ipc?

instance.setVariableValues was the slowest part from the checking I did within my own module using Nodes perf_hooks and measuring the time before/after, accounting for about 100ms to 120ms of the 180ms total. I didn't do any performance testing within module-base. The largest benefit from my recent commit was doing comparison between current variables and new variables within my module and only setVariableValues the changes rather than giving it all the variables each time.

The next slowest part was actually processing the potentially hundreds of variables for each Input, so not much performance gains to be made there other than reducing the number of variables. The input variables alone accounted for about 22ms of the 180ms for the whole start to finish of processing variables.

[Julusian]

I'll work on adding that next then, I think the best option may be to have the variables side of things queued, but still let the JSON parsing and checking feedbacks continue (or perhaps have that as it's own queue too).

Cool. Yeah having separate queues sounds like a decent idea.
Make sure there is enough async in them for it to help though. The variables logic looks to be sync, so it will want a debounce instead of a queue.

instance.setVariableValues was the slowest part from the checking I did within my own module using Nodes perf_hooks and measuring the time before/after, accounting for about 100ms to 120ms of the 180ms total. I didn't do any performance testing within module-base

ok, ill take a look here to see if there is anything major on our side that can be improved.

[BBrazner]

For what it's worth, I have 140 inputs the bulk of which are three NDI PTZ cameras each with a boatload of presets. My Win 10 CPU runs at 35%. I'd like to think my system is not under-powered.

I posted a file to this issue showing the vMix module on my Companion machine (Mac M1 Mini) crashing due to an out-of-heap condition after a period of time. Are the fixes discussed above going to solve this problem?

I have a production this Friday. My system is not stable. I'm thinking I need to revert back to 2.4. Please, can anyone tell me the procedure for that? I have the 2.4 dmg file and a full 2.4 config export taken just before applying 3.0.0-rc2.

[thedist]

Can those in this thread experiencing issues please try the latest Comapnion beta build and see if the issues are still there.

For anyone wanting to revert to 2.4, it should just be a case of uninstalling v3, installing v2.4, importing the config.

[BBrazner]

On Mac, I sent 3.0 to Trash (as I did not see an option to uninstall), installed 2.4 whereupon my buttons came up in their 2.4 last-used state, and I was good to go with 2.4 again. I was surprised when I did not need to import my last-used 2.4 config backup.

[thedist]

If you need to import a config it depends on what modules you use. For example, if a module was to rename an action in Companion v3, it would update the database and any actions using the old name would be updated to what it was renamed to when that latest version of the module is run. If the user then goes back to a version of Companion before that renaming, the database would still have that new name but the Companion module would have no idea what that action is.

vMix hasn't had any changes that would not be backwards compatible in a couple years though, but some other modules may have had upgrades in v3 that has changed the database data for them. If you import a config from 2.4 though, you will be sure that all of the data is good for 2.4, and you wont have data for v3 modules in the database.

[Julusian]

With 3.0 Companion is now using a different subfolder for each release, to make version hopping easier. As seen here, that manifests as going back to 2.4 gives you your config as you left it before upgrading to 3.0 Equally, when switching back to 3.0, it will load the config you last used when running 3.0. It will even warn that 2.4 was run mroe recently when 3.0 is next run

So it is perfectly safe to jump around versions now, without fear of corrupting configs.

[BBrazner]

Thanks for confirming the use of version-specific configs. That's a great feature! I did make some changes to my 3.0 config before I reverted to 2.4, and am looking forward to not having to make those changes again when I go back to 3.0.

I'm not in a position to be a 3.0 beta tester, but if there was a way to just test the fixed vMix module in 3.0.0-rc2, then I might be in a position to do that. For instance, can the fixed vMix module be slipped in to some Companion folder where it would override the regular/bad module?

Finally, does the fixed vMix module solve the out-of-heap problem I reported above?

[psvail]

Yes, the version folder makes a world of sense, thanks! Although I am keenly interested in the responsiveness testing, I will be away from my system until Sept, so I'm afraid I can't help shake it out. Sounds like you have a handle on it, and look forward to trying out the variable type selector (is that multiples types or just one? - i never use uid). Thanks for the good work, and this is a Wonderful Thing!

On Thu, Jul 6, 2023, 12:24 PM BBrazner @.***> wrote:

Thanks for confirming the use of version-specific configs. That's a great feature! I did make some changes to my 3.0 config before I reverted to 2.4, and am looking forward to not having to make those changes again when I go back to 3.0.

I'm not in a position to be a 3.0 beta tester, but if there was a way to just test the fixed vMix module in 3.0.0-rc2, then I might be in a position to do that. For instance, can the fixed vMix module be slipped in to some Companion folder where it would override the regular/bad module?

Finally, does the fixed vMix module solve the out-of-heap problem I reported above?

— Reply to this email directly, view it on GitHub https://github.com/bitfocus/companion-module-studiocoast-vmix/issues/213#issuecomment-1623965713, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADAOUX3G4RZQGHWVUIHJAU3XO3RDLANCNFSM6AAAAAAZ3YQ4GU . You are receiving this because you commented.Message ID: @.*** com>

[Julusian]

@thedist I'm taking a look at the performance of the companion side of this. Trying with 80000 variables, to make sure to stress it.

It is spending about 1000ms inside of companion code. 200-250ms is being spent parsing the json received from the module 600ms is spent figuring out which ones changed, and splitting them into the removed, changed arrays 200ms is spent processing these new values.

the profile gets hard to read in the processing, there are a couple of function calls but not many. is the iterating over all the variable names that costly?

of that 600ms of diffing the values, 400ms looks to be spent on logging the new values. this is logging at the silly level which is hidden by default (even for core developers), so an easy speed boost is to check the log level is enabled before running each line

of the 200ms spent processing the new values, 100ms+ was spent building an array/set a couple of times of the changed/removed ids. doing that once instead while doing the diffing saves 100ms.

In total, this is saving 50% of the cpu time on the companion side, which should be a noticable improvement. This is pushed to beta

It feels like more should possible inside the diffing, as there are some notable hot spots, but I'm not sure how to improve it:

---

On the module side, the call to setVariableValues is taking 300-400ms. 200ms+ of that is spend serializing the json the remaining 100ms+ is spent reshuffling the new values, and updating the store of the current values. Im not 100% sure on what is being slow here the heatmap isnt lining up on my profiles. But replacing the Object.entries call with a for in loop would be a good idea, as I have now discovered that using Object.entries is almost 3 times slower than other methods. Ill let you know once there is an updated module-base to use

[BBrazner]

I noticed the log does not have timestamps. Should I open a separate issue for this?

[psvail]

Great analysis! Thanks for digging.

On Thu, Jul 6, 2023, 7:41 PM Julian Waller @.***> wrote:

@thedist https://github.com/thedist I'm taking a look at the performance of the companion side of this. Trying with 80000 variables, to make sure to stress it.

It is spending about 1000ms inside of companion code. 200-250ms is being spent parsing the json received from the module 600ms is spent figuring out which ones changed, and splitting them into the removed, changed arrays 200ms is spent processing these new values.

the profile gets hard to read in the processing, there are a couple of function calls but not many. is the iterating over all the variable names that costly?

of that 600ms of diffing the values, 400ms looks to be spent on logging the new values. this is logging at the silly level which is hidden by default (even for core developers), so an easy speed boost is to check the log level is enabled before running each line

of the 200ms spent processing the new values, 100ms+ was spent building an array/set a couple of times of the changed/removed ids. doing that once instead while doing the diffing saves 100ms.

In total, this is saving 50% of the cpu time on the companion side, which should be a noticable improvement. This is pushed to beta

It feels like more should possible inside the diffing, as there are some notable hot spots, but I'm not sure how to improve it: [image: Screenshot from 2023-07-06 23-38-41] https://user-images.githubusercontent.com/1327476/251591510-47d5ff38-ecf4-4e33-aea9-8eb99171dfde.png

On the module side, the call to setVariableValues is taking 300-400ms. 200ms+ of that is spend serializing the json the remaining 100ms+ is spent reshuffling the new values, and updating the store of the current values. Im not 100% sure on what is being slow here the heatmap isnt lining up on my profiles. But replacing the Object.entries call with a for in loop would be a good idea, as I have now discovered that using Object.entries is almost 3 times slower than other methods. Ill let you know once there is an updated module-base to use

— Reply to this email directly, view it on GitHub https://github.com/bitfocus/companion-module-studiocoast-vmix/issues/213#issuecomment-1624437765, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADAOUXZP5Q5372VX3TZ6HJLXO5EMJANCNFSM6AAAAAAZ3YQ4GU . You are receiving this because you commented.Message ID: @.*** com>

[Julusian]

It feels like more should possible inside the diffing, as there are some notable hot spots, but I'm not sure how to improve it:

Circling back to this, that changed_variables object which is taking 100ms to build isnt being used anywhere anymore. It previously was, before the all_changed_variables_set was added.
So removing that should gains a further 10% improvement over before

---

I noticed the log does not have timestamps. Should I open a separate issue for this?

what logging is that?

[thedist]

I've been trying some of my own testing to see if I could improve the setVariableValues, as I was surprised iterating over them was so costly.

I haven't found any significant improvements yet, although I do wonder if an option may be to add an additional param to the function where by default the function works as it currently does, but if a certain option is provided by the module setVariableValues could skip the comparison checking entirely and either 1. replace that instances variables in their entirety with the provided variables and treat each variable as it being changed from whatever may previously have been set, or 2. treat each variable provided as having been changed so they all need updating.

An example of why this could help is that the vMix module does it's own check for changes because we store the variables within the instance for use elsewhere, so anything that we send to setVariableValues is known to be a changed, and it has been more performant to do this than to just send all variables each time to setVariableValues.

[BBrazner]

As to the logging issue, I was referring to the Companion 3.0 vMix module DEBUG log which does not include timestamps. Perhaps there's a setting I need to enable?

[BBrazner]

Where do we stand with this issue? Has it been fixed? If yes, is there a way to upgrade to 3.0.0-rc2 (with the bad vmix module) and then install the fixed vmix module? What I'm hoping to avoid is installing a 3.0 beta version in order to get the vmix fix.

[Julusian]

@thedist yeah I am open to having a parameter for that. should be an easy change to make

@BBrazner the betas are essentially 3.0.0-rc2 with some updated modules and additional companion bugfixes. Until 3.0.0 are released, they are probably more stable than the latest 3.0.0-rc2. Plus when the 3.0.0 release is done (or another rc) it will be whatever the latest beta is at that time

[thedist]

As for if the issue is fixed, try it and see. As I've said I can't reproduce the issue, and every event production I work with hasn't had issues, so all I can do is to add in performance improvements, more logging, and config options that let you disable some instance variables to hopefully reduce load. I wont know if that 'fixes' it for you until you try it because it still is only a small minority of users with an issue.

[psvail]

Unfortunately, I'm one of those affected, but I won't be able to test until mid September. Let's hope the variable flags do the trick! Thanks again.

On Fri, Jul 14, 2023, 5:14 PM Jeff Martin @.***> wrote:

As for if the issue is fixed, try it and see. As I've said I can't reproduce the issue, and every event production I work with hasn't had issues, so all I can do is to add in performance improvements, more logging, and config options that let you disable some instance variables to hopefully reduce load. I wont know if that 'fixes' it for you until you try it because it still is only a small minority of users with an issue.

— Reply to this email directly, view it on GitHub https://github.com/bitfocus/companion-module-studiocoast-vmix/issues/213#issuecomment-1636451383, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADAOUX4MFSJ4WOZM2BUJO3DXQGZE5ANCNFSM6AAAAAAZ3YQ4GU . You are receiving this because you commented.Message ID: @.*** com>

[BBrazner]

I'm curious about the new config option to limit the returned variables. I only use feedback for cameras in preview/program. Will I be able to use the new option to exclude all variables except for what is necessary to process preview/program feedback?

[thedist]

You'll still be able to use all actions and feedbacks with all of the input variables toggled off and disabled (that's as long as you don't try to use one of those variables in the options for those actions/feedbacks).

For a long explanation, for every input in vMix Companion will create about 40 variables for things like input name, number, duration, time remaining, volume meter, playing, loop, etc... These can be used either to display this data as text on a button, it can be used in input fields to feed in to actions/feeds, or in Companion triggers to automate things. Each of those 40 variables is duplicated 3 times, once to reference an input by name, again for number, again for GUID. This means that by default you could do $(vmix:input_vt1_remaining), or $(vmix:input_12_remaining), or $(vmix:input_0de07bdc-97c8-4665-81d6-b978b7c797f9_remaining). Some people like to use names, some numbers, some keys, Companion provides for all those use cases. That does mean by default there'd be about 120 variables per input, and this number goes up for things like List inputs as each item in the list also has variables for it.

The config options Input Variables by Name, Input Variables by Number, and Input Variables by GUID, hide some of the variables from autocomplete, for example if you only reference inputs by Name you could hide numbers and GUID from showing up in autocomplete. This hides them from the UI but Companion still makes the variables just in case you need to quickly reference a variable by number because 2 inputs share the same name for example.

There's also 1 more recent config option, Limit Input Variable Types. this will disable all input variables entirely, except those which you have toggled on above. As long as you don't try to use any of these variables that are now disabled, eg you don't use $(vmix:input_.....), then you're still good to use all the actions and feedbacks you like, with the performance benefits or not having to generate thousands, potentially tens of thousands, of variables, that could have been updating each time the API is polled.

[BBrazner]

Thanks for the detailed explanation and all your efforts to improve the situation. I'll try the beta now and will do the Limit Input Variable Types to disable all the input variables.

Have you reached out to vMix to see if they can provide some relief from their end? For instance, they could implement a setting for only returning input variable names (i.e., not sending numbers and guids), or a setting for only returning a couple of specified variables instead of all 40 for every input. For those of us who claim we have CPU to spare, if makes sense to me to have vMix spin some cycles to help out with the problem.

[thedist]

It's not something vMix can fix on their end. Taking the XML data they provide, parsing it to JSON (what Companion works with), and checking feedbacks usually takes less than 10ms, It's using that data to then make all the variables, and send them from this vMix module to Companion itself, which then has to check if any of those variables are used anywhere and need updating stuff, or if a trigger is using them, etc... this takes significantly longer than the rest of the process.

What I may do in a future update is create a more thorough set of config options that allows users to finely tune the functionality they want out of this module, and nothing more. Until then hopefully the new config options should be sufficient, maybe slowing the API polling interval setting if needed.

[thedist]

I've not had any new reports of this so I'm closing it for now, but will reopen if people still have issues.