VA lagging with plugins

[Loriath]

I have a clean install of Windows 10(Creators Update), Voice Attack, and the latest HCS Voicepack (Verity).

I have been struggling with an issue that I have traced back to having any plugins enabled.

Any command that relies on a plugin seems to have a random lag when responding. I can give commands and VA recognizes them but the responses will lag, anywhere from a second to 10 seconds. If i use a command that is not reliant on a plugin, it gets executed almost immediately.

I have tried reinstalling plugins, running VA as admin (which seems to make it worse for whatever reason) and even marking VA as High Priority in the Task Manager, all with no change. This is both with HCS Voicepacks or the EDDI plugin.

I know its plugins causing this slow down because if I disable plugins and use an older VA profile for the same commands that do not rely on plugins, or other commands with plugins enabled but are not used, it is fine.

Any Ideas? I posted on the HCS forums with no luck.

[Loriath]

No ideas from the community? Hmmm....

[Pfeil]

I've built and attached a simple plugin, as I'd like to try and find out when the issue occurs exactly.

Import the profile, and place the .dll into its own folder(the name of which doesn't really matter) inside the "Apps" subfolder of your VoiceAttack installation directory.

When you run the commands inside that profile, you'll see three numeric values printed to the log; These values are marked with:

• pink(before the plugin is called)
• purple(when the plugin executes)
• black(after the plugin has executed for commands "Test One" and "Test Two", and after the plugin action has been called but not necessarily completed for command "Test Three" and "Test Four).

Run all the commands in sequence, and post the output.


Contents of "VoiceAttack Execution Time Test Plugin.dll":

Code: [Select]

using System;
using System.Collections.Generic;
using System.Text;
using System.Windows.Forms;
 
namespace VAETTP
{
    //this is a very basic plugin created very quickly (maybe 20 minutes, including the profile).  Note that this class depends on the WinampLib.cs file also located in this project.

    //also note that you'll need a running instance of winamp to actually see anything happen... pick a good song and play it while you are issuing voice commands

    public class VoiceAttackExecutionTimePlugin
    {
        public static string VA_DisplayName()
        {
            return "VoiceAttack Execution Time Test Plugin";  //a name to distinguish my plugin from others
        }

        public static Guid VA_Id()
        {
            return new Guid("{144eb47e-7130-477f-9043-f5b4469efc57}");   //note this is a new guid for this plugin
        }

        public static string VA_DisplayInfo()
        {
            return "VoiceAttack Execution Time Test Plugin";  //this is just extended info that you might want to give to the user.  note that you should format this up properly.
        }

        public static void VA_Init1(dynamic vaProxy)
        {
            //not needing to initialize anything here this time
        }

        public static void VA_Exit1(dynamic vaProxy)
        {
            //no need to do anything on exit with this implementation
        }

        public static void VA_StopCommand()
        {
            //no need to monitor this
        }

        public static void VA_Invoke1(dynamic vaProxy)
        {
            string iVal = vaProxy.Context;

            switch (iVal)
            {
                case "Timeofexecution":
            vaProxy.WriteToLog(DateTime.Now.Ticks.ToString(), "purple");
            break;
            case "Timeofexecutionvar":
            vaProxy.SetDecimal("timeofexecution", DateTime.Now.Ticks);
            break;
                default:  //the catch-all for this is to just bail out (undefined or null or whatever)
                    vaProxy.WriteToLog("VoiceAttack Execution Time Test Plugin Error: \"" + iVal + "\" is not a known command", "red");
                    break;
            }
           
        }
    }
}
It's pretty much the example plugin. As you can see, nothing malicious in there(if you want to scan it anyway, I understand. That's what I would do).

[Loriath]

OKay, I tried this a few times. I made sure that everything I normally run was started and working.

Here is the output

Code: [Select]

20:39:29 - 636291815698341064
20:39:29 - 636291815698311063
20:39:29 - 636291815698151042
20:39:29 - Recognized : 'test four' (Confidence 94)
20:39:27 - 636291815675963207
20:39:27 - 636291815675968220
20:39:27 - 636291815675738193
20:39:27 - Recognized : 'test three' (Confidence 92)
20:39:25 - 636291815654315456
20:39:25 - 636291815654285456
20:39:25 - 636291815654270454
20:39:25 - Recognized : 'test two' (Confidence 95)
20:39:23 - 636291815634827968
20:39:23 - 636291815634812966
20:39:23 - 636291815634797964
20:39:23 - Recognized : 'test one' (Confidence 94)
20:39:21 - 636291815613750281
20:39:21 - 636291815613720277
20:39:21 - 636291815613585263
20:39:21 - Recognized : 'test four' (Confidence 95)
20:39:18 - 636291815588047006
20:39:18 - 636291815588027003
20:39:18 - 636291815587946997
20:39:18 - Recognized : 'test three' (Confidence 95)
20:39:16 - 636291815566489259
20:39:16 - 636291815566414253
20:39:16 - 636291815566344243
20:39:16 - Recognized : 'test two' (Confidence 95)
20:39:14 - 636291815546101659
20:39:14 - 636291815545871632
20:39:14 - 636291815545746620
20:39:14 - Recognized : 'test one' (Confidence 95)
20:39:12 - 636291815522473652
20:39:12 - 636291815522123606
20:39:12 - 636291815522088601
20:39:12 - Recognized : 'test four' (Confidence 95)
20:39:09 - 636291815499605735
20:39:09 - 636291815499505726
20:39:09 - 636291815499395707
20:39:09 - Recognized : 'test three' (Confidence 95)
20:39:07 - 636291815474527536
20:39:07 - 636291815474397518
20:39:07 - 636291815474382520
20:39:07 - Recognized : 'test two' (Confidence 86)
20:39:05 - 636291815453689815
20:39:05 - 636291815453659807
20:39:05 - 636291815453644809
20:39:05 - Recognized : 'test one' (Confidence 95)
20:39:02 - 636291815421265682
20:39:02 - 636291815421215675
20:39:02 - 636291815421120659
20:39:02 - Recognized : 'test four' (Confidence 92)
20:38:59 - 636291815396812512
20:38:59 - 636291815396787505
20:38:59 - 636291815396772503
20:38:59 - Recognized : 'test three' (Confidence 95)
20:38:57 - 636291815373599549
20:38:57 - 636291815373569545
20:38:57 - 636291815373554543
20:38:57 - Recognized : 'test two' (Confidence 96)
20:38:43 - 636291815232396556
20:38:43 - 636291815232381554
20:38:43 - 636291815232346553
20:38:43 - Recognized : 'test one' (Confidence 95)
20:38:40 - 636291815201887662
20:38:40 - 636291815201857666
20:38:40 - 636291815201712647
20:38:40 - Recognized : 'test four' (Confidence 95)
20:38:37 - 636291815179239720
20:38:37 - 636291815179219718
20:38:37 - 636291815179204712
20:38:37 - Recognized : 'test three' (Confidence 95)
20:38:35 - 636291815159187165
20:38:35 - 636291815159157157
20:38:35 - 636291815159137166
20:38:35 - Recognized : 'test two' (Confidence 95)
20:38:33 - 636291815136759302
20:38:33 - 636291815136744300
20:38:33 - 636291815136729298
20:38:33 - Recognized : 'test one' (Confidence 84)
20:36:03 - 636291813632932208
20:36:03 - 636291813632897200
20:36:03 - 636291813632877201
20:36:03 - Recognized : 'test four' (Confidence 95)
20:36:01 - 636291813612939657
20:36:01 - 636291813612909657
20:36:01 - 636291813612879653
20:36:01 - Recognized : 'test three' (Confidence 95)
20:35:58 - 636291813588766578
20:35:58 - 636291813588596559
20:35:58 - 636291813588581557
20:35:58 - Recognized : 'test two' (Confidence 95)
20:35:57 - 636291813570999315
20:35:57 - 636291813570974312
20:35:57 - 636291813570884303
20:35:56 - Recognized : 'test one' (Confidence 94)
20:35:53 - Plugin 'bindED Plugin v1.0' initialized.
20:35:53 - Plugin 'HCS Voice Packs - Elite Dangerous Journal Reader v1.0 - for VA v1.5.14+' initialized.
20:35:53 - HCS Elite Dangerous Journal Reader Initialized
20:35:53 - Plugin 'VoiceAttack Execution Time Test Plugin' initialized.



[Pfeil]

From what I can see, the delay does not stem from calling the plugin itself.

Let's look at the last tests in your sequence:

Test one(print to log directly, wait for plugin execution)
before to when: 1.4976ms
when to after: 1.5104ms
Total execution time: 3.008ms

Test two(use an intermediate variable, wait for plugin execution)
before to when: 4.5056ms
when to after: 3.008ms
Total execution time: 7.5136ms

Test three(print to log directly, don't wait for plugin execution)
before to when: 23.0016ms
when to after: -0.4992ms (I'm guessing the plugin write happened after the black write to log action)
Total execution time: 23.5008ms

Test four(use an intermediate variable, don't wait for plugin execution)
before to when: 16ms
when to after: 3.008ms
Total execution time: 19.008ms

While it is strange that apparently not waiting for the plugin means execution takes longer(), no execution takes longer than a few tens of milliseconds.


I'm not sure where the delay you're experiencing occurs, but it doesn't appear to be when calling the plugin.

Have you tried making a single call to one of the HCS plugins and checking how long it takes for the return?

[Loriath]

Sorry, I have no idea how to do that.

[Pfeil]

As the issue occurs with EDDI as well, you could try making a call to that:

• Create a new command(command phrase doesn't matter)
• add a "Write a Value to the Event Log" action with the "Value" option set to "{DATETICKS}"
• add a "Set a Text Value" action with the "Variable Name" option set to "State Variable" and the "Text" option set to(something like) "this is a test"
• add an "Execute an External Plugin Function" action with the "Plugin" option set to EDDI and the "Plugin Context"
• set to "setstate" and the "Wait for the plugin function to finish before continuing" checked
• add another "Write a Value to the Event Log" action with the "Value" option set to "{DATETICKS}"
• execute the command and post the output

You can calculate the time difference yourself if you want, by subtracting the first number from the second, and dividing by 10000. That'll give you the millisecond difference.