pymepix PixelPipeline / PacketProcessor is missing data in the first seconds after startup

PixelPipeline / PacketProcessor is missing data in the first seconds after startup

Open bj-s opened this issue 2 years ago • 0 comments

Within the packet processor (pymepix/processing/logic/packet_processor.py) in the PixelPipeline, it is observed that some data is missing in the first seconds after the acquisition was initiated with PymepixConnection.start(). As a consequence, the assigned counter values might be shifted for the first events, since some events are simply not counted.

The origin of this issue is not clear to me. But it looks to me as if this is likely already present in the data provided by the UDP sampler.

Evidence

Missing triggers

Looking at the absolute times for the trigger edges that are seen by pymepix and used in PacketProcessor.find_events_fast() to assign the detected pixels (with known absolute time) to their trigger. And to then compute their time of arrival relative to their trigger.

To make the error apparent I added in the file pymepix/processing/logic/packet_processor.py for logging after line 283

self.info("    find_events >> Trigger times >> %s" % str(start))

so in the context of the function it looks like:

 def find_events_fast(self):
        if self.__exist_enough_triggers():
            self._triggers = self._triggers[np.argmin(self._triggers) :]

            if self.__toa_is_not_empty():
                # Get our start/end triggers to bin events accordingly
                start = self._triggers[0:-1:]
                if start.size > 0:
                    self.info("    find_events >> Trigger times >> %s" % str(start))
                    trigger_counter = np.arange(
                        self._trigger_counter, self._trigger_counter + start.size - 1, dtype=int
                    )
                    self._trigger_counter = trigger_counter[-1] + 1

The array start contains the absolute times of the detected triggers (rising edges to TDC1). For a 10Hz repetition rates triggers should appear every 0.1 second. This is usually the case, except for a gap in the beginning.

Consistently, also after power-cycling of the pymepix, the array start has in the first or second call (note: I am not sure whether it was also observed in the first call) of find_events_fast a single longer spacing. Here some examples

[ 0.85430714 0.95435797 1.0544088 1.45457223 1.55462305 1.65467388 1.75472471 1.85477553]
[ 0.83766719 0.93771802 1.03776885 1.13781967 1.43797215 1.53802298 1.63807381 1.73812463 1.83817546]
[ 0.27671487 0.37672582 0.47673677 0.57670785 0.6767188 1.47676652 1.57677747]
[ 0.38867928 0.4887301 0.58878092 1.48923833 1.58924927 1.68930009]
[ 0.34440454 0.44441549 0.54446631 0.64447725 1.44464456 1.54465551 1.64470633]

Missing pixel data

Even further, when looking not at the MessageType.EventData but MessageType.PixelData, and printing a histogram, there is a gap in the same time window. Meaning the time window missing the triggers also misses the pixel data.

e.g. from the full log shown below (top row histogram counts, bottom row bin edges):

[24681 10342     0     0     0     0  2061 25109 24743 25139]
[ 0.48644553  0.61522435  0.74400318  0.872782    1.00156082  1.13033965   1.25911847  1.3878973   1.51667612  1.64545494  1.77423377]

setup / minimal script

I run the PixelPipeline with only 1 process for the packet processor (opposed to the default hardcoded 2 processes). I.e. in pymepix/processing/acquisition.py line 47 is changed to

self.addStage(2, PipelinePacketProcessor, num_processes=1)

Code to reproduce (please note the necessary changes in pymepix to print logs, also you need to indicate the correct sophy config file):

from pymepix import PymepixConnection
from pymepix.processing import PixelPipeline

from time import sleep
import numpy as np

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
)

def data_callback(header, data):
    print(f"Received data type: {header}")
    if int(header) == 1:
        _hist, _bins = np.histogram(data[2], bins=np.linspace(np.min(data[2]), np.max(data[2]),num=11))
        print(_hist)
        print(_bins)

test_duration_s = 5
Vthreshold_fine = 10
config_file_path = "SoPhy_XFEL_config.spx"

ppx = PymepixConnection(("192.168.100.10", 50000), ('', 0))

ppx.dataCallback = data_callback
ppx[0].loadConfig(config_file_path)
ppx[0].setupAcquisition(PixelPipeline, use_event=True, event_window=(0, 1e-1))
sleep(1)
ppx[0].Vthreshold_fine = Vthreshold_fine
sleep(1)
ppx.start()
sleep(test_duration_s)
ppx.stop()

Full log output

