Time to set device properties is variable and sometimes takes very long

[Bruno]

Hi all,

Im commanding the scope with MicroManager through Matlab.

I give the scope a series of instructions to perform an experiment, and I
timed how much it takes to execute each instruction.
For example I track how much it takes to change a filter, or change from one
Group Config to another, or to project an image to the SLM.

There is an average time it takes to execute an operation, but sometimes it
takes much longer, like funny peaks in timing.
Did anyone of you have this, and do you know why could it be?

I have several devices and it seems to happen with most of them. So I
wouldnt say its device specific.

Thanks in advance!
Best
Bruno

<http://micro-manager.3463995.n2.nabble.com/file/t397139/for_mm_forums.png>



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[tron]

I'm sure not the best one to answer, but some things come to mind:

o Units of your graphs ?
o What kind of device does positioning ?
-different devices have (very?) different positioning time response
-many depend on how much they have to move
(in changing filters, that might be how much to rotate a cube)
-sometimes they need to check reference position ?
-sometimes just something happens and a correction takes place that
takes some time
-That's life with measurements ? :)
-Time from previous shot ? Some devices have some "prepare" time so you
can not take 2 shots back to back (or 100, or... i.e. max burst)
-Something else happening in your computer ?

I'm sure there are many others.

Bruno @ 09/05/2020 07:37 -0300 dixit:

> Hi all,
>
> Im commanding the scope with MicroManager through Matlab.
>
> I give the scope a series of instructions to perform an experiment, and I
> timed how much it takes to execute each instruction.
> For example I track how much it takes to change a filter, or change from one
> Group Config to another, or to project an image to the SLM.
>
> There is an average time it takes to execute an operation, but sometimes it
> takes much longer, like funny peaks in timing.
> Did anyone of you have this, and do you know why could it be?
>
> I have several devices and it seems to happen with most of them. So I
> wouldnt say its device specific.
>
> Thanks in advance!
> Best
> Bruno
>
> <http://micro-manager.3463995.n2.nabble.com/file/t397139/for_mm_forums.png>
>
>
>
> --
> Sent from: http://micro-manager.3463995.n2.nabble.com/
>
>
> _______________________________________________
> micro-manager-general mailing list
> [hidden email]
> https://lists.sourceforge.net/lists/listinfo/micro-manager-general
> --

Carlos G Mendioroz  <[hidden email]>


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[dmahecic]

Hi Bruno,


Bruno wrote
> There is an average time it takes to execute an operation, but sometimes
> it
> takes much longer, like funny peaks in timing.
> Did anyone of you have this, and do you know why could it be?

Since this sounds like software-based triggering, I would expect it depends
on how busy your PC is - things like CPU, memory and disk usage. I notice
that if I'm running a lot of processes simultaneously, then the timing can
be longer and more variable.

Best,
Dora




--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[Nico Stuurman-2]

Hi Bruno,

Would be fun if you could share some more details (for instance, exactly
what equipment, code you used for testing, your timing results, etc..). 
Also, the logs (Corelog.txt, first switch on debug logging) can you give
you some ideas what the code is waiting for.

One possibility is that the Java garbage collector kicks in and blocks
program execution for a bit, causing the delay.
Pavak Shah on this mailing list reported some success running
Micro-Manager with the Concurrent Mark Sweep garbage collector rather
than the parallel GC.  To experiment with this, you would need to figure
out how to start Matlab/MM using this other garbage collector.  All only
useful if these delays are important to you and if you have evidence
that indeed the garbage collector is involved.

Best,

Nico


On 5/9/2020 3:37 AM, Bruno wrote:

> Hi all,
>
> Im commanding the scope with MicroManager through Matlab.
>
> I give the scope a series of instructions to perform an experiment, and I
> timed how much it takes to execute each instruction.
> For example I track how much it takes to change a filter, or change from one
> Group Config to another, or to project an image to the SLM.
>
> There is an average time it takes to execute an operation, but sometimes it
> takes much longer, like funny peaks in timing.
> Did anyone of you have this, and do you know why could it be?
>
> I have several devices and it seems to happen with most of them. So I
> wouldnt say its device specific.
>
> Thanks in advance!
> Best
> Bruno
>
> <https://urldefense.proofpoint.com/v2/url?u=http-3A__micro-2Dmanager.3463995.n2.nabble.com_file_t397139_for-5Fmm-5Fforums.png&d=DwICAg&c=iORugZls2LlYyCAZRB3XLg&r=UwP8SWqih8VHO1LwZpgcx83I4o21yLj6V6QD-25Dt4I&m=hylxryf_TkTP27_DVPHC3yGOjraUMmJkdInF0NR47X4&s=U7_xHfJZbspLwp7aCheE27T9I29ZHXy2AZENlOp7iwo&e= >
>
>
>
> --
> Sent from: https://urldefense.proofpoint.com/v2/url?u=http-3A__micro-2Dmanager.3463995.n2.nabble.com_&d=DwICAg&c=iORugZls2LlYyCAZRB3XLg&r=UwP8SWqih8VHO1LwZpgcx83I4o21yLj6V6QD-25Dt4I&m=hylxryf_TkTP27_DVPHC3yGOjraUMmJkdInF0NR47X4&s=-Zi6lNwuXmTQnjk739FnMVnIwGXKIgvACc6E6dsc0Yo&e=
>
>
> _______________________________________________
> micro-manager-general mailing list
> [hidden email]
> https://urldefense.proofpoint.com/v2/url?u=https-3A__lists.sourceforge.net_lists_listinfo_micro-2Dmanager-2Dgeneral&d=DwICAg&c=iORugZls2LlYyCAZRB3XLg&r=UwP8SWqih8VHO1LwZpgcx83I4o21yLj6V6QD-25Dt4I&m=hylxryf_TkTP27_DVPHC3yGOjraUMmJkdInF0NR47X4&s=i5ta4Qmn-QJxpKDq6P4ICFBosvUYZbIkd2gTgEG-yUE&e=
> .

_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[Bruno]

Hi Nico and Tron,
Thanks a lot for your quick reply.
I will try to gather the data you asked for and send it here.

But I would like to ask Nico: how would I check if the garbage collector is
involved?
Also, could it be a problem of serial ports and serial/usb converters?

Thanks a lot,
Best
Bruno



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[nanthony]

Hi Bruno,

You can use something like VisualVM to monitor garbage collector activity. Your best bet though is probably to start with the CoreLog log files. These should allow you to see if the delays you're seeing are just from one slow device or if something more complicated is happening.

--Nick

On May 10, 2020 3:00 AM, Bruno <[hidden email]> wrote:

Hi Nico and Tron,
Thanks a lot for your quick reply.
I will try to gather the data you asked for and send it here.

But I would like to ask Nico: how would I check if the garbage collector is
involved?
Also, could it be a problem of serial ports and serial/usb converters?

Thanks a lot,
Best
Bruno



--
Sent from: https://urldefense.com/v3/__http://micro-manager.3463995.n2.nabble.com/__;!!Dq0X2DkFhyF93HkjWTBQKhk!G6apoOyQwPDRLKNWiTEQjcbzFXJWSPwExRiVH-1vwiUU8ZHAPm3-TIMYVQjV5igephgwxUDQT3MS$


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://urldefense.com/v3/__https://lists.sourceforge.net/lists/listinfo/micro-manager-general__;!!Dq0X2DkFhyF93HkjWTBQKhk!G6apoOyQwPDRLKNWiTEQjcbzFXJWSPwExRiVH-1vwiUU8ZHAPm3-TIMYVQjV5igephgwxW6Vkyvh$

_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[PAVAK SHAH-4]

Hi Bruno,

Garbage collection may be a culprit but so can general system timing jitter from the OS scheduler and serial/USB I/O overhead, which cannot really be avoided. If deterministic timing is a need and your hardware can accept TTL control, consider using something like the Triggerscope, an NI DAQ, or an Arduino to provide hardware timed triggers. I haven't yet dug into the MATLAB JVM garbage collector and how to change it, but quick googling suggests that it may not be straightforward and I suspect it won't necessarily fix your problem.

Best,

Pavak

On Sun, May 10, 2020, 8:13 AM Nicholas Michael Anthony <[hidden email]> wrote:

Hi Bruno,

You can use something like VisualVM to monitor garbage collector activity. Your best bet though is probably to start with the CoreLog log files. These should allow you to see if the delays you're seeing are just from one slow device or if something more complicated is happening.

--Nick

On May 10, 2020 3:00 AM, Bruno <[hidden email]> wrote:

Hi Nico and Tron,
Thanks a lot for your quick reply.
I will try to gather the data you asked for and send it here.

But I would like to ask Nico: how would I check if the garbage collector is
involved?
Also, could it be a problem of serial ports and serial/usb converters?

Thanks a lot,
Best
Bruno



--
Sent from: https://urldefense.com/v3/__http://micro-manager.3463995.n2.nabble.com/__;!!Dq0X2DkFhyF93HkjWTBQKhk!G6apoOyQwPDRLKNWiTEQjcbzFXJWSPwExRiVH-1vwiUU8ZHAPm3-TIMYVQjV5igephgwxUDQT3MS$


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://urldefense.com/v3/__https://lists.sourceforge.net/lists/listinfo/micro-manager-general__;!!Dq0X2DkFhyF93HkjWTBQKhk!G6apoOyQwPDRLKNWiTEQjcbzFXJWSPwExRiVH-1vwiUU8ZHAPm3-TIMYVQjV5igephgwxW6Vkyvh$

_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[Bruno]

Dear all,

Thanks a lot for all your replies.

I have narrowed down the problem to a single device which is Mosaic3 from
Andor.

I made a timing test, to see how long it takes to do mc.setSLMImage and I
obtain the graph attached, the y axis is in seconds. (you can find the
timing code below)
The peak in timing rarely occurs if I only time mc.displaySLMImage, so its
the setSLMImage
The average timing is around 130 ms, and the peaks add an extra 500 ms.

I am already calling this function as little as possible in my experiment,
so would not be an option to shorten the amount of calls. Also the reason
why this is bothering is that it limits the amount of positions I can do at
each frame interval.  For example, 30 pos in 1 min, but if peaks would be
eliminated I could do more positions.

Did you experience this with other devices or if you have this device did
you oberve it solve it?
Do you know why could this be?

Thanks a lot in advance!
Best
Bruno

-----------------

clear sleepTime
for i=1:500;

c0 = clock;
mosaic = 'Mosaic3';
allon = uint8(ones(800*600,1)*250);
mc.setSLMImage(mosaic,allon)
mc.displaySLMImage(mosaic)
mc.waitForSystem
pause(0.1)
sleepTime(i) = etime(clock,c0);

end

<http://micro-manager.3463995.n2.nabble.com/file/t397139/for_mm_forum2.png> 



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[e-mail]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[PAVAK SHAH-4]

Hi Bruno,

Sounds like the issue is transferring the image to the SLM, which isn't terribly surprising. Have you done the test of swapping it with a device on one of the system's main USB ports from the hub to see if that helps? Is the Mosaic a USB 3 device? Are you using a USB 3 hub? Even if it's a USB 2 device, using a USB 3 hub on a USB 3 port may help by providing more bandwidth to all of the peripherals sharing that hub. The best test will be to see if there are similar spikes when the Mosaic is plugged into a fast port on the PC directly.

Best,

Pavak

On Mon, May 11, 2020, 8:01 AM Bruno <[hidden email]> wrote:

Dear all,

Thanks a lot for all your replies.

I have narrowed down the problem to a single device which is Mosaic3 from
Andor.

I made a timing test, to see how long it takes to do mc.setSLMImage and I
obtain the graph attached, the y axis is in seconds. (you can find the
timing code below)
The peak in timing rarely occurs if I only time mc.displaySLMImage, so its
the setSLMImage
The average timing is around 130 ms, and the peaks add an extra 500 ms.
Mosaic is connected via USB, in a USB hub because I run out of USB ports.

I am already calling this function as little as possible in my experiment,
so would not be an option to shorten the amount of calls. Also the reason
why this is bothering is that it limits the amount of positions I can do at
each frame interval.  For example, 30 pos in 1 min, but if peaks would be
eliminated I could do more positions.

Did you experience this with other devices or if you have this device did
you oberve it solve it?
Do you know why could this be?

Thanks a lot in advance!
Best
Bruno

-----------------

clear sleepTime
for i=1:500;

c0 = clock;
mosaic = 'Mosaic3';
allon = uint8(ones(800*600,1)*250);
mc.setSLMImage(mosaic,allon)
mc.displaySLMImage(mosaic)
mc.waitForSystem
pause(0.1)
sleepTime(i) = etime(clock,c0);

end

<http://micro-manager.3463995.n2.nabble.com/file/t397139/for_mm_forum2.png>



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[Bruno]

Dear all thanks for your valuable input,

I have now looked at the corelog. I have identified that the majority of
these timing peaks come from unsolicited communication with the Cooled
pE4000. I paste below the part of the corelog where hte scope takes around
500 ms giving this peak in timing.

It seems like the scope randomly decides to communicate with the pE4000
about its four Lamps (A,B,C,D, with colors 435 500, 580, and 635).
Do you know what are this commands and why do they appear?

Thanks a lot!

The code im  running for timing is:

for i=1:500
c0 = clock;
mosaic = 'Mosaic3';
allon = uint8(ones(800*600,1)*250);
mc.setSLMImage(mosaic,allon)
mc.displaySLMImage(mosaic)
mc.waitForDevice('Mosaic3')
pause(0.050)
sleepTime(i) = etime(clock,c0);
end
---------------------------

2020-05-12T12:23:34.883348 tid13040 [dbg,dev:COM15] SetCommand -> CSS?\r
2020-05-12T12:23:34.889348 tid13040 [dbg,dev:COM15] GetAnswer <-
CSSAXF025BXF050CSF001DXF050\r\n
2020-05-12T12:23:34.889348 tid13040 [dbg,dev:COM15] SetCommand -> LAMS\r
2020-05-12T12:23:34.894348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:A:435\r\n
2020-05-12T12:23:34.894348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:B:500\r\n
2020-05-12T12:23:34.894348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:C:580\r\n
2020-05-12T12:23:34.894348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:D:635\r\n
2020-05-12T12:23:34.991348 tid7492 [dbg,dev:COM13] Write -> (hex) 28
2020-05-12T12:23:34.994348 tid13040 [dbg,dev:COM15] SetCommand -> CSS?\r
2020-05-12T12:23:34.995348 tid7492 [dbg,dev:COM13] Read <- (hex) 28 3f
2020-05-12T12:23:34.999348 tid13040 [dbg,dev:COM15] GetAnswer <-
CSSAXF025BXF050CSF001DXF050\r\n
2020-05-12T12:23:34.999348 tid13040 [dbg,dev:COM15] SetCommand -> LAMS\r
2020-05-12T12:23:35.004348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:A:435\r\n
2020-05-12T12:23:35.004348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:B:500\r\n
2020-05-12T12:23:35.004348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:C:580\r\n
2020-05-12T12:23:35.004348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:D:635\r\n
2020-05-12T12:23:35.104348 tid13040 [dbg,dev:COM15] SetCommand -> CSS?\r
2020-05-12T12:23:35.109348 tid13040 [dbg,dev:COM15] GetAnswer <-
CSSAXF025BXF050CSF001DXF050\r\n
2020-05-12T12:23:35.109348 tid13040 [dbg,dev:COM15] SetCommand -> LAMS\r
2020-05-12T12:23:35.114348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:A:435\r\n
2020-05-12T12:23:35.114348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:B:500\r\n
2020-05-12T12:23:35.114348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:C:580\r\n
2020-05-12T12:23:35.114348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:D:635\r\n
2020-05-12T12:23:35.214348 tid13040 [dbg,dev:COM15] SetCommand -> CSS?\r
2020-05-12T12:23:35.219348 tid13040 [dbg,dev:COM15] GetAnswer <-
CSSAXF025BXF050CSF001DXF050\r\n
2020-05-12T12:23:35.219348 tid13040 [dbg,dev:COM15] SetCommand -> LAMS\r
2020-05-12T12:23:35.225348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:A:435\r\n
2020-05-12T12:23:35.225348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:B:500\r\n
2020-05-12T12:23:35.225348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:C:580\r\n
2020-05-12T12:23:35.225348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:D:635\r\n
2020-05-12T12:23:35.325348 tid13040 [dbg,dev:COM15] SetCommand -> CSS?\r
2020-05-12T12:23:35.330348 tid13040 [dbg,dev:COM15] GetAnswer <-
CSSAXF025BXF050CSF001DXF050\r\n
2020-05-12T12:23:35.330348 tid13040 [dbg,dev:COM15] SetCommand -> LAMS\r
2020-05-12T12:23:35.334348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:A:435\r\n
2020-05-12T12:23:35.334348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:B:500\r\n
2020-05-12T12:23:35.334348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:C:580\r\n
2020-05-12T12:23:35.334348 tid13040 [dbg,dev:COM15] GetAnswer <-
LAM:D:635\r\n



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[JB Lugagne]

Hi Bruno,

did you try using the loadSLMsequence() and related functions? I find that
it is faster and more reliable than the setSLMImage() function, even with
only one frame per sequence.

You can find some of my code using it here:
http://micro-manager.3463995.n2.nabble.com/LoadSLMSequence-and-the-Matlab-API-td7591004.html
<http://micro-manager.3463995.n2.nabble.com/LoadSLMSequence-and-the-Matlab-API-td7591004.html>  
Although I use a different SLM.



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general

[Bruno]

Dear JB,

I hadnt tried with load sequence and actually you code has been really
helpful!
I agree its more reliable, it takes around 30 ms less, although I still get
this peaks in timing when I do loadSLMsequence.
From the corelog i have identified that the following lines are taking the
500 ms time:

2020-05-14T15:54:36.363345 tid8976 [dbg,dev:Mosaic3] Sending command
ClearSequenceMemory...
2020-05-14T15:54:36.865345 tid8976 [dbg,dev:Mosaic3] ... ClearSequenceMemory
finished.

As you can see it takes around 500 ms, and it seems to happen randomly.
Like it gets stuck in clearing the sequence memory.
Why is this and why would it be kind of random?

Thanks in advance,
Best
Bruno



--
Sent from: http://micro-manager.3463995.n2.nabble.com/


_______________________________________________
micro-manager-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/micro-manager-general