Synchronization (or tracking of offset) of involved clocks

video stimuli grabber computer uses NTP to keep its clock nicely synchronized (related #12), but we do not know (yet) what is happening on MRI system which includes multiple computers (console, reconstruction server)

[ ] investigate if any clocks synchronization is happening "natively" between them
[ ] unlikely they are talking to any NTP server, so we would need to establish a way to monitor their individual or synchronized (if they are synced) drift(s). Of most interest I guess is the reconstruction server, metadata (including times) of which I guess is encoded within DICOM.
[ ] see if we can make reproiner receive trigger pulses directly from the scanner, so we could use those time stamps (in the clock of reproiner) to later better judge about beginning/end of acquisition

Details of our current setup

and with more annotations:

with added connection from curdes to personal computer via USB (not yet committed here):

Regarding "what is where", here is a list of involved "computers"

reproiner: operated under reprostim account:
- ntpsec server, pointing to ntp.dartmouth.edu (and a pool of debian NTP servers)
- ReproStim (videograbber - natively "installed" under /usr/local/bin; under screen)
- ReproEvents (@TheChymera 's micropython thingie, under tmux),
- ReproMon (in a podman container)
- not running: reprostim-screencapture (for con/noisseur) - built but not used yet
rolando: operated under bids account
- cron job runs update-lists daily
- @yarikoptic runs HeuDiConv and ReproIn helper using ///ReproNim/containers (and datalad/datalad-containers) on obtained DICOM files (from under /inbox/DICOM) and updates BIDS datasets under /inbox/BIDS
birch: RPi within CurDes BIRCH device, networked through reproiner
- ntpsec server, pointing to reproiner, and ntp.dartmouth.edu (and a pool of debian NTP servers)
- runs "customized" stack to capture events
MRI beast computers
- console: used by operator to schedule/run/view data/trigger data sending etc. @yarikoptic thinks it runs NTP but fails to sync... yet to double check
- reconstruction: no direct access, times might be within DICOMS
- ...
Experimenter Computer
- typically what experimenter comes with, and connects projector via VGA (and adapters) and birch via USB to collect trigger pulse and responses
- for sync timing reproiner will be used

not yet used/deployed

con/noisseur

On 2024/05/28 we got sample collection of data after syncing birch via ntp to reproiner and running the "show qr code with details" after each trigger pulse was received. Data is available there on typhon and here it is with added short descriptions

yoh@typhon:/data/repronim/reproflow-data-sync/ses-20240528

birch -- jsonlines records as obtained from modified (not open source yet) software on birch
- convinient to be viewed using visidata (command vd). First there was session where Terry tried all buttons on response box, so it looks like
- then there would eventually come "trigger pulses" from all the runs we tried to do. They typically look like so we have bit for 256 going into 1 and then back to 0.
- detailed description of the alink_byte and alink_flags are at https://wiki.curdes.com/bin/view/CdiDocs/BirchTimestampFile besides that there it describes original (non jsonlines) format which corresponds to following json fields: time, alink_byte (we do in regular decimal int, whenever it was original in hex), alink_flags
- more documentation for Birch: https://wiki.curdes.com/bin/view/CdiDocs/BirchUsersManual

DICOMS -- fMRI sequences on a phantom in DICOMs (not converted to nii.gz yet)

there is a python library pydicom which would allow to load it from python
on command line, use dcmdump from dcmtk package to dump all metadata

here is an example of dump of all acquisition times for 15 dynamics we have

❯ for f in *.dcm; do dcmdump +P '0008,0032' $f; done
(0008,0032) TM [111322.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111324.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111326.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111328.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111330.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111332.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111334.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111336.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111338.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111340.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111342.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111344.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111346.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111348.495000]                          #  14, 1 AcquisitionTime
(0008,0032) TM [111350.495000]                          #  14, 1 AcquisitionTime

psychopy -- Python stimuli script and produced logs which I ran on my laptop (time was not ntp synced)
README.md -- attempt to describe more
reproevents -- .tsv file from ReproEvents MicroPython board ran/sampled on reproiner as well
reprostim-videos -- videos of the stimuli as captured by ReproStim (reprostim-videocapture)
- Parsing/parse_wQR.py extracts recorded as QR codes records which must correspond to the ones logged under psychopy/ folder
- 96 to tune that script up

there were 1 screwed up (I think) run and then 2 good ones. "good ones" should have _run-1 and _run-2 where "available" (DICOM series description and psychopy logs have it for sure)

so the idea would be to create a "calibration stimuli script" which would

be ran from reproin'er box (might need VGA splitter?)
be triggered by MR trigger pulse to begin upon a matching in duration BOLD sequence acquisition (on phantom)
present QR code after each trigger pulse thus presenting time as known to the reproiner
present some audio stimuli (could be simple short chirp) as well with known timing (also reflected in the log)
record timings for all trigger pulses in a readily machine readable log (json or yaml)
- same records as what in QR codes
- timing/duration on audio chirps
- all trigger pulses received

based on that data AND timestamps in the DICOMs we would be able to tell the offset and from multiple (across weeks) acquisitions to tell the drift of the clock in the MR reconstruction box.

Then this information on clock differences would be used for partitioning videos (#14).

more on this idea (which I like now even more): by presenting it from reproin'er (the same box which also has video capturing dongle attached) we can assess delay introduced by the capturing dongle! (assuming that stimuli script does all the timing correctly)

proceed after #35 is done.

in preparation to tomorrow QA/sync acquisition -- @andycon please prepare a script which would keep presenting QR codes (e.g. every 10th frame or so?) with that datetime up to milliseconds embedded so we could later assess delay/jitter between video stimuli delivery and capture (in addition to magnet triggers captured by #35)

summary of times for the sample `006-func-bold_task-rest_run-1` acquisition and only 1st dynamic shown here: not ultimately usable since we are lacking qrcode recording for some reason

- DICOMS on MRI hardware (reconstruction box likely) - **t_mri**. ``` ❯ for f in *.dcm; do dcmdump +P '0008,0032' $f; done (0008,0032) TM [111322.495000] # 14, 1 AcquisitionTime ``` - psychopy script on my laptop (just because it was me running it so I have those logs): **t_experimenter** ```shell ❯ grep acqNum 20240528_run-1.log {"event": "trigger", "acqNum": 0, "logfn": "20240528-2.log", "time": 1716908819.6869357, "time_formatted": "2024-05-28T11:06:59.686936-04:00", "keys": ["5"], "keys_time": 1716908832.3484943, "keys_time_str": "2024-05-28T11:07:12.348494-04:00", "time_flip": 1716908832.4185193, "time_flip_formatted": "2024-05-28T11:07:12.418519-04:00"} ``` - times decoded by qrcode decoder from a longer video recording (should correspond 1-to-1 to psychopy script log entry). What is of interest is the "offset" from the beginning of the file... **t_experimenter** (relates to **t_reproiner** + **t_ffmpeg_recdelay**) ``` !!! We are actually missing them somehow. I think they should have been part of the 2024.05.28.11.01.49.915_2024.05.28.11.08.26.672.mkv but that one seems missing them... ``` - times in the .mkv.log file accompanying .mkv (also time is encoded in the file name) -- in **t_reproiner** (and we do not know t_ffmpeg_recdelay) ``` ❯ grep REPROSTIM-METADATA-JSON.*start_ts 2024.05.28.11.08.50.176_2024.05.28.11.10.31.855.mkv.log 2024-05-28 11:08:50.177 [info] [3719071] REPROSTIM-METADATA-JSON: {"aDev":"hw:2,1","appName":"reprostim-videocapture","cx":1920,"cy":1080,"frameRate":"60","serial":"B208220302195","start_ts":"2024.05.28.11.08.50.176","ts":"2024.05.28.11.08.50.177","type":"session_begin","vDev":"USB Capture DVI+","version":"1.8.0.225"} :REPROSTIM-METADATA-JSON ... ``` - time when we received trigger pulse on birch **t_birch** (NTP synced, thus should be really close to **t_reproiner**), time stamps in Z UTC zone (+00:00) ```shell ❯ grep -A1 024-05-28T15:08 * {"epoch_time": 1716908920.407058, "iso_time": "2024-05-28T15:08:40.407058+00:00", "time": 386.6154779999997, "alink_byte": 240, "alink_flags": 1} {"epoch_time": 1716908940.610456, "iso_time": "2024-05-28T15:09:00.610456+00:00", "time": 406.82571899999994, "alink_byte": 496, "alink_flags": 2} ```

this times from README.md where I palpated delays (my laptop was not in sync by about 500ms)

    ❯ date --iso-8601=ns | tr "\n" "\t" ; for h in reproiner birch localhost; do ssh $h 'date --iso-8601=ns | tr "\n" "\t" ; hostname' & done; sleep 3;
    2024-05-28T11:50:40,131809493-04:00 
    2024-05-28T11:50:40,168054275-04:00 bilena
    2024-05-28T11:50:40,777833551-04:00 reproiner
    2024-05-28T11:50:40,813447469-04:00 Birch-4115966

So redoing for the _run-2 for which we should have everything (yet TODO)

DICOMS on MRI hardware (reconstruction box likely) - t_mri.

ses-20240528/DICOMS/007-func-bold_task-rest_run-2
❯ for f in *.dcm; do dcmdump +P '0008,0032' $f; done
(0008,0032) TM [111511.502500]                          #  14, 1 AcquisitionTime

so we started to acquire first slice of the first volume at t_mri=11:15:11,502500.

psychopy script on my laptop (just because it was me running it so I have those logs): t_experimenter

ses-20240528/psychopy
❯ grep 'keys": \["5' 20240528_run-2.log | head -n 1
{"event": "trigger", "acqNum": 0, "logfn": "20240528_run-2.log", "time": 1716908929.1446826, "time_formatted": "2024-05-28T11:08:49.144683-04:00", "keys": ["5"], "keys_time": 1716908940.5812862, "keys_time_str": "2024-05-28T11:09:00.581286-04:00", "time_flip": 1716908940.6707587, "time_flip_formatted": "2024-05-28T11:09:00.670759-04:00"}

so we received trigger pulse at t_experimenter=11:09:00.581286 (6 minutes diff!)

times decoded by qrcode decoder from a longer video recording (should correspond 1-to-1 to psychopy script log entry). What is of interest is the "offset" from the beginning of the file... t_experimenter (relates to t_reproiner + t_ffmpeg_recdelay)

ses-20240528/reprostim-videos
❯ grep '2024-05-28T11:09:00.581286-04:00' *jsonl
2024.05.28.11.08.50.176_2024.05.28.11.10.31.855.mkv-qr.jsonl:{"frame_start": 639, "time_start": "TODO-figureout", "data": {"event": "trigger", "acqNum": 0, "logfn": "20240528_run-2.log", "time": 1716908929.1446826, "time_formatted": "2024-05-28T11:08:49.144683-04:00", "keys": ["5"], "keys_time": 1716908940.5812862, "keys_time_str": "2024-05-28T11:09:00.581286-04:00"}, "frame_end": 657, "time_end": "TODO"}

so we got that record on frame 639 (time from video start yet to be determined to establish relationship to t_reproiner etc) for 18 frames.

times in the .mkv.log file accompanying .mkv (also time is encoded in the file name) -- in t_reproiner (and we do not know t_ffmpeg_recdelay)

❯ grep REPROSTIM-METADATA-JSON.*start_ts 2024.05.28.11.08.50.176_2024.05.28.11.10.31.855.mkv.log
2024-05-28 11:08:50.177 [info] [3719071] REPROSTIM-METADATA-JSON: {"aDev":"hw:2,1","appName":"reprostim-videocapture","cx":1920,"cy":1080,"frameRate":"60","serial":"B208220302195","start_ts":"2024.05.28.11.08.50.176","ts":"2024.05.28.11.08.50.177","type":"session_begin","vDev":"USB Capture DVI+","version":"1.8.0.225"} :REPROSTIM-METADATA-JSON
...

time when we received trigger pulse on birch t_birch (NTP synced, thus should be really close to t_reproiner but we do not have samples for that one ATM since experimenter box was different, but about .5 sec behind), time stamps in Z UTC zone (+00:00)

ses-20240528/birch
❯ grep -A1 -E '15:(0[789]|1[0123]):.*alink_byte.*496' 20240528-105648.jsonl
.... there came bunch for run-01, then break in time/lines and beginning of run-02: ...
{"epoch_time": 1716908940.610456, "iso_time": "2024-05-28T15:09:00.610456+00:00", "time": 406.82571899999994, "alink_byte": 496, "alink_flags": 2}

so we have 11:09:00.610456 in t_birch

time when we detected on reproiner via micro-python board recording via DB35 connector on birch the TTL pulse

❯ grep -A1 -E '11:(09|1[0123])' 2024-05-28T11.csv | head -n 2
224,1,1716908940.6144216,2024-05-28T11:09:00.614422-04:00,6,0.000224,122.171526,-ACK,,1162414
219,0,1716908940.6344159,2024-05-28T11:09:00.634416-04:00,6,0.000219,122.191516,-ACK,,1162415

so 200ms pulse at 11:09:00.614422 in t_reproiner

FWIW we have got a new data sample (again from my laptop :-/ ) which was pushed to typhon,

full content of repo

```shell yoh@typhon:/data/repronim/reproflow-data-sync$ find * -maxdepth 2 code code/collect_data.sh ses-20240528 ses-20240528/DICOMS ses-20240528/DICOMS/001-anat-scout_ses-{date} ses-20240528/DICOMS/002-anat-scout_ses-{date}_MPR_sag ses-20240528/DICOMS/003-anat-scout_ses-{date}_MPR_cor ses-20240528/DICOMS/004-anat-scout_ses-{date}_MPR_tra ses-20240528/DICOMS/005-func-bold_task-rest_run-1 ses-20240528/DICOMS/006-func-bold_task-rest_run-1 ses-20240528/DICOMS/007-func-bold_task-rest_run-2 ses-20240528/README.md ses-20240528/psychopy ses-20240528/psychopy/20240528-1.log ses-20240528/psychopy/20240528_run-1.log ses-20240528/psychopy/20240528_run-2.log ses-20240528/psychopy/qr_code_flips.py ses-20240528/reprostim-videos ses-20240528/reprostim-videos/2024.05.28.11.08.50.176_2024.05.28.11.10.31.855.mkv ses-20240528/reprostim-videos/2024.05.28.11.08.50.176_2024.05.28.11.10.31.855.mkv.log ses-20240528/reprostim-videos/2024.05.28.11.11.35.277_2024.05.28.11.12.06.156.mkv ses-20240528/reprostim-videos/2024.05.28.11.11.35.277_2024.05.28.11.12.06.156.mkv.log ses-20240528/reprostim-videos/2024.05.28.11.18.01.667_2024.05.28.11.18.47.953.mkv ses-20240528/reprostim-videos/2024.05.28.11.18.01.667_2024.05.28.11.18.47.953.mkv.log ses-20240528/reprostim-videos/2024.05.28.11.01.49.915_2024.05.28.11.08.26.672.mkv ses-20240528/reprostim-videos/2024.05.28.11.01.49.915_2024.05.28.11.08.26.672.mkv.log ses-20240528/reprostim-videos/2024.05.28.11.01.49.915_2024.05.28.11.08.26.672.mkv-qr.jsonl ses-20240528/reprostim-videos/2024.05.28.11.08.37.837_2024.05.28.11.08.44.617.mkv ses-20240528/reprostim-videos/2024.05.28.11.08.37.837_2024.05.28.11.08.44.617.mkv-qr.jsonl ses-20240528/reprostim-videos/2024.05.28.11.08.37.837_2024.05.28.11.08.44.617.mkv.log ses-20240528/reprostim-videos/2024.05.28.11.08.50.176_2024.05.28.11.10.31.855.mkv-qr.jsonl ses-20240528/reprostim-videos/2024.05.28.11.11.35.277_2024.05.28.11.12.06.156.mkv-qr.jsonl ses-20240528/reprostim-videos/2024.05.28.11.18.01.667_2024.05.28.11.18.47.953.mkv-qr.jsonl ses-20240528/reproevents ses-20240528/reproevents/2024-05-28T11.csv ses-20240528/reproevents/fetch.sh ses-20240528/birch ses-20240528/birch/20240528-105648.jsonl ses-20240604 ses-20240604/DICOMS ses-20240604/DICOMS/001-anat-scout_ses-{date} ses-20240604/DICOMS/002-anat-scout_ses-{date}_MPR_sag ses-20240604/DICOMS/003-anat-scout_ses-{date}_MPR_cor ses-20240604/DICOMS/004-anat-scout_ses-{date}_MPR_tra ses-20240604/DICOMS/005-func-bold_task-rest_run-1 ses-20240604/DICOMS/006-func-bold_task-rest_run-2 ses-20240604/DICOMS/007-func-bold_task-rest_run-3 ses-20240604/DICOMS/008-func-bold_task-rest_run-4 ses-20240604/README.md ses-20240604/birch ses-20240604/birch/out.jsonl ses-20240604/psychopy ses-20240604/psychopy/20240604_run-1.log ses-20240604/psychopy/20240604_run-2.log ses-20240604/psychopy/20240604_run-3.log ses-20240604/psychopy/20240604_run-4.log ses-20240604/psychopy/qr_code_flips.py ses-20240604/reproevents ses-20240604/reproevents/events.csv ses-20240604/reprostim-videos ses-20240604/reprostim-videos/2024.06.04.13.51.24.278_2024.06.04.13.51.31.057.mkv ses-20240604/reprostim-videos/2024.06.04.13.51.24.278_2024.06.04.13.51.31.057.mkv.log ses-20240604/reprostim-videos/2024.06.04.13.51.36.620_2024.06.04.13.58.20.763.mkv ses-20240604/reprostim-videos/2024.06.04.13.51.36.620_2024.06.04.13.58.20.763.mkv.log ```

but to facilitate collaboration etc I now pushed that dataset also to https://datasets.datalad.org/?dir=/repronim/reproflow-data-sync , so you can datalad clone it and get files. Could you @vmdocua please look at that https://datasets.datalad.org/repronim/reproflow-data-sync/ses-20240604/reprostim-videos/2024.06.04.13.51.36.620_2024.06.04.13.58.20.763.mkv which should have all the qrcodes and should be having good "duration" , to adjust the Parsing/parse_wQR.py so it reports frames/time since the video beginning until that QR code?

First round done:

To analyse QR codes and data was used command on @typhon like listed below with the latest parse_wQR.py tool:

/reprostim/Parsing$ ./parse_wQR.py --log-level INFO /data/repronim/reproflow-data-sync/ses-20240604/reprostim-videos/2024.06.04.13.51.36.620_2024.06.04.13.58.20.763.mkv > 2024-06-27.info.txt

Script execution results were copied to @typhon:/data/repronim/reproflow-data-sync.analysis/ses-20240604/2024-06-27.info.txt location.
Just fragment sample for a parsed QR record:

QR: QrRecord(frames=[16089, 16119], pos=[268.133, 268.633 sec], start_time=2024-06-04 13:56:04.753000, end_time=2024-06-04 13:56:05.253000], data={'event': 'trigger', 'acqNum': 7, 'logfn': '20240604_run-3.log', 'time': 1717523763.3222332, 'time_formatted': '2024-06-04T13:56:03.322233-04:00', 'keys': ['5'], 'keys_time': 1717523764.7378685, 'keys_time_str': '2024-06-04T13:56:04.737869-04:00'})
 - QR code time : 2024-06-04 13:56:04.753000
 - Event time   : 2024-06-04 13:56:03.322233 / dt=-1.430767 sec
 - Keys time    : 2024-06-04 13:56:04.737869 / dt=-0.015131 sec

Cool, thank you! Most likely we would also want some json output mode so we have it machine readable

ReproNim / reprostim

Synchronization (or tracking of offset) of involved clocks #13

Details of our current setup

96 to tune that script up

So redoing for the _run-2 for which we should have everything (yet TODO)