Here the full output from the script:

2022-02-17 17:30:17,030 - pymepix.SPIDRController - INFO - Connecting to 192.168.100.10:50000
2022-02-17 17:30:17,041 - pymepix.SpidrDevice - INFO - Device 0 with id 14139 created
2022-02-17 17:30:17,044 - pymepix.SpidrDevice - INFO - Device 1 with id 2147483647 created
2022-02-17 17:30:17,047 - pymepix.SpidrDevice - INFO - Device 2 with id 2147483647 created
2022-02-17 17:30:17,050 - pymepix.SpidrDevice - INFO - Device 3 with id 2147483647 created
2022-02-17 17:30:17,059 - pymepix.Timepix W0055_K03 - INFO - UDP Address is 192.168.100.1:8192
2022-02-17 17:30:17,552 - pymepix.Timepix W0055_K03 - INFO - Setting up acquisition class
2022-02-17 17:30:17,553 - pymepix.Pixel AcqPipeline - INFO - Initializing pipeline
2022-02-17 17:30:17,553 - pymepix.Pixel AcqPipeline - INFO - Initializing Pixel pipeline
2022-02-17 17:30:17,554 - pymepix.Pixel AcqPipeline - INFO - Adding stage 0 with klass <class 'pymepix.processing.udpsampler.UdpSampler'>
2022-02-17 17:30:17,554 - pymepix.Pixel AcqPipeline - INFO - Adding stage 2 with klass <class 'pymepix.processing.pipeline_packet_processor.PipelinePacketProcessor'>
2022-02-17 17:30:17,555 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 1,128
2022-02-17 17:30:17,564 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 2,8
2022-02-17 17:30:17,571 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 3,128
2022-02-17 17:30:17,572 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 4,5
2022-02-17 17:30:17,574 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 5,128
2022-02-17 17:30:17,575 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 6,420
2022-02-17 17:30:17,576 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 7,6
2022-02-17 17:30:17,578 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 8,84
2022-02-17 17:30:17,580 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 9,8
2022-02-17 17:30:17,583 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 10,128
2022-02-17 17:30:17,586 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 11,8
2022-02-17 17:30:17,587 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 12,192
2022-02-17 17:30:17,588 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 13,128
2022-02-17 17:30:17,589 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 14,128
2022-02-17 17:30:17,591 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 15,128
2022-02-17 17:30:17,593 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 16,256
2022-02-17 17:30:17,596 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 17,128
2022-02-17 17:30:17,598 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 18,128
2022-02-17 17:30:19,665 - pymepix.Timepix W0055_K03 - INFO - Dev: 14139 eth_mask :    FFFF cpu_mask:     F39F
2022-02-17 17:30:19,666 - pymepix.Timepix W0055_K03 - INFO - Heartbeat thread starting
2022-02-17 17:30:19,670 - pymepix.Pymepix - INFO - Found 1 Timepix/Medipix devices
2022-02-17 17:30:19,671 - pymepix.Pymepix - INFO - Device 0 - W0055_K03
2022-02-17 17:30:19,672 - pymepix.SPIDRController - INFO - Setting bias Voltage to 50 V (Dac value 1691)
2022-02-17 17:30:19,673 - pymepix.Pymepix - INFO - Enabling polling
2022-02-17 17:30:19,674 - pymepix.Pymepix - WARNING - Clearing polling buffer
2022-02-17 17:30:19,674 - pymepix.Pymepix - WARNING - Clearing polling buffer
2022-02-17 17:30:19,674 - pymepix.Pymepix - INFO - Starting data thread
2022-02-17 17:30:19,674 - pymepix.Pymepix - WARNING - Clearing polling buffer
2022-02-17 17:30:19,768 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 1,128
2022-02-17 17:30:19,770 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 2,8
2022-02-17 17:30:19,771 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 3,128
2022-02-17 17:30:19,772 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 4,10
2022-02-17 17:30:19,773 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 5,128
2022-02-17 17:30:19,774 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 6,218
2022-02-17 17:30:19,775 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 7,6
2022-02-17 17:30:19,777 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 8,128
2022-02-17 17:30:19,778 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 9,8
2022-02-17 17:30:19,779 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 10,128
2022-02-17 17:30:19,780 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 11,8
2022-02-17 17:30:19,781 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 12,113
2022-02-17 17:30:19,782 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 13,128
2022-02-17 17:30:19,783 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 14,128
2022-02-17 17:30:19,784 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 15,128
2022-02-17 17:30:19,785 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 16,256
2022-02-17 17:30:19,786 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 17,128
2022-02-17 17:30:19,787 - pymepix.Timepix W0055_K03 - INFO - Setting DAC 18,128
2022-02-17 17:30:22,265 - pymepix.Timepix W0055_K03 - INFO - Setting up acquisition class
2022-02-17 17:30:22,265 - pymepix.Pixel AcqPipeline - INFO - Initializing pipeline
2022-02-17 17:30:22,265 - pymepix.Pixel AcqPipeline - INFO - Initializing Pixel pipeline
2022-02-17 17:30:22,266 - pymepix.Pixel AcqPipeline - INFO - Adding stage 0 with klass <class 'pymepix.processing.udpsampler.UdpSampler'>
2022-02-17 17:30:22,266 - pymepix.Pixel AcqPipeline - INFO - Adding stage 2 with klass <class 'pymepix.processing.pipeline_packet_processor.PipelinePacketProcessor'>
2022-02-17 17:30:24,270 - pymepix.Pymepix - INFO - Starting acquisition
2022-02-17 17:30:24,283 - pymepix.Pymepix - INFO - Setting up W0055_K03
2022-02-17 17:30:24,320 - pymepix.Pymepix - INFO - Starting W0055_K03
2022-02-17 17:30:24,320 - pymepix.Timepix W0055_K03 - INFO - Beginning acquisition
2022-02-17 17:30:24,320 - pymepix.Pixel AcqPipeline - INFO - Starting acquisition
2022-02-17 17:30:24,320 - pymepix.AcqStage-0 - INFO - Creating 1 processes
2022-02-17 17:30:24,321 - pymepix.AcqStage-2 - INFO - Creating 1 processes
2022-02-17 17:30:24,323 - pymepix.AcqStage-0 - INFO - zmq bind on "tcp://127.0.0.1:40000"
2022-02-17 17:30:24,339 - pymepix.PacketProcessor - INFO - Running with triggers? True
2022-02-17 17:30:26,039 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 0.04433183  0.14434278  0.2443936   0.34440454]
Received data type: 1
[8641 8788 8893 8807 8750 9041 8830 8849 8824 8883]
[ 0.0188097   0.06557339  0.11233708  0.15910076  0.20586445  0.25262813
  0.29939182  0.3461555   0.39291919  0.43968288  0.48644656]
Received data type: 2
2022-02-17 17:30:26,345 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 0.34440454  0.44441549  0.54446631  0.64447725  1.44464456  1.54465551
  1.64470633]
Received data type: 1
[24681 10342     0     0     0     0  2061 25109 24743 25139]
[ 0.48644553  0.61522435  0.74400318  0.872782    1.00156082  1.13033965
  1.25911847  1.3878973   1.51667612  1.64545494  1.77423377]
Received data type: 2
2022-02-17 17:30:26,624 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 1.64470633  1.74471727  1.84476809  1.94477904  2.04478998  2.14480093]
Received data type: 1
[9716 9502 9892 9975 9523 9949 9911 9857 9732 9978]
[ 1.77423678  1.82456453  1.87489229  1.92522005  1.97554781  2.02587557
  2.07620333  2.12653108  2.17685884  2.2271866   2.27751436]
Received data type: 2
2022-02-17 17:30:26,915 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 2.14480093  2.24485175  2.34486269  2.44487364]
Received data type: 1
[5942 5873 6059 6107 5920 5869 5964 5869 5910 5760]
[ 2.2775137   2.30771155  2.3379094   2.36810725  2.39830511  2.42850296
  2.45870081  2.48889866  2.51909652  2.54929437  2.57949222]
Received data type: 2
2022-02-17 17:30:27,216 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 2.44487364  2.54492446  2.6449354   2.74494635]
Received data type: 1
[5919 5815 6030 5842 6121 6179 6058 5904 6114 5778]
[ 2.57950271  2.60958743  2.63967215  2.66975687  2.69984159  2.72992631
  2.76001103  2.79009575  2.82018046  2.85026518  2.8803499 ]
Received data type: 2
2022-02-17 17:30:27,520 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 2.74494635  2.84499717  2.94500811  3.04505893]
Received data type: 1
[5732 5712 5651 5669 5740 5714 5960 5759 5973 5778]
[ 2.88034685  2.90952901  2.93871117  2.96789332  2.99707548  3.02625764
  3.05543979  3.08462195  3.11380411  3.14298626  3.17216842]
Received data type: 2
2022-02-17 17:30:27,821 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 3.04505893  3.14506988  3.24508082  3.34513164]
Received data type: 1
[6175 6328 6139 6394 6329 6246 6322 6363 6345 6276]
[ 3.17217755  3.20326131  3.23434506  3.26542882  3.29651257  3.32759633
  3.35868008  3.38976384  3.42084759  3.45193135  3.4830151 ]
Received data type: 2
2022-02-17 17:30:28,118 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 3.34513164  3.44514259  3.54515353  3.64520435]
Received data type: 1
[6285 6071 5932 6034 6059 6029 6351 6190 5998 6200]
[ 3.48301514  3.5130552   3.54309526  3.57313532  3.60317538  3.63321544
  3.6632555   3.69329556  3.72333562  3.75337568  3.78341574]
Received data type: 2
2022-02-17 17:30:28,422 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 3.64520435  3.7452153   3.84522624  3.94523719]
Received data type: 1
[5997 6032 6158 6392 6274 6254 6170 6129 5732 6022]
[ 3.78342647  3.81346316  3.84349985  3.87353655  3.90357324  3.93360994
  3.96364663  3.99368332  4.02372002  4.05375671  4.0837934 ]
Received data type: 2
2022-02-17 17:30:28,720 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 3.94523719  4.04524813  4.14525908  4.2453099 ]
Received data type: 1
[6215 6084 6106 5769 6109 6034 6141 6094 6439 6038]
[ 4.08379238  4.11377211  4.14375185  4.17373158  4.20371132  4.23369105
  4.26367079  4.29365053  4.32363026  4.35361     4.38358973]
Received data type: 2
2022-02-17 17:30:29,020 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 4.2453099   4.34532084  4.44533179  4.54534273]
Received data type: 1
[6266 6106 6075 6066 6149 6082 6080 5830 5744 6216]
[ 4.3835893   4.41368924  4.44378917  4.47388911  4.50398905  4.53408899
  4.56418892  4.59428886  4.6243888   4.65448873  4.68458867]
Received data type: 2
2022-02-17 17:30:29,323 - pymepix.PacketProcessor - INFO -     find_events >> Trigger times >> [ 4.54534273  4.64535368  4.74536462  4.84537556]
2022-02-17 17:30:29,337 - pymepix.Pymepix - INFO - Stopping acquisition
Received data type: 1
[6105 6173 6186 6003 6049 6131 6003 6073 6091 6360]
[ 4.68459818  4.71463792  4.74467767  4.77471741  4.80475716  4.8347969
  4.86483664  4.89487639  4.92491613  4.95495588  4.98499562]
Received data type: 2
2022-02-17 17:30:29,391 - pymepix.Timepix W0055_K03 - INFO - Stopping acquisition
2022-02-17 17:30:29,392 - pymepix.Pixel AcqPipeline - INFO - Stopping acquisition
2022-02-17 17:30:29,392 - pymepix.AcqStage-0 - INFO - Stopping stage 0
2022-02-17 17:30:29,392 - pymepix.AcqStage-0 - INFO - Joining thread <UdpSampler(UdpSampler-1, started daemon)>
Received data type: 1
[748 729 777 831 855 789 803 778 773 854]
[ 4.98500347  4.98877454  4.9925456   4.99631666  5.00008773  5.00385879
  5.00762985  5.01140092  5.01517198  5.01894304  5.0227141 ]
2022-02-17 17:30:29,712 - pymepix.AcqStage-0 - INFO - Join complete
2022-02-17 17:30:29,713 - pymepix.AcqStage-0 - INFO - Stop complete
2022-02-17 17:30:29,713 - pymepix.AcqStage-2 - INFO - Stopping stage 2
2022-02-17 17:30:29,714 - pymepix.AcqStage-2 - INFO - Waiting for process 0
2022-02-17 17:30:30,725 - pymepix.AcqStage-2 - INFO - Process stop complete
2022-02-17 17:30:30,725 - pymepix.AcqStage-2 - INFO - Stop complete

Feb 17 '22 16:02 bj-s

pymepix pymepix copied to clipboard

PixelPipeline / PacketProcessor is missing data in the first seconds after startup

Evidence

Missing triggers

Missing pixel data

setup / minimal script

Full log output

pymepix
pymepix copied to clipboard