epics-modules / Dante

EPICS module for support of Dante digital pulse processors
1 stars 4 forks source link

Mapping mode with external trigger has worse performance than free running #25

Open MarkRivers opened 3 years ago

MarkRivers commented 3 years ago

I have modified the test_mapping program so that it prints the elapsed time since start_map was called on each output message. This allows evaluating the performance.

I used this command to collect data in FreeRunning mode with 4096 channel spectra, 10 ms acquisition time, 2000 mapping points. This is exactly 800 spectra/s.

test_mapping 164.54.160.186 4096 10 100 2000 0

The expected time for this acquisition to complete is 2000 * 0.010 seconds = 20.0 seconds.

This is the end of the output.

20.1491 Acquisition complete on board 0
20.1492 getAvailableData on board 0 numAvailable=9
20.1492 Acquisition complete on board 1
20.1492 getAvailableData on board 1 numAvailable=9
20.1492 Acquisition complete on board 2
20.1492 getAvailableData on board 2 numAvailable=9
20.1492 Acquisition complete on board 3
20.1492 getAvailableData on board 3 numAvailable=9
20.1492 Acquisition complete on board 4
20.1492 getAvailableData on board 4 numAvailable=9
20.1492 Acquisition complete on board 5
20.1492 getAvailableData on board 5 numAvailable=9
20.1492 Acquisition complete on board 6
20.1492 getAvailableData on board 6 numAvailable=9
20.1492 Acquisition complete on board 7
20.1492 getAvailableData on board 7 numAvailable=9
20.1493 Minimum number of spectra available=9
20.1493 getAllData board=0, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1494 getAllData board=1, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1495 getAllData board=2, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1495 getAllData board=3, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1497 getAllData board=4, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1497 getAllData board=5, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1498 getAllData board=6, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1499 getAllData board=7, read 9 spectra OK, pSpectraId[0]=1991, currentPixel=2000
20.1499 getAvailableData on board 0 numAvailable=0
20.1499 getAvailableData on board 1 numAvailable=0
20.1499 getAvailableData on board 2 numAvailable=0
20.1499 getAvailableData on board 3 numAvailable=0
20.1499 getAvailableData on board 4 numAvailable=0
20.1499 getAvailableData on board 5 numAvailable=0
20.1499 getAvailableData on board 6 numAvailable=0
20.1499 getAvailableData on board 7 numAvailable=0
20.1499 Spectra collected on each board
  Board 0, number collected=2000
  Board 1, number collected=2000
  Board 2, number collected=2000
  Board 3, number collected=2000
  Board 4, number collected=2000
  Board 5, number collected=2000
  Board 6, number collected=2000
  Board 7, number collected=2000
Dante::Dante calling CloseLibrary()
Dante::Dante called CloseLibrary successfully

It worked exactly as expected. All boards completed acquisition at the same time, and the total acquisition took 20.15 seconds, very close to the expected time.

This is the same test, except with TriggerRising rather than FreeRun. I used an external trigger with a frequency of 100 Hz, e.g. 10.0 ms period. The pulse generator was started some time after the call to start_map. The first time there was a non-zero number of available spectra allows estimating this time delay as 1.01 seconds.

test_mapping 164.54.160.186 4096 10 100 2000 1
...
 1.0154 getAvailableData on board 0 numAvailable=4
...
21.3468 Acquisition complete on board 0
...
21.8477 Acquisition complete on board 1
...
22.1482 Acquisition complete on board 2
...
26.0559 Acquisition complete on board 3
...
31.1747 Acquisition complete on board 4
...
36.5135 Acquisition complete on board 5
...
42.3969 Acquisition complete on board 6
...
42.6017 Acquisition complete on board 7
...

42.6018 Minimum number of spectra available=8
42.6018 getAllData board=0, read 8 spectra OK, pSpectraId[0]=5858, currentPixel=1999
42.6019 getAllData board=1, read 8 spectra OK, pSpectraId[0]=5856, currentPixel=1999
42.6020 getAllData board=2, read 8 spectra OK, pSpectraId[0]=5856, currentPixel=1999
42.6021 getAllData board=3, read 8 spectra OK, pSpectraId[0]=5856, currentPixel=1999
42.6021 getAllData board=4, read 8 spectra OK, pSpectraId[0]=5856, currentPixel=1999
42.6022 getAllData board=5, read 8 spectra OK, pSpectraId[0]=5858, currentPixel=1999
42.6023 getAllData board=6, read 8 spectra OK, pSpectraId[0]=5858, currentPixel=1999
42.6024 getAllData board=7, read 8 spectra OK, pSpectraId[0]=5859, currentPixel=1999
42.6024 getAvailableData on board 0 numAvailable=0
42.6024 getAvailableData on board 1 numAvailable=2
42.6024 getAvailableData on board 2 numAvailable=2
42.6024 getAvailableData on board 3 numAvailable=2
42.6024 getAvailableData on board 4 numAvailable=2
42.6024 getAvailableData on board 5 numAvailable=1
42.6025 getAvailableData on board 6 numAvailable=1
42.6025 getAvailableData on board 7 numAvailable=1
42.6025 Spectra collected on each board
  Board 0, number collected=1999
  Board 1, number collected=2001
  Board 2, number collected=2001
  Board 3, number collected=2001
  Board 4, number collected=2001
  Board 5, number collected=2000
  Board 6, number collected=2000
  Board 7, number collected=2000
Dante::Dante calling CloseLibrary()
Dante::Dante called CloseLibrary successfully

A number of things are wrong:

I have not seen any documentation that suggests that the performance with triggered mode should be worse than with free running mode.

Today's APS presentation said 4096 channels can run at 800 spectra/s total from a Dante8, which is what these tests are doing. That mapping rate works fine in free-running mode, but not in triggered mode.

MarkRivers commented 3 years ago

I measured the total time to collect 2000 mapping points with TriggerRising mode as a function of the external trigger frequency. These were all done with 4096 channel spectra and 8 boards.

Trigger frequency (Hz) Expected time (s) Actual time (s)
100 20 41.5
80 25 43.0
60 33.3 43.0
50 40.0 55.5
40 50 57.3
30 66.7 71.6
25 80 84.0
20 100 100.0

It can be seen that only when the frequency is 20 Hz or less (50 ms period) does the acquisition time match the expected execution time. At that rate the boards all complete acquisition at the same time, and they all return the spectra at about the same rate. At any higher rate the board 7 completes acquisition significantly later than board 0.

lucagrittiniXGLAB commented 3 years ago

Hi Mark Theoretically the performance of the gated or trigger acquisition modes in maps should be 50% of the corrisponding free-running, I will update it on the manual since it is missing. It means that if with a DANTE-8CH you can collect maps in real-time with 10ms spectrums, in trigger or gating mode you can collect max. 20ms spectrums (50Hz trigger) to keep the real-time. But this just theoretically, because with 50Hz trigger the throughput should be about 60Mbit/s and the processor must be strong enough to support this throughput. I tested the map in TriggerRising mode, 4096bins, 10000 spectra and 50Hz AUX signal (15ms up, 5ms down duty doesn't care) and it is real-time, the acquisition has a duration of 200s. I attach saved files of the acquisitions.

maps_gated.zip

MarkRivers commented 3 years ago

I just tried to reproduce this with the test_mapping.cpp program. 50 Hz AUX signal, 15 ms high, 5 ms low. I only collected 2000 mapping points rather than 1000.

test_mapping 164.54.160.186 4096 100 10 2000 1
...
 4.9707 getAvailableData on board 0 numAvailable=1
 4.9707 getAvailableData on board 1 numAvailable=1
 4.9707 getAvailableData on board 2 numAvailable=1
 4.9707 getAvailableData on board 3 numAvailable=1
 4.9707 getAvailableData on board 4 numAvailable=1
 4.9707 getAvailableData on board 5 numAvailable=1
 4.9707 getAvailableData on board 6 numAvailable=1
 4.9707 getAvailableData on board 7 numAvailable=0
 4.9808 getAvailableData on board 0 numAvailable=1
 4.9808 getAvailableData on board 1 numAvailable=1
 4.9808 getAvailableData on board 2 numAvailable=1
 4.9809 getAvailableData on board 3 numAvailable=1
 4.9809 getAvailableData on board 4 numAvailable=1
 4.9809 getAvailableData on board 5 numAvailable=1
 4.9809 getAvailableData on board 6 numAvailable=1
 4.9809 getAvailableData on board 7 numAvailable=1
 4.9809 Minimum number of spectra available=1
 4.9809 getAllData board=0, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9809 getAllData board=1, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9809 getAllData board=2, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9809 getAllData board=3, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9809 getAllData board=4, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9810 getAllData board=5, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9810 getAllData board=6, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
 4.9810 getAllData board=7, read 1 spectra OK, pSpectraId[0]=49, currentPixel=1
...
44.9395 Acquisition complete on board 0
44.9395 getAvailableData on board 0 numAvailable=1
44.9395 getAvailableData on board 1 numAvailable=0
44.9395 getAvailableData on board 2 numAvailable=0
44.9395 getAvailableData on board 3 numAvailable=0
44.9395 getAvailableData on board 4 numAvailable=0
44.9395 getAvailableData on board 5 numAvailable=0
44.9395 getAvailableData on board 6 numAvailable=0
44.9395 getAvailableData on board 7 numAvailable=0
44.9497 Acquisition complete on board 0
44.9497 getAvailableData on board 0 numAvailable=1
44.9497 Acquisition complete on board 1
44.9497 getAvailableData on board 1 numAvailable=2
44.9497 Acquisition complete on board 2
44.9497 getAvailableData on board 2 numAvailable=2
44.9497 Acquisition complete on board 3
44.9497 getAvailableData on board 3 numAvailable=2
44.9497 Acquisition complete on board 4
44.9497 getAvailableData on board 4 numAvailable=2
44.9497 getAvailableData on board 5 numAvailable=1
44.9497 getAvailableData on board 6 numAvailable=1
44.9497 getAvailableData on board 7 numAvailable=0
44.9598 Acquisition complete on board 0
44.9598 getAvailableData on board 0 numAvailable=1
44.9598 Acquisition complete on board 1
44.9598 getAvailableData on board 1 numAvailable=2
44.9598 Acquisition complete on board 2
44.9598 getAvailableData on board 2 numAvailable=2
44.9598 Acquisition complete on board 3
44.9598 getAvailableData on board 3 numAvailable=2
44.9598 Acquisition complete on board 4
44.9598 getAvailableData on board 4 numAvailable=2
44.9598 Acquisition complete on board 5
44.9598 getAvailableData on board 5 numAvailable=2
44.9599 Acquisition complete on board 6
44.9599 getAvailableData on board 6 numAvailable=2
44.9599 Acquisition complete on board 7
44.9599 getAvailableData on board 7 numAvailable=2
44.9599 Minimum number of spectra available=1
44.9599 getAllData board=0, read 1 spectra OK, pSpectraId[0]=4048, currentPixel=2000
44.9599 getAllData board=1, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAllData board=2, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAllData board=3, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAllData board=4, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAllData board=5, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAllData board=6, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAllData board=7, read 1 spectra OK, pSpectraId[0]=4047, currentPixel=2000
44.9599 getAvailableData on board 0 numAvailable=0
44.9599 getAvailableData on board 1 numAvailable=1
44.9599 getAvailableData on board 2 numAvailable=1
44.9600 getAvailableData on board 3 numAvailable=1
44.9600 getAvailableData on board 4 numAvailable=1
44.9600 getAvailableData on board 5 numAvailable=1
44.9600 getAvailableData on board 6 numAvailable=1
44.9600 getAvailableData on board 7 numAvailable=1
44.9600 Spectra collected on each board
  Board 0, number collected=2000
  Board 1, number collected=2001
  Board 2, number collected=2001
  Board 3, number collected=2001
  Board 4, number collected=2001
  Board 5, number collected=2001
  Board 6, number collected=2001
  Board 7, number collected=2001
Dante::Dante calling CloseLibrary()
Dante::Dante called CloseLibrary successfully

It worked, all channels got done at almost exactly the same time. The total acquisition time from when I started the pulse generator (at about 4.9 seconds after starting acquisition) was almost exactly 40 seconds, as expected. The only problem is that board 0 collected 2000 spectra, boards 1-7 collected 2001.

This is a very different result than I got on April 27, when it took 55.5 seconds to complete with a 50 Hz trigger. The only difference is that I have power-cycled the Dante8 in between. I have not changed the software or the arguments I used with test_mapping. It seems clear that previously the Dante8 was in some bad state which a power-cycle fixed.

MarkRivers commented 3 years ago

I did a test with 10000 mapping points and 70 Hz trigger. It took less than 1 second longer than the theoretical time of 142.9 seconds. Acquisition completed on board 0 at 144.16, and on board 7 at 144,65,

...
144.1616 Acquisition complete on board 0
144.1617 getAvailableData on board 0 numAvailable=134
144.1617 getAvailableData on board 1 numAvailable=133
144.1617 getAvailableData on board 2 numAvailable=130
144.1617 getAvailableData on board 3 numAvailable=123
144.1617 getAvailableData on board 4 numAvailable=123
144.1618 getAvailableData on board 5 numAvailable=82
,,,
144.6478 getAvailableData on board 6 numAvailable=3
144.6479 Acquisition complete on board 7
144.6479 getAvailableData on board 7 numAvailable=3
144.6479 Minimum number of spectra available=2
144.6479 getAllData board=0, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6479 getAllData board=1, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6480 getAllData board=2, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6480 getAllData board=3, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6480 getAllData board=4, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6480 getAllData board=5, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6481 getAllData board=6, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6481 getAllData board=7, read 2 spectra OK, pSpectraId[0]=20008, currentPixel=10000
144.6481 getAvailableData on board 0 numAvailable=0
144.6481 getAvailableData on board 1 numAvailable=1
144.6481 getAvailableData on board 2 numAvailable=1
144.6481 getAvailableData on board 3 numAvailable=1
144.6481 getAvailableData on board 4 numAvailable=1
144.6482 getAvailableData on board 5 numAvailable=1
144.6482 getAvailableData on board 6 numAvailable=1
144.6482 getAvailableData on board 7 numAvailable=1
144.6482 Spectra collected on each board
  Board 0, number collected=10000
  Board 1, number collected=10001
  Board 2, number collected=10001
  Board 3, number collected=10001
  Board 4, number collected=10001
  Board 5, number collected=10001
  Board 6, number collected=10001
  Board 7, number collected=10001
Dante::Dante calling CloseLibrary()
Dante::Dante called CloseLibrary successfully