CreateChannel is slow responding

[jveisz]

I have the following C# code that works great most of the time but every once in a while CreateChannel will take 400+ms to return instead of the usual 3-4ms.  I can reproduce this on at least two different computers / configurations.

Attached sample output from test program.

Any ideas?

Thanks

        public long SetRangeDigitalOutput(string portID, string[] lineIDs, bool[] values, ref DateTime timeStamp)
        {
            Task digitalWriteTask = null;
            bool[] tmpValues;
            string chanelDescription = string.Empty;
            long timeBeforeCallingWriteSingleSampleMultiLine = 0;
            long timeAfterCallingWriteSingleSampleMultiLine = 0;
            long timeBeforeCreateChannel = 0;
            long timeAfterCreateChannel = 0;


            try
            {

                if (DOPorts.ContainsKey(portID))
                {
                    //build the chanelDescription string
                    foreach (string line in lineIDs)
                    {
                        if (DOPorts[portID].Lines.ContainsKey(line))
                        {
                            chanelDescription = chanelDescription + this.DeviceID + "/" + portID + "/line" + DOPorts[portID].Lines[line].LineNumber.ToString() + ",";
                        }
                        else
                        {
                            throw new ArgumentOutOfRangeException("endLineID", "Line: " + line + " is not available on device: " + this.DeviceID + " port: " + portID);
                        }

                    }

                    chanelDescription = chanelDescription.TrimEnd(',');

                    digitalWriteTask = new Task();

                    timeBeforeCreateChannel = debugTimer.ElapsedMilliseconds;

                    chanel = digitalWriteTask.DOChannels.CreateChannel(chanelDescription, portID, ChannelLineGrouping.OneChannelForAllLines);

                    timeAfterCreateChannel = debugTimer.ElapsedMilliseconds;

                    writer = new DigitalSingleChannelWriter(digitalWriteTask.Stream);

                    tmpValues = new bool[values.Length];

                    values.CopyTo(tmpValues, 0);
                    timeStamp = DateTime.Now;

                    timeBeforeCallingWriteSingleSampleMultiLine = debugTimer.ElapsedMilliseconds;

                    writer.WriteSingleSampleMultiLine(true, tmpValues);

                    timeAfterCallingWriteSingleSampleMultiLine = debugTimer.ElapsedMilliseconds;

                    DebugMessage = " Time before creating DAQ channel = " + timeBeforeCreateChannel.ToString() +
                                   " Time after creating DAQ channel = " + timeAfterCreateChannel.ToString() + 
                                   " Time before calling WriteSingleSampleMultiLine = " + timeBeforeCallingWriteSingleSampleMultiLine.ToString() +
                                   " Time after calling WriteSingleSampleMultiLine = " + timeAfterCallingWriteSingleSampleMultiLine.ToString();
                    
                }
                else
                {
                    throw new ArgumentOutOfRangeException("portID", "Port: " + portID + " is not available on device: " + this.DeviceID);
                }


            }
            catch (Exception)
            {
                throw;
            }
            finally
            {
                writer = null;
                chanel = null;
                digitalWriteTask = null;
            }

            return (timeAfterCallingWriteSingleSampleMultiLine - timeBeforeCreateChannel);
        }

[Maxwell_Taylor]

Hey jveisz

Is the increased time completely random each time you run your code or does it consistantly happen around the same trial?

You may want to put a wait function before the CreateChannel to make sure that the resource isn't reserved and everything has a chance to catch up. 

[kvermeer]

I'm having a similar problem, and I can answer for jveisz- it's extremely consistent.  Every time, the first (of eight) CreateChannel instructions is slow.  I ran the program 40 times:

Hardware device:        Virtual device:
1293                    1275
1293                    1274
1287                    1273
1301                    1273
1297                    1273
1294                    1274
1292                    1274
1290                    1273
1285                    1274
1286                    1274
1287                    1276
1288                    1274
1289                    1275
1288                    1274
1294                    1275
1287                    1287
1290                    1274
1291                    1275
1287                    1273

 These are the duration in milliseconds for the call. Both columns are for PCIe-6321 cards, one virtual and the other physical.

I declare analog input channels, digital input channels, and digital output channels, all in almost identical fashion, and they all take a very short time. Here's the offending line: 

logger.Trace("Configuring channels")
Dim ch01 As DIChannel = Me.DIChannels.CreateChannel("Dev1/port0/line0", "DigitalIn_01", ChannelLineGrouping.OneChannelForEachLine)
logger.Trace("Configured ch01")

and here is the progress log:

frmSplash         09:02:46.8011 TRACE Splash form event (5): Loading National Instruments IO configuration file
modNI             09:02:46.8181 TRACE Loading NI
modNI             09:02:46.8181 TRACE 0: Declared variables
modNI             09:02:46.8181 TRACE 0: Loaded section Machine Settings
modNI             09:02:46.8181 TRACE 1: Loaded section Digital IO 00 - Input
modNI             09:02:46.8181 TRACE 1: Loaded section Digital IO 01 - Input
modNI             09:02:46.8181 TRACE 1: Loaded section Digital IO 02 - Input
modNI             09:02:46.8181 TRACE 1: Loaded section Digital IO 03 - Input
modNI             09:02:46.8181 TRACE 1: Loaded section Digital IO 04 - Input
modNI             09:02:46.8181 TRACE 2: Loaded section Digital IO 05 - Input
modNI             09:02:46.8181 TRACE 2: Loaded section Digital IO 06 - Input
modNI             09:02:46.8181 TRACE 2: Loaded section Digital IO 07 - Input
modNI             09:02:46.8181 TRACE 2: Loaded section Digital IO 08 - Output
modNI             09:02:46.8271 TRACE 2: Loaded section Digital IO 09 - Output
modNI             09:02:46.8271 TRACE 3: Loaded section Digital IO 10 - Output
modNI             09:02:46.8271 TRACE 4: Loaded section Digital IO 11 - Output
modNI             09:02:46.8271 TRACE 4: Loaded section Digital IO 12 - Output
modNI             09:02:46.8271 TRACE 4: Loaded section Digital IO 13 - Output
modNI             09:02:46.8271 TRACE 4: Loaded section Digital IO 14 - Output
modNI             09:02:46.8271 TRACE 4: Loaded section Digital IO 15 - Output
modNI             09:02:46.8271 TRACE 6: Loaded section Analog Input 00
modNI             09:02:46.8271 TRACE 6: Loaded section Analog Input 00 - Calibration
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 01
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 01 - Calibration
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 02
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 02 - Calibration
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 03
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 03 - Calibration
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 04
modNI             09:02:46.8271 TRACE 7: Loaded section Analog Input 04 - Calibration
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Input 05
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Input 05 - Calibration
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Input 06
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Input 06 - Calibration
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Input 07
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Input 07 - Calibration
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Output 00
modNI             09:02:46.8271 TRACE 8: Loaded section Analog Output 01
modNI             09:02:46.8271 TRACE 9: Declared AIControl
modNI             09:02:46.8271 TRACE 13: Loaded analogInput 0
modNI             09:02:46.8271 TRACE 14: Loaded analogInput 1
modNI             09:02:46.8271 TRACE 14: Loaded analogInput 2
modNI             09:02:46.8431 TRACE 19: Loaded analogInput 3
modNI             09:02:46.8431 TRACE 19: Done loading AIControl
uctrlDigitalInput 09:02:46.8431 TRACE Loading uctrlDigitalInput
uctrlDigitalInput 09:02:46.8761 TRACE Declaring daqmxTask
tskDigitalInput   09:02:46.9061 TRACE Loaded MyBase.New(tskDigitalInput)
tskDigitalInput   09:02:46.9061 TRACE Configuring tskDigitalInput

# Here is where the execution waits for 1300+ milliseconds
tskDigitalInput   09:02:46.9061 TRACE Configuring channels

tskDigitalInput   09:02:48.1831 TRACE Configured ch01
tskDigitalInput   09:02:48.1831 TRACE Configured ch02
tskDigitalInput   09:02:48.1831 TRACE Configured ch03
tskDigitalInput   09:02:48.1841 TRACE Configured ch04
tskDigitalInput   09:02:48.1841 TRACE Configured ch05
tskDigitalInput   09:02:48.1841 TRACE Configured ch06
tskDigitalInput   09:02:48.1841 TRACE Configured ch07
tskDigitalInput   09:02:48.1841 TRACE Configured ch08
tskDigitalInput   09:02:48.1841 TRACE Done configuring channels
tskDigitalInput   09:02:48.1841 TRACE Setting InvertLines
tskDigitalInput   09:02:48.1841 TRACE Done setting InvertLines
tskDigitalInput   09:02:48.1841 TRACE Done configuring tskDigitalInput
uctrlDigitalInput 09:02:48.1841 TRACE Done declaring daqmxTask
uctrlDigitalInput 09:02:48.1841 TRACE Declaring daqmxReader
uctrlDigitalInput 09:02:48.1841 TRACE Done declaring daqmxReader
uctrlDigitalInput 09:02:48.1841 TRACE Done loading uctrlDigitalInput
modNI             09:02:48.1841 TRACE 1364: Declared DIControl
modNI             09:02:48.1841 TRACE 1365: Loaded digitalInput 0
modNI             09:02:48.1841 TRACE 1365: Loaded digitalInput 1
modNI             09:02:48.1841 TRACE 1365: Loaded digitalInput 2
modNI             09:02:48.1841 TRACE 1365: Loaded digitalInput 3
modNI             09:02:48.1841 TRACE 1365: Loaded digitalInput 4
modNI             09:02:48.1841 TRACE 1366: Loaded digitalInput 5
modNI             09:02:48.1841 TRACE 1366: Loaded digitalInput 6
modNI             09:02:48.1841 TRACE 1366: Loaded digitalInput 7
modNI             09:02:48.1841 TRACE 1370: Declared DOControl
modNI             09:02:48.1841 TRACE 1370: Loaded digitalInput 0
modNI             09:02:48.1841 TRACE 1371: Loaded digitalInput 1
modNI             09:02:48.1841 TRACE 1371: Loaded digitalInput 2
modNI             09:02:48.1841 TRACE 1371: Loaded digitalInput 3
modNI             09:02:48.1841 TRACE 1371: Loaded digitalInput 4
modNI             09:02:48.1841 TRACE 1371: Loaded digitalInput 5
modNI             09:02:48.1841 TRACE 1374: Loaded digitalInput 6
modNI             09:02:48.1841 TRACE 1374: Loaded digitalInput 7
modNI             09:02:48.1841 TRACE 1374: Done with LoadNI
frmSplash         09:02:48.1841 TRACE Splash form event (6): IO configuration and calibration loaded

The initialization code is much the same as jveisz's code, but I can post it if that would help.

[jveisz]

kvermeer you are correct.  The first call to CreateChannel and WriteSingleSampleMultiline takes longer for me as well.  About 60ms for the first CreateChannel and another 80ms or so for the write.

I'm using an NI-9476 in a cDAQ9174 base.  However if you change your program to call CreateChannel about 600 times instead of just 8 you should see other instances where CreateChannel takes longer.

Maxwell,

The timing seems random to me.  It happens once in about every 500 calls.  How long should I wait before calling CreateChannel?  Not sure if that will help but I'm willing to give it a try.

[kvermeer]

Once in 500 tries?  Interesting. My code is structured to only make the call once, at startup, so I've only seen it as occurring the first time, every time.  I've been ignoring the issue for a while: It's by far the longest thing in the startup sequence, but we can tolerate it.  However, it would be great to be able to remove it.

I'll see if I can throw together a minimal example program that will do it.

[kvermeer]

Here's a small example program which reproduces the issue, which occurs on Line 50 of niDigitalInputs.vb.

[kvermeer]

Does anyone know how to fix this problem? Has anyone else observed it?

[Maxwell_Taylor]

Hey kvermeer,

I tried to run your example program that you’ve written but I’m not able to find where the data is logged to by this line

logger.Debug("DI Channel 1 CreateChannel time is {0}", sw.ElapsedMilliseconds)

Can you also tell me what hardware you are using to try and replicate this issue as close as I can?

[kvermeer]

Hi Taylor,

Thanks for looking into this.  

The logger.Debug lines are referencing a logging package called NLog, and NLog.config specifies that the output goes into %AppData%/NI Init Demo/logs/shortdate.log (or C:\Users\user\AppData\Roaming\Schap Specialty Machine\NI Init Demo\logs\shortdate.log on my machine).  You can also use a monitoring program like Log2Console on udp://127.0.0.1:9999.

I'm using a PCIe-6321 card, but I've seen it on other cards like the PCIe-6320s and PCI-6503.

--

Kevin Vermeer

[Maxwell_Taylor]

Hey kvermeer,

Thanks for sending that file path location, I would have never been able to find it on my own.  Unfortunately I'm not able to reproduce what you're seeing though.  The example program that you posted seems work pretty consistantly.  I'm wondering if this could just be do to the system you're running on.  I'm including the log file that was generated while running your example program.  I ran it about 20 times or so.