====== Spectrum Timing ======

While doing FPGA development, David and Ed found that the digitizer could not keep up with 130k sample depth at 5kHz trigger rate.

===== Step by Step =====

Instructions to run the test step by step

  - Make a temporary directory in your home to compile and run the code <code>
# make a temp directory
mkdir ~/tmp
# make a spectrum directory
mkdir ~/tmp/spectrum-support
</code>
  - Enter the directory and uncompress the sample programs (you will have directories created: **xmcRead** and **xmcTest** ) <code>
cd ~/tmp/spectrum-support
tar xvf ~/Download/spectrum-support.tar
</code>

Parameters we are interested in **~/tmp/spectrum-support/xmcTest/xmc1151.h**

^  Parameters ^ Desired Value ^ Max Value ^ Description ^
| COLLECTSIZE |    131072     |  ~ 25600  | Number of samples to digitize per trigger. |

  * **Max Value** is as high as we could reliably get this value before it started missing triggers.
  * **Clock Rate** is 1 GHz, so 130k is 131 microsecond of flight time for the laser.
  * **Repetition Rate** is 5kHz, so only 200 microseconds between triggers, leaving ~ 70 microsecond for FPGA / software to complete each cycle.  (the cycle being: once collected, DMA data to user space program and reset for next trigger)

  - Compile the **xmcRead** program <code>
cd ~/tmp/spectrum-support/xmcRead
make
</code>
  - Go to the collection program directory, compile and run
    - Enter the directory <code>
cd ~/tmp/spectrum-support/xmcTest/
</code>
    - Compile the program <code>
make
</code>
    - Run the program and let it go for about 10 files.  Press ENTER/RETURN to cleanly stop collection<code>
sudo ./xmcTest
</code>
  - Display the results 
    - Display all the meta data <code>
~/tmp/spectrum-support/xmcRead/xmcRead -v -m -i lvisF_00000004.dat
</code>
    - Display just the trigger counter.  Ed has a counter that sees the triggers.  This trigger count is how we see shots that are missed <code>
~/tmp/spectrum-support/xmcRead/xmcRead -v -m -i lvisF_00000004.dat | grep trigger
</code>
    - Notice you are seeing the same count twice, that is because this is dual channel collection.  Using **awk** we can ignore every other line <code>
../xmcRead/xmcRead -v -m -i lvisF_00000004.dat | grep trigger | awk 'NR%2==0'
</code>
    - the **event** values in the meta data is the "tick" counter that Ed added.  So we can verify that we are operating at the correct frequency, and that indeed we are skipping a trigger (because the tick counter is twice what it ought to be) <code>
../xmcRead/xmcRead -v -m -i lvisF_00000004.dat | grep  'event Start Dig'| awk 'NR%2==0'
</code>

===== Testing Results =====

Remove the clutter around the values, so we can plot some data

  - Extract the time <code>
../xmcRead/xmcRead -v -m -i lvisF_00000004.dat | grep  'event Start Dig'| awk 'NR%2==0' > time.txt
</code>
  - Remove everything except the brackets, and then remove the brackets for time: <code>
../xmcRead/xmcRead -v -m -i lvisF_00000004.dat              \
    | grep  'event Start Dig'| awk 'NR%2==0'                \
    | sed -e 's/^[^\[]*//;s/\][^\[]*\[/\] \[/g;s/[^]]*$//;' \
    | tr -d '[]' > time.txt
</code>
  - Remove everything except the brackets, and then remove the brackets for trigger count: <code>
../xmcRead/xmcRead -v -m -i lvisF_00000004.dat              \
    | grep  'trigger'| awk 'NR%2==0'                        \
    | sed -e 's/^[^\[]*//;s/\][^\[]*\[/\] \[/g;s/[^]]*$//;' \
    | tr -d '[]' > trigger.txt
</code>

===== Observations =====

  * Counter rate is 250MHz (clock / 4) so each sample is (1/250000000) or 4 nanoseconds. 4e-09 s)

==== Digitizer Time ====

Ed has recorded "event Start Dig" and "event End Dig".  How does that behave with samples to record?

  * Looks like Digi End - Digi Start is about 16,500 counts or 16500 * 4e-09 = 66 microseconds at 130k
  * If I change **COLLECT_SIZE** to 65536, this difference is halved... so 8,250 or 33 microseconds (note you have to re-compile the test program AND the reader (both **xmcRead** and **xmcTest**, just enter directory, make clean, make))
  * Try 32768, and we get 4,150 counts or 16.6 micro seconds, yep, roughly linear time decrease.

  * 130k samples ~= 20km of laser round trip travel time (about 60,000 feet)
  * 65k samples ~= 10km of laser round trip travel time (about 30,000 feet)

==== Repetition Rate Check ====

Using that same 4 ns internal clock (one quarter the input clock, or 250 MHz for our 1 GHz input).  Checking trigger time.
  * Set the **COLLECT_SIZE** to 8192
  * Recompile both (make clean ; make)
  * At 8192 samples, 1089 clock ticks, or about 4.36 microseconds (nice and fast, is DMA transfer in this?)
  * Shot to shot time difference at 5khz:  50,000 counts * 4ns = 0.0002 or exactly 200 microsecond period.  Nice!

==== Thoughts ====

  * Could it just be transfer speed?  We are DMA'ing all of the data down to the PC.  We actually only need the pulse data, which is (128+128+1024 samples x 2channels (2560 bytes of samples and 256 meta for 2816 bytes total).  If the data were all in one nice block (TX window, FR window, and RX window to DMA down, it should be quite fast at PCIexpress x8 bus speed.  Two short DMAs of 1408 bytes each).


==== Sample Output ====

Here is 5khz example:


<code>
~/tmp/spectrum-support/xmcRead/xmcRead -v -m -i lvisF_00000002.dat

*** counter           [00994]
*** trigger           [13219]
*** window A start    [00000]
*** window A  stop    [00125]
*** window B start    [00137]
*** window B  stop    [00250]
*** window C start    [00262]
*** window C  stop    [00375]
*** window D start    [00450]
*** window D  stop    [00537]
*** thresh Win3 Value [00600]
*** thresh Win3 Loc   [00000]
*** thresh Win3 Count [00000]
*** noise Win4 max    [00000]
*** noise Win4 min    [00000]
*** noise Win4 cnt    [00000]
*** noise Win4 sum    [00000]
*** noise Win4 sum Sq [00000]
*** event PPS         [00000]
*** event Start Dig   [660956440]
*** event End   Dig   [660957527]
*** event Logic Done  [10085]
*** event Restart     [660908108]


*** counter           [00995]
*** trigger           [13219]
*** window A start    [00000]
*** window A  stop    [00125]
*** window B start    [00137]
*** window B  stop    [00250]
*** window C start    [00262]
*** window C  stop    [00375]
*** window D start    [00450]
*** window D  stop    [00537]
*** thresh Win3 Value [00600]
*** thresh Win3 Loc   [00000]
*** thresh Win3 Count [00000]
*** noise Win4 max    [00000]
*** noise Win4 min    [00000]
*** noise Win4 cnt    [00000]
*** noise Win4 sum    [00000]
*** noise Win4 sum Sq [00000]
*** event PPS         [00000]
*** event Start Dig   [660956440]
*** event End   Dig   [660957527]
*** event Logic Done  [10085]
*** event Restart     [660908139]


*** counter           [00997]
*** trigger           [13222]
*** window A start    [00000]
*** window A  stop    [00125]
*** window B start    [00137]
*** window B  stop    [00250]
*** window C start    [00262]
*** window C  stop    [00375]
*** window D start    [00450]
*** window D  stop    [00537]
*** thresh Win3 Value [00600]
*** thresh Win3 Loc   [00000]
*** thresh Win3 Count [00000]
*** noise Win4 max    [00000]
*** noise Win4 min    [00000]
*** noise Win4 cnt    [00000]
*** noise Win4 sum    [00000]
*** noise Win4 sum Sq [00000]
*** event PPS         [00000]
*** event Start Dig   [661006441]
*** event End   Dig   [661007529]
*** event Logic Done  [10086]
*** event Restart     [660958193]


*** counter           [00998]
*** trigger           [13223]
*** window A start    [00000]
*** window A  stop    [00125]
*** window B start    [00137]
*** window B  stop    [00250]
*** window C start    [00262]
*** window C  stop    [00375]
*** window D start    [00450]
*** window D  stop    [00537]
*** thresh Win3 Value [00600]
*** thresh Win3 Loc   [00000]
*** thresh Win3 Count [00000]
*** noise Win4 max    [00000]
*** noise Win4 min    [00000]
*** noise Win4 cnt    [00000]
*** noise Win4 sum    [00000]
*** noise Win4 sum Sq [00000]
*** event PPS         [00000]
*** event Start Dig   [661156443]
*** event End   Dig   [661157533]
*** event Logic Done  [10088]
*** event Restart     [661123109]
</code>

  * Period between triggers = event Start Dig - event Start Dig
  * Period between triggers = 661156443 - 661006441
  * Period between triggers = 150,002 * (1/250000000) = 0.0006 or 600 microseconds, so this one missed two shots
  * Check the trigger value, it looks OK, but the one above it did miss 3, wonder if the values are one behind?
    * This one shows 13223 and 13222 but the next shot above 13219



=== Experimental Data ===

== Lowered Data Depth Testing ==

  * Acquire Time ?

Testing 130k versus 64k, I am finding the start digi and end digi indeed take half as long.

<code>
d=c130k.EVENTENDDIG - c130k.EVENTSTARTDIG
print,mean( c130k.EVENTENDDIG - c130k.EVENTSTARTDIG ) * t2s
6.5787344e-05
print,mean( c64k.EVENTENDDIG - c64k.EVENTSTARTDIG ) * t2s
3.3019777e-05
</code>

  * **lvisF_64k.dat.meta.bin** average is 33 uSecs Acquire Time
  * **lvisF_130k.dat.meta.bin** average is 66 uSecs Acquire Time

  * Transfer Time ?

Looks to be that the event reset time is shifted by one sample.

<code>
d = shift(c130k.EVENTDIGRESTART,-2)- c130k.EVENTENDDIG
print,mean(double(d(where(d LT 40000 AND d GT 1000))))  * t2s
   0.00010969424  ; 110 usecs
d = shift(c64k.EVENTDIGRESTART,-2)- c64k.EVENTENDDIG
print,mean(double(d(where(d LT 20000 AND d GT 5000))))  * t2s
4.9933655e-05 ; 50 usecs
</code>

  * **lvisF_64k.dat.meta.bin** average is 50 uSecs DMA to PC Time
  * **lvisF_130k.dat.meta.bin** average is 110 uSecs DMA to PC Time