Delay when connecting to several tracker interfaces

[zachkinstner]

I originally described the issue in #3:

In my simple Unity test client, using OSVR's Unity ClientKit, I'm finding that it takes a long time (~50 seconds) to obtain interface connections for all of these tracker paths. The Unity app is not responsive during this time.

Once I have the connections, it takes another minute or so for all these connections to start providing data. The client's cubes (which each follow one pose) start reacting, one by one, to the hand movements during this time. Eventually, they are all reacting as expected, with the 46 cubes showing the elbow/hand/bone structure.

[zachkinstner]

The code I'm using for my test Unity client looks (basically) like this:

private Interface[] vHandInterfaces; //class variable
private PoseCallback[] vHandCallbacks; //class variable

[... array init, GameObject creation, etc ...]

public void Start() {
    const string rawTrackerPath = "/com_osvr_LeapMotion/Controller/tracker/";

    for ( int i = 0 ; i < 46 ; i++ ) {
        vHandInterfaces[i] = vContext.getInterface(rawTrackerPath+i);
        vHandCallbacks[i] = HandlePalmUpdate; //refers to a class method
        vHandInterfaces[i].registerCallback(vHandCallbacks[i], IntPtr.Zero);
    }
}

[zachkinstner]

Is there a faster (or more efficient) way to connect to these tracker interfaces?

[DuFF14]

Maybe try putting that for loop in a coroutine to see if it prevents a hangup? Something like:

private bool leapInit = false;
public void Start() {
    StartCoroutine(GetLeapInterfaces());
}
IEnumerator GetLeapInterfaces()
{
      const string rawTrackerPath = "/com_osvr_LeapMotion/Controller/tracker/";
       for ( int i = 0 ; i < 46 ; i++ ) {
            vHandInterfaces[i] = vContext.getInterface(rawTrackerPath+i);
            vHandCallbacks[i] = HandlePalmUpdate; //refers to a class method
            vHandInterfaces[i].registerCallback(vHandCallbacks[i], IntPtr.Zero);
            yield return null;
        }
        leapInit = true;
}

[rpavlik]

Hmm, this is unusual. A few thoughts:

• A coroutine would only avoid the hangup at most, but that code shouldn't take that long to run in the first place.
• Note that you're using a "raw" way of doing that - there is a better way of doing callbacks now using .NET events (example in managed-osvr) and while it wouldn't suit your Unity test case here, there is an improved Unity way of dealing with these devices as well - see the examples that come with the Unity package. This shouldn't really affect performance much if any, though, unless the delay is from .net/pinvoke allocations, etc. which I think are reduced with the new code.
• I'm curious whether this same behavior occurs with native code, to find out if it's some performance issue in the binding or if it's in the core.
• The paths you are giving are the simplest possible ones for the core to resolve: as long as your JSON device descriptor is even slightly correct (haven't checked that yet), no aliases need to be followed, it can just directly resolve this as the original source after inferring/generating the SensorElement node.

Basically, "it shouldn't take nearly that long to do that" - so profiling data showing where the time is being taken would be useful.

[rpavlik]

I suppose in the absence of profiling data, we could help to pinpoint the level of the slowdown by putting your sample code into a purely Managed-OSVR app, since it's already mostly compatible from the snippets you showed.

[zachkinstner]

Hi @rpavlik, thanks for taking a look at this (and the other tickets). I'm on another project right now, but I should be able to provide some Unity profiling results in about two hours.

[zachkinstner]

@rpavlik, here is the first frame of available profiler results. The profiler didn't return results while the app is non-responsive, but it looks like the Interface.osvrClientGetInterface() function accrues about 48 seconds during that time:

I also happened to have some debugging output in my current plugin build (outputs the analog values every frame). When Unity starts requesting tracker connections, I noticed that the debugging output stops. This implies that the plugin's entire update loop is locked up during this time.

Here's what I see in the console. It stays like this during the 40-50 second delay, with occasional "skipped 1 frame" lines:

[rpavlik]

Hmm, that profiling data isn't super useful - don't see where the time actually goes. Might have to get some native profiling out.

That console output looks like you're running the Oculus plugin, is that correct? Can you try without the oculus plugin?

[zachkinstner]

Correct. I get the same result (just without the "skipped 1 frame" lines) when I remove the Oculus plugin.

After the tracker connections are obtained, the output continues. I see some "no response from server" and other warning output that might be relevant:

[zachkinstner]

Note that you're using a "raw" way of doing that - there is a better way of doing callbacks now using .NET events (example in managed-osvr)

The TrackerCallback example still uses Interface hand = context.GetInterface(path) for connecting (like my Unity code). The difference seems to be after the connection occurs -- using events vs. callbacks.

The paths you are giving are the simplest possible ones for the core to resolve

Good, that's what I figured. I have previously also tested with the aliases, but the delay still occurred.

I should note that I've been using osvr_print_tree.exe to check the plugin's path names, and all the various "source", "semantic", and "alias" paths seem to be configured/exposed correctly.

[russell-taylor]

If you use DEVICE@tcp:hostname rather than DEVICE@hostname to identify the VRPN connection to use, does this fix it? I've seen cases where the UDP callback connection mechanism can take a long time to connect. Not sure I remember what they were, but this is something to test.

[rpavlik]

Oh, that is an issue then Russ... OK, looks like this goes on my pile.

[jdonald]

@rpavlik Is this delay still present?

[rpavlik]

Sorry I apparently left this issue with a misleading comment - I was mostly referring to the VRPN bug Russ mentioned as "my pile". I have never had a full test case for this issue. Some assistance in reproducing the problem and particularly reducing the test case would be beneficial - trying it with a native-code (rather than .NET) example, seeing if it happens if all the interfaces point to the same path or if they have to point to different paths, seeing if it happens if the paths pointed to exist or not, seeing if it happens with another plugin, etc. (The latter three are particularly important as they'd significantly reduce the difficulty of reproducing the issue if you didn't need to run a server with many sensors, as well as helping to pinpoint the location of the timing flaw.)

Also, the Unity profiler is limited in what it can see - it would be valuable to look with a tracing-enabled build of OSVR with ETW: http://osvr.github.io/presentations/20150901-Intro-ETW-OSVR/ If nothing else, privately sharing a trace recorded during local reproduction of the issue would be more useful data to look at.

[zachkinstner]

Good news -- the delay issue seems resolved with these latest builds:

• OSVR-Core-Snapshot-v0.2-772-gdf65c03-build155-vs12-32bit
• OSVR-Unity-v0.2-122-g2ff3c40-with-core-v0.2-772-gdf65c03-build193

I was previously using OSVR-Core-Snapshot-v0.2-705-g533991b-build147-vs12-32bit and the corresponding Unity client. After updating, I can connect to the tracker and analog paths quickly.

However, now I'm seeing different/incorrect behavior with the analog values. I'll describe that in a separate issue.