DotNet problem.

[Braxius]

Here is a small piece of code that displays what I am talking about. All that it does it display a line, check to make sure the extension is loaded, displaying another line that it is done, and then exit.

Code: Select all

using System;
using System.Collections.Generic;
using InnerSpaceAPI;
using LavishScriptAPI;
using LavishVMAPI;
using LavishSettingsAPI;
using Vanguard.ISXVG;

namespace VGExample {

    static class Program {

        public static Extension VGExt;

        static void Main(string[] args) {
            try
            {
                VGExt = new Extension();

                InnerSpace.Echo("Starting up.");

                while (true)
                {
                    using (FrameLock Locker = new FrameLock())
                    {
                        Locker.Lock();

                        if (!VGExt.ISXVG().IsReady)
                        {
                            InnerSpace.Echo("Required extension (ISXVG) not found.");
                            return;
                        }
                        //if (VGExt.ISXVG().ConnectionState == "IN_GAME")
                        if (VGExt.ISXVG().ConnectionState != "this is never going to be the same so exit")
                        {
                            break;
                        }

                    }
                }

                InnerSpace.Echo("Loading Settings.");

                //stuff
            }

            catch (Exception ExcpetionData)               
            {
                //stuff
            }

            finally {
                //stuff
            }
        }

    }
}

Sitting idle in the game I am getting a consistent 22fps. In the example above it can take a very short time (much less than 500ms I can time it if you really want) or it can take as much as 30 seconds to display the two lines. If you can tell me what I am doing wrong here, I can fix whatever it is that I am doing wrong.

I have my own UI that I use in the game and almost never report anything to the console. The above code is very close to what I use to determine if my script is going to execute. If it takes more than half a second (just by looking at it), I know that its not going to run and I have to restart.

[Lax]

So you can reproduce the problem with ONLY what is in there? I see comments with //stuff, so for example I have no idea if you immediately lock and then do something that takes a while after the "Loading Settings." echo, which if you do, then sometimes you would see the "Loading Settings." one frame, and sometimes in the frame after whatever it is completes.

In other words, the following is what you're giving me (note that I've pulled the loop and cleaned up a few things, but the same code is executing; also note that if your loop was actually looping, you would definitely want to Frame.Wait(true) instead of using Frame.Lock(), so these conditions would be checked once per frame instead of as-many-times-as-the-operating-system-will-run-my-thread per frame, which with only a Frame.Lock() is not guaranteed to be 1 or fewer)

Code: Select all

    static void Main(string[] args) {
                VGExt = new Extension();

                InnerSpace.Echo("Starting up.");

                    using (new FrameLock(true))
                    {

                        if (!VGExt.ISXVG().IsReady)
                        {
                            InnerSpace.Echo("Required extension (ISXVG) not found.");
                            return;
                        }
                        if (VGExt.ISXVG().ConnectionState != "this is never going to be the same so exit")
                        {
                        }

                    }

                InnerSpace.Echo("Loading Settings.");
            }

The above could take up to 3 frames to execute, one for the first echo, one for the explicitly frame locked code, and one for the last echo. At 22fps, that could mean about 136ms for that to happen based on frames alone. If you have a momentary drop to 10fps, the number jumps to 300ms.

And the following could completely change the story:

Code: Select all

    static void Main(string[] args) {
                VGExt = new Extension();

                InnerSpace.Echo("Starting up.");

                    using (FrameLock Locker = new FrameLock(true))
                    {

                        if (!VGExt.ISXVG().IsReady)
                        {
                            InnerSpace.Echo("Required extension (ISXVG) not found.");
                            return;
                        }
                        if (VGExt.ISXVG().ConnectionState != "this is never going to be the same so exit")
                        {
                        }

                    }

                InnerSpace.Echo("Loading Settings.");

		using (new FrameLock(true))
		{
			// stuff
		}
            }

This adds an assumed 4th frame. However, that's not a perfect assumption. The code is going to run in anywhere from 1 to 4 frames. You assume 4 because it's the worst case scenario, but it's entirely possible that it runs in 1 frame. This means that you aren't guaranteed to see the echoes until after the final bit of code. If you want to be guaranteed to actually see the echoes immediately after they are given to Inner Space, you need to force a frame so that Inner Space will render them for you. Consider the following:

Code: Select all

    static void Main(string[] args) {
                VGExt = new Extension();

                InnerSpace.Echo("Starting up.");

		{
			Frame.Wait(true);

                        if (!VGExt.ISXVG().IsReady)
                        {
                            InnerSpace.Echo("Required extension (ISXVG) not found.");
			    Frame.Unlock();
                            return;
                        }
                        if (VGExt.ISXVG().ConnectionState != "this is never going to be the same so exit")
                        {
                        }

			Frame.Unlock();
		}


                InnerSpace.Echo("Loading Settings.");

		{
			Frame.Wait(true)
			// stuff
			Frame.Unlock();
		}
            }

In this code, there is a bare minimum of 3 frames, and 4 frames is still a good assumption. The common case for this will be
frame 1: echo
frame 2: check IsReady and ConnectionState
frame 3: echo Loading Settings (this could happen on frame 2)
frame 4: "stuff"

This way, you will always see the first echo before IsReady and ConnectionState are checked, and you will always see the second echo before "stuff" happens. If "stuff" takes a couple hundred milliseconds (maybe it's loading files from disk into memory and parsing settings out of them, and so on), then without at least doing a Frame.Wait before doing "stuff", you would not be guaranteed to see the echoes until AFTER that completes, which could indeed be more than half a second. I wouldn't know what your "stuff" is though.

Nothing in the pasted code looks particularly troublesome (although the ISXVGWrapper is pretty bad performance, the pasted code shouldn't take measurably more time than it takes to advance frames under normal conditions) -- can you reproduce your issue with that code and that code alone, or does it require "stuff" to be present?

[Braxius]

Yes, with that exact code I am able to reproduce the problem.

[Braxius]

When that script does take an extremely long time to run (~30 seconds), it can take 5-10 seconds before the first line is displayed on the console. During the 30 seconds that it runs, the frame is not locked and continues to run at ~22fps.

[Lax]

I'm getting things set up to look into this, I just tested that code on an XP system for comparison, but I have to wait for the game to patch on my Vista box. So I probably wont get it done today, but just letting you know that I'm getting set up to test it possibly tomorrow.

[Lax]

Okay, now that I'm set up... I don't see any real issues. I created a Console Application, added references to ISXVGWrapper and Lavish.InnerSpace, put your code in there line for line, and the only "problem" I see is that the application actually causes a console window to open, on top of Vanguard. That happens slower than it does on XP, which with the same binary, does not appear to open a console window, or if it does, it is not made visible (although keeping an eye on the task bar shows that something is being launched). If I re-run the app any number of times, I can of course observe that it sometimes takes longer than others for that window to show up. If you're playing in full screen mode, I could see why you don't notice it.

So this in particular I don't see being related to any longer-term problem in the application, I would assume that this is simply a startup time related issue (and beyond my control, since this is a difference between Microsoft's .NET implementations on XP and Vista). I guess I'll have to do some testing of my own to get to the bottom of whatever the issue really is, but bear in mind that if I'm the one doing the code and profiling, I'm not likely to turn up any issues. And I don't know anything about playing Vanguard, so running Diplobot is probably beyond me.

In the meantime, a couple questions that might help me.
Are you making Console Applications or Windows Applications (winforms)? Are you playing Vanguard in full screen mode?

[Lax]

Here's some food for thought. I am using a dual core Vista box, and a hyperthreaded P4 XP box. On the Vista box, I get about the same performance testing this app if I set the processor affinity to a single core, as I do on the XP box without touching it (it would use both virtual cores on the hyperthreaded P4). I set up high-precision profiling, and it takes anywhere from 30 to about 160 milliseconds to run if set to a single core, and far less predictable with the second core in use, anywhere from 80 to 600ms.

I'd recommend using the command "proc 1 only" before running your app, and see how that changes things.

[Braxius]

I am making windows applications, play in windowed mode, and have never noticed another window opening. With InnerSpace loaded and in full screen mode, Vanguard will crash if you have to switch to another window and try to come back.

I'll try the "proc 1 only" command on the dual core box and see what happens. I will not be able to get back to test it until sometime tomorrow.

[Braxius]

When the program does load and start up slower, its not just the first command(s) that takes longer to execute, it is every command after it in the script also.

[Lax]

Further testing pretty much just confirms what I've already known, but perhaps didn't communicate properly. It mostly just adds to my arguments about why proper frame locking is necessary, and perhaps aids in why and how to do so.

Here's what I did. I set up my profiling, checking the amount of time it takes for each individual part of your Main function to execute. I set it to loop 100 times, and I put all of the echoes inside the frame lock.

Here's the results with 1 core enabled: (comments added to the titles for each part, for your understanding, and note that the listed order is not the order of execution)

Code: Select all

   VGTest.Program.Main:base [color=red]Total time for 100 iterations of VGTest.Instance.Go()[/color]
   ----------------------------------------
   Executions: 1
   Minimum time: 249.72785694328ms
   Average time: 249.72785694328ms
   Maximum time: 249.72785694328ms
   Total time: 249.72785694328ms (108.363429119599%)

   VGTest.VGTest.Go:base [color=red]Individual executions of VGTest.Go().[/color]
   ----------------------------------------
   Executions: 100
   Minimum time: 0.284157585917854ms
   Average time: 2.2550991897178ms
   Maximum time: 179.980441464096ms
   Total time: 225.536183291422ms (97.4530942513723%)

   VGTest.VGTest.Go:Echo("Required extension (ISXVG) not ready")
   ----------------------------------------
   Executions: 100
   Minimum time: 0.0128527521654093ms
   Average time: 0.0201173512154233ms
   Maximum time: 0.122380553227158ms
   Total time: 2.0148086057558ms (0.870589056220247%)

   VGTest.VGTest.Go:Echo("Starting up.")
   ----------------------------------------
   Executions: 100
   Minimum time: 0.0120145291981ms
   Average time: 0.0368818105616094ms
   Maximum time: 1.68454875663593ms
   Total time: 3.71304833752445ms (1.60439023271541%)

   VGTest.VGTest.Go:isxvg.IsReady [color=red]calls to isxvg.IsReady, WITHOUT the ISXVG() call, that's shown in another section[/color]
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00167644593461861ms
   Average time: 0.137747974294496ms
   Maximum time: 13.5959765297569ms
   Total time: 13.7988264878458ms (5.96240620309154%)

   VGTest.VGTest.Go:Lock [color=red]Calls to FrameLock.Lock()[/color]
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00279407655769768ms
   Average time: 0.504889633975971ms
   Maximum time: 50.0257055043308ms
   Total time: 50.508521933501ms (21.8244881005317%)

   VGTest.VGTest.Go:VGExt = new Extension()
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00167644593461861ms
   Average time: 0.00949986029617212ms
   Maximum time: 0.755797708857223ms
   Total time: 0.961441743503772ms (0.415434328450127%)

   VGTest.VGTest.Go:VGExt.ISXVG() [color=red]done before the ISXVG.IsReady call[/color]
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00474993014808606ms
   Average time: 0.088013411567477ms
   Maximum time: 8.02542609667505ms
   Total time: 8.8262084381112ms (3.81376198820432%)

And here it is with 2 cores enabled:

Code: Select all

   VGTest.Program.Main:base
   ----------------------------------------
   Executions: 1
   Minimum time: 1784.61385861973ms
   Average time: 1784.61385861973ms
   Maximum time: 1784.61385861973ms
   Total time: 1784.61385861973ms (102.041404531889%)

   VGTest.VGTest.Go:base
   ----------------------------------------
   Executions: 100
   Minimum time: 0.281084101704387ms
   Average time: 17.6918133556859ms
   Maximum time: 408.022911427773ms
   Total time: 1769.20368818106ms (101.160275301584%)

   VGTest.VGTest.Go:Echo("Required extension (ISXVG) not ready")
  ----------------------------------------
   Executions: 100
   Minimum time: 0.0131321598211791ms
   Average time: 0.0924839340597932ms
   Maximum time: 2.11958647666946ms
   Total time: 9.25062866722548ms (0.528936350823097%)

   VGTest.VGTest.Go:Echo("Starting up.")
   ----------------------------------------
   Executions: 100
   Minimum time: 0.0120145291981ms
   Average time: 0.126571668063705ms
   Maximum time: 2.96870634255379ms
   Total time: 12.6716960044705ms (0.724547583137884%)

   VGTest.VGTest.Go:isxvg.IsReady
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00167644593461861ms
   Average time: 0.057837384744342ms
   Maximum time: 5.58284436993574ms
   Total time: 5.78932662754959ms (0.331024561708788%)

   VGTest.VGTest.Go:Lock
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00307348421346745ms
   Average time: 15.9457949147807ms
   Maximum time: 405.354568315172ms
   Total time: 1594.58982956133ms (91.1761303851756%)

   VGTest.VGTest.Go:VGExt = new Extension()
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00167644593461861ms
   Average time: 0.00922045264040235ms
   Maximum time: 0.693769209276334ms
   Total time: 0.922324671696005ms (0.0527370694112312%)

   VGTest.VGTest.Go:VGExt.ISXVG()
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00474993014808606ms
   Average time: 0.167365185806091ms
   Maximum time: 9.48225761385862ms
   Total time: 16.7401508801341ms (0.956641275335%)

The difference in time is very significant. 1769ms with 2 cores, and 249ms with 1 core. You'll ALSO notice that the only non-negligible difference in execution times is the call to FrameLock.Lock(), for a total of 1594ms. That's very significant.

Now, here's another test, with both cores enabled, with the only difference being that I added using (new FrameLock(true)) around the for (int i = 0 ; i < 100 ; i++) VGTest.Instance.Go(); loop, so that the entire loop iterates in 1 frame instead of up to 100.

Code: Select all

   VGTest.Program.Main:base
   ----------------------------------------
   Executions: 1
   Minimum time: 329.86392847164ms
   Average time: 329.86392847164ms
   Maximum time: 329.86392847164ms
   Total time: 329.86392847164ms (175.02708917151%)

   VGTest.VGTest.Go:base
   ----------------------------------------
   Executions: 100
   Minimum time: 0.280804694048617ms
   Average time: 1.74713607152836ms
   Maximum time: 120.704945515507ms
   Total time: 174.731489242805ms (92.7132108396039%)

   VGTest.VGTest.Go:Echo("Required extension (ISXVG) not ready")
  ----------------------------------------
   Executions: 100
   Minimum time: 0.0128527521654093ms
   Average time: 0.0606314613020397ms
   Maximum time: 3.9158982956133ms
   Total time: 6.06817546800782ms (3.20320071579427%)

   VGTest.VGTest.Go:Echo("Starting up.")
   ----------------------------------------
   Executions: 100
   Minimum time: 0.0120145291981ms
   Average time: 0.109527801061749ms
   Maximum time: 6.22687901648505ms
   Total time: 10.9639564124057ms (5.78753090007216%)

   VGTest.VGTest.Go:isxvg.IsReady
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00167644593461861ms
   Average time: 0.0922045264040235ms
   Maximum time: 9.03827884884046ms
   Total time: 9.24504051411009ms (4.88016876711487%)

   VGTest.VGTest.Go:Lock
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00279407655769768ms
   Average time: 0.0729253981559095ms
   Maximum time: 6.66191673651858ms
   Total time: 7.29533389214865ms (3.85097940369225%)

   VGTest.VGTest.Go:VGExt = new Extension()
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00167644593461861ms
   Average time: 0.0111763062307907ms
   Maximum time: 0.925956971221012ms
   Total time: 1.13411567476949ms (0.598664320168015%)

   VGTest.VGTest.Go:VGExt.ISXVG()
   ----------------------------------------
   Executions: 100
   Minimum time: 0.00474993014808606ms
   Average time: 0.0799105895501537ms
   Maximum time: 7.27437831796591ms
   Total time: 8.0148086057558ms (4.23076768268527%)

Now the total execution time with 2 cores is 329ms, and 174ms of it is taken by the same Go() function originally used, implying that it took me roughly 100-130ms to lock the frame initially, which isn't in the profiling info but can be deduced from the differences between the total execution time of main() and VGTest.Go() with (3rd paste) and without the lock (first two pastes), and knowing that the lock is the only difference for that.

So what does this tell us?

The first two tests both released and re-locked the frame each iteration of the loop. The first test was either a) more successful at re-locking before the frame actually advanced, or b) took significantly less time for the frame to advance. And it wasn't B. So, with a single core, the chances of re-locking before the frame advances is much greater than with two cores. The reason for this is fairly obvious -- the main thread can be competing with the frame locking threads at the same instant, instead of only on context switches (in other words, both CPU cores are executing threads at the same time, and both CPU cores are context switching. a context switch is when one core rotates to processing another thread.). So, when it's all running on one core, the bet is that the thread will not switch contexts before you re-lock the frame. The operating system decides when that is, usually based on some amount of time based on the priority of the thread, unless the thread yields control (e.g. by using Sleep()). When it's running on multiple cores, the bet must ALSO take into account that the thread may be running on another CPU (core) entirely. The game's main thread has a significantly better chance of taking control between your frame locks when it is running on another core.

So... how do we use this info to our advantage?

Well, first of all we can cop out and set the processor affinity to a single core. But beyond that, obviously if the game has a good chance of taking control between our frame locks, then we need to make sure that that doesn't happen when we intended for something to actually perform well. Loops that contain implicit or explicit frame locks can be, in turn, explicitly frame locked to force the loop to execute in a single frame -- the expected savings could be dozens of milliseconds per frame lock. Any call to anything in the Inner Space API should be assumed to implicitly frame lock, so this of course includes any loop that simply does InnerSpace.Echo, and so on.

This is, of course, nothing new, it's what I've been saying all along. However, now there's a significantly better argument in favor of greedy frame locking, with test data to back it up and showing the difference between 1 and 2 cores.

But as far as any bugs in the API, absolutely not. The data conclusively tells me that the API in use in your small test case is performing as intended, though perhaps not as initially predicted (in hindsight, it's obvious and makes perfect sense).

I may distribute my profiling code since it would be beneficial to all of these people trying to report that the API is slow.

[Lax]

In response to your latest replies:
re: Windows apps: ok, thanks for the info, that helps me for future testing
re: Not just the first commands: Yep, that's just as I would have expected

[wired203]

I don't think I have seen the option, but since multi core can cause so many issues, would it be possible to add a checkbox in the game setup to set it for single core?

I know we can just use the command "proc 1 only" before launching the game but it would have a much cleaner feel to it and be easier to instruct others on how to take care of the speed issues caused by the multi cores.

I as well as others really appreciate the time you have put into this and can't wait to give the new eq2 harvester a test run this evening with single core and actually watch it work on a continous basis

[Lax]

Certainly such an option can be added, but I don't think it's necessarily something that should be put in the game configuration options. I don't want to be the one enforcing how the CPU cores are rotated with multiple sessions, etc.

It'd be trivial for the harvest script to execute the command or set the affinity through .NET (System.Diagnostics.Process.ProcessorAffinity) or Win32 API (GetProcessAffinityMask/SetProcessAffinityMask). It's not necessarily a requirement of the game (depending on the game of course; EQ2 used to have a pretty sweet bug where you could move across entire zones within seconds just by having a dual core CPU, and EQ1 just recently set their software to use only 1 core), and certainly not of Inner Space, but rather it's a requirement imposed by the design of the .NET application. If the .NET application is designed properly, then it will simply run on multiple cores without issue. The test data should clearly indicate that, considering the difference between pastes 2 (improper) and 3 (much better). It clearly doesn't take much to make that difference, but in the end it's really up to the .NET app developer to either get it done right, or to figure something out so that the "bug" (it's a bug in the .NET app, not in the OS, and not in the API) doesn't affect you, such as by setting the affinity itself. The cleanest route would be for EQ2Harvest to do that itself instead of making the user change some game configuration option in the platform.

[wired203]

Sounds good here, I know it will be sometime before the harvester gets updated as Blazer has been busy with work and someone else has stepped up for the crafting code portion just to keep us running.

For now I'll just crutch with the afinity in the console and see how that works for testing.

[stardog]

Lax, thanks for this info.. i had run into a similar issues with vanguard i had no idea at all how it all worked i feel like i just took a class. heheh

Thanks