C# Confusing Results from Performance Test

Question

I am currently working on an image processing application. The application captures images from a webcam and then does some processing on it. The app needs to be real time responsive (ideally < 50ms to process each request). I have been doing some timing tests on the code I have and I found something very interesting (see below).

clearLog();
log("Log cleared");

camera.QueryFrame();
camera.QueryFrame();
log("Camera buffer cleared");

Sensor s = t.val;
log("Sx: " + S.X + " Sy: " + S.Y);

Image<Bgr, Byte> cameraImage = camera.QueryFrame();
log("Camera output acuired for processing");

Each time the log is called the time since the beginning of the processing is displayed. Here is my log output:

[3 ms]Log cleared
[41 ms]Camera buffer cleared
[41 ms]Sx: 589 Sy: 414
[112 ms]Camera output acuired for processing

The timings are computed using a StopWatch from System.Diagonostics. Timings shown above are cumulative. So Log Clear took 3ms. And "Camera Buffer cleared" took (41-3 = 38ms).

QUESTION 1

I find this slightly interesting, since when the same method is called twice it executes in ~40ms and when it is called once the next time it took longer (~70ms).

Assigning the value can't really be taking that long right?

QUESTION 2

Also the timing for each step recorded above varies from time to time. The values for some steps are sometimes as low as 0ms and sometimes as high as 100ms. Though most of the numbers seem to be relatively consistent.

I guess this may be because the CPU was used by some other process in the mean time? (If this is for some other reason, please let me know)

Is there some way to ensure that when this function runs, it gets the highest priority? So that the speed test results will be consistently low (in terms of time).

EDIT

I change the code to remove the two blank query frames from above, so the code is now:

clearLog();
log("Log cleared");

Sensor s = t.val;
log("Sx: " + S.X + " Sy: " + S.Y);

Image<Bgr, Byte> cameraImage = camera.QueryFrame();
log("Camera output acuired for processing");

The timing results are now:

[2 ms]Log cleared
[3 ms]Sx: 589 Sy: 414
[5 ms]Camera output acuired for processing

The next steps now take longer (sometimes, the next step jumps to after 20-30ms, while the next step was previously almost instantaneous). I am guessing this is due to the CPU scheduling. Is there someway I can ensure the CPU does not get scheduled to do something else while it is running through this code?

Answer 1

Without source, it's almost impossible to say "what's possible".

One thing that would make timing tricky is if stopwatch were in low-resolution mode; it may be worth it to write a few loops just to verify that you can indeed generate arbitrary measurements (i.e. any number of milliseconds without undue granularity).

Have you tried using a profiler? That may answer your question as to what else the process is doing at that time.

Answer 2

It might be that the camera does not really "acquire frame" when you ask it to, but does it all the time. Then when you ask it for image data and it is fresh enough, the data returns right away. But if you're unlucky and data is stale, then you get to wait for newer image acquisition. If camera does 25fps it could well mean 50ms delay (not only actual photon collection but the data transfer too).

Try to set the camera into lower resolution (so that framerate could get up), do the delays drop?

Answer 3

Too many unknowns. Without full source it is not possible to tell where time is spent. My guess would be the log method itself, if it is writing to the file. Other suspects garbage collector, camera drivers..