APS-USAXS / usaxs-bluesky-ended-2023

Bluesky instrument for USAXS
0 stars 0 forks source link

Better way of time recording in AD #351

Open prjemian opened 4 years ago

prjemian commented 4 years ago

by email, @jilavsky writes:

... trying to verify some data collection - basically, user argues ... that somehow we measured the same sample twice under different names. Now, I can more or less conclusively prove, that it is not true - NeXus files with all the metadata are simply amazing. Spec file is useful also.

Now, as I am working on this, I extract times when data were collected. That reminded me of problem here, which I have been ignoring for long time.

We have two PVs for waxs: 9idcLAX:WAXS:StartExposureTime and EndExposureTime.

These are set in spec (and I assume Bluesky also) :

  1. epics_put(“9idcLAX:WAXS:StartExposureTime”, date()) ...
  2. Collect WAXS data using AD ...
  3. epics_put(“9idcLAX:WAXS:EndExposureTime”, date())

These PVs are in the NeXus attributes Template and included in the Nexus file through layout.xml file.

Logically, before spec puts in the PV end time, AD has already updated its value and uses therefore only the stale value, end time of prior image. End time is BEFORE the start time… Ouch. Basically, only the Start time has any meaning here.

How do we get the correct end time in the metadata? It is confusing the hell out of me to remember this and if user sees this, they will be wild.


Alternatively, I can remove the end time if there is no simple way of getting that. It should be startTime+exposure time anyway…

Any suggestion which will not require major revision of AD and our templates? Is there default internal AD metadata which one can use for this? Seems obvious timestamp…

prjemian commented 4 years ago

Understandable that it is confusing for anyone. It's possible. Read...

There exists the possibility of configuring the AreaDetector's HDF5 layout file to write a PV onFileClose. (I believe the default is onFileOpen). See the example layout file: https://github.com/areaDetector/ADSimDetector/blob/master/iocs/simDetectorIOC/iocBoot/iocSimDetector/hdf5_layout_demo.xml#L20-L27

Direct access to a record's .TIME field is not possible from a client directly. This is most obvious from the EPICS Record Reference Manual, section on Fields Common to All Records: https://wiki-ext.aps.anl.gov/epics/index.php/RRM_3-14_dbCommon#Miscellaneous_Fields

Now comes the tricky business. And this took a bit more research for sure. You must get this information to areadetector before it closes the data file. If you put start time, collect WAXS AD, put stop time, you have missed that opportunity.

You need this PV: WAXS:cam1.Acquire.TIME

The .TIME field is accessible within the IOC database, just not by Channel Access clients. Clients usually can access that information as metadata but the HDF File Writer in AD cannot use that method since it is configured by PVs. Here's the gold nugget: https://epics.anl.gov/tech-talk/2006/msg00017.php

We create a stringin (not stringout) record that will contain the formatted time of the WAXS:cam1:Acquire PV. Whenever that PV updates, the time will be posted to our new stringin record in the format we specify.

record(stringin, "$(P)$(R)Acquire_TimeStamp") {
     field(DESC, "Acquire timestamp, ISO8601")
     field(DTYP, "Soft Timestamp")
     field(INP, "@%Y-%m-%dT%H:%M:%S.%09f")
     # TODO: connect with "$(P)$(R)Acquire.TIME"
}

but this only updates when the record is processed. We need to make it process (set its .PROC field to 1) when "$(P)$(R)Acquire" is processed. Here's a PV that will do that work:

record(calcout, "$(P)$(R)Acquire_TimeStampTrigger") {
     field(DESC, "when AD camera Acquire processes")
     field(CALC, "1")
     field(SCAN, ".1 Second")
     field(INPA, "$(P)$(R)Acquire")
     field(OOPT, "On Change")
     field(OUT, "$(P)$(R)Acquire_TimeStamp.PROC")
}

We could create more infrastructure to make separate PVs for AcquireStartTime and AcquireStopTime. This is just one way to do this.

These two records can be run in (EPICS base) softIoc. But the Trigger record will only capture transitions SLOWER than its .SCAN rate. If we set .SCAN to "I/O Intr" so it only processes when Acquire processes, the IOC will reset that to Passive on startup if it is not in the same IOC with the area detector (and it fails to connect with the INPA). An alternative is to use a record that supports re-targetable connections, such as the swait record.

prjemian commented 4 years ago

We need the IOC to update these two records, not SPEC or Bluesky: 9idcLAX:WAXS:StartExposureTime and 9idcLAX:WAXS:EndExposureTime. The basics of this are:

  1. AreaDetector P=IOC prefix:, R=cam1: -- $(P)$(R)Acquire
  2. Acquire is monitored by an swait record for transitions from Done to Acquire to update StartExposureTime
  3. Acquire is monitored by an swait record for transitions from Acquire to Done to update EndExposureTime

Since the StartExposureTime and EndExposureTime PVs are already in the detector's XML attributes file, both values, contemporary for the current image set, will be written into the NeXus file by the HDF Writer plugin.

prjemian commented 4 years ago

In an offline development workstation, I've demonstrated that the time stamps will be update on demand when the swait record is used to trigger writing the time stamp:

database ``` record(stringin, "$(P)$(R)Acquire_TimeStamp") { field(DESC, "Acquire timestamp, ISO8601") field(DTYP, "Soft Timestamp") field(INP, "@%Y-%m-%dT%H:%M:%S.%09f") } record(swait, "$(P)$(R)Acquire_TimeStampTrigger") { field(DESC, "when AD camera Acquire processes") field(INAN, "$(P)$(R)Acquire") field(SCAN, "I/O Intr") field(INAP, "Yes") field(CALC, "A") field(OOPT, "On Change") field(OUTN, "$(P)$(R)Acquire_TimeStamp.PROC") } ```
camonitor with acquire times: 0.2, 0.02, 0.002, 0.0002 s ``` adsky:cam1:AcquireTime 2020-06-29 11:53:12.520139 0.2 adsky:cam1:Acquire 2020-06-29 11:53:17.500201 Acquire adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:17.500856 1 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:17.500945 2020-06-29T11:53:17.500935495 adsky:cam1:Acquire 2020-06-29 11:53:17.706038 Done adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:17.706268 0 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:17.706478 2020-06-29T11:53:17.706470762 adsky:cam1:AcquireTime 2020-06-29 11:53:23.443010 0.02 adsky:cam1:Acquire 2020-06-29 11:53:24.884157 Acquire adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:24.884835 1 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:24.884883 2020-06-29T11:53:24.884867562 adsky:cam1:Acquire 2020-06-29 11:53:24.904450 Done adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:24.904750 0 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:24.905188 2020-06-29T11:53:24.905179050 adsky:cam1:AcquireTime 2020-06-29 11:53:29.334267 0.002 adsky:cam1:Acquire 2020-06-29 11:53:30.958725 Acquire adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:30.959767 1 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:30.959911 2020-06-29T11:53:30.959897742 adsky:cam1:Acquire 2020-06-29 11:53:30.961189 Done adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:30.961433 0 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:30.961530 2020-06-29T11:53:30.961521657 adsky:cam1:AcquireTime 2020-06-29 11:53:36.314641 0.0002 adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:37.619314 1 adsky:cam1:Acquire 2020-06-29 11:53:37.618442 Acquire adsky:cam1:Acquire 2020-06-29 11:53:37.619251 Done adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:37.619776 2020-06-29T11:53:37.619615060 adsky:cam1:Acquire_TimeStampTrigger 2020-06-29 11:53:37.619838 0 adsky:cam1:Acquire_TimeStamp 2020-06-29 11:53:37.619917 2020-06-29T11:53:37.619912823 ```

Next, will create database for separate StartExposureTime and EndExposureTime PVs to match original request.

prjemian commented 4 years ago

Ok, here is the IOC configuration:

acquire_timestamp.db database ``` # record start/end times of area detector acquisition # # times are strings, formatted per ISO-8601 as used by NeXus # # ====== =============================================== # macro meaning # ====== =============================================== # PRE IOC prefix hosting this database (such as lax:) # D database PREFIX (such as SAXS:) # AD IOC prefix of area detector # CAM CAM module prefix (almost always cam1:) # ====== =============================================== record(stringin, "$(PRE)$(D)StartExposureTime") { field(DESC, "Acquire start timestamp") field(DTYP, "Soft Timestamp") field(INP, "@%Y-%m-%dT%H:%M:%S.%09f") } record(stringin, "$(PRE)$(D)EndExposureTime") { field(DESC, "Acquire end timestamp") field(DTYP, "Soft Timestamp") field(INP, "@%Y-%m-%dT%H:%M:%S.%09f") } record(swait, "$(PRE)$(D)StartExposureTrigger") { field(DESC, "when AD camera Acquire starts") field(INAN, "$(AD)$(CAM)Acquire") field(SCAN, "I/O Intr") field(INAP, "Yes") field(CALC, "A") field(OOPT, "Transition To Non-zero") field(OUTN, "$(PRE)$(D)StartExposureTime.PROC") } record(swait, "$(PRE)$(D)EndExposureTrigger") { field(DESC, "when AD camera Acquire ends") field(INAN, "$(AD)$(CAM)Acquire") field(SCAN, "I/O Intr") field(INAP, "Yes") field(CALC, "A") field(OOPT, "Transition To Zero") field(OUTN, "$(PRE)$(D)EndExposureTime.PROC") } ```
example st.cmd configuration ``` # ====== =============================================== # macro meaning # ====== =============================================== # PRE IOC prefix hosting this database (such as lax:) # D database PREFIX (such as SAXS:) # AD IOC prefix of area detector # CAM CAM module prefix (almost always cam1:) # ====== =============================================== dbLoadRecords("$(TOP)/iocBoot/$(IOC)/timestamp.db","PRE=s61:,D=WAXS:,AD=adsky:,CAM=cam1:") ```
console test (as before) ``` (base) mintadmin@mint-vm:~$ camonitor adsky:cam1:Acquire{Time,} s61:WAXS:{Start,End}Exposure{Trigger,Time} adsky:cam1:AcquireTime 2020-06-29 12:25:20.968821 1.1 adsky:cam1:Acquire 2020-06-29 12:24:31.537287 Done s61:WAXS:StartExposureTrigger 2020-06-29 12:24:31.537446 0 s61:WAXS:StartExposureTime 2020-06-29 12:24:31.537480 2020-06-29T12:24:31.537467263 s61:WAXS:EndExposureTrigger 2020-06-29 12:24:31.537448 0 s61:WAXS:EndExposureTime 2020-06-29 12:24:31.537489 2020-06-29T12:24:31.537487182 adsky:cam1:Acquire 2020-06-29 12:25:28.139157 Acquire s61:WAXS:StartExposureTrigger 2020-06-29 12:25:28.139837 1 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:28.139845 1 s61:WAXS:StartExposureTime 2020-06-29 12:25:28.139867 2020-06-29T12:25:28.139859464 adsky:cam1:Acquire 2020-06-29 12:25:29.240344 Done s61:WAXS:StartExposureTrigger 2020-06-29 12:25:29.240875 0 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:29.240895 0 s61:WAXS:EndExposureTime 2020-06-29 12:25:29.241257 2020-06-29T12:25:29.241241803 adsky:cam1:AcquireTime 2020-06-29 12:25:40.293889 0.11 adsky:cam1:Acquire 2020-06-29 12:25:43.290137 Acquire s61:WAXS:StartExposureTrigger 2020-06-29 12:25:43.290811 1 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:43.290828 1 s61:WAXS:StartExposureTime 2020-06-29 12:25:43.290873 2020-06-29T12:25:43.290855579 adsky:cam1:Acquire 2020-06-29 12:25:43.400566 Done s61:WAXS:StartExposureTrigger 2020-06-29 12:25:43.400779 0 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:43.400791 0 s61:WAXS:EndExposureTime 2020-06-29 12:25:43.400810 2020-06-29T12:25:43.400803098 adsky:cam1:AcquireTime 2020-06-29 12:25:47.089794 0.011 adsky:cam1:Acquire 2020-06-29 12:25:50.264769 Acquire s61:WAXS:StartExposureTrigger 2020-06-29 12:25:50.266110 1 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:50.266117 1 s61:WAXS:StartExposureTime 2020-06-29 12:25:50.266292 2020-06-29T12:25:50.266283887 adsky:cam1:Acquire 2020-06-29 12:25:50.276402 Done s61:WAXS:StartExposureTrigger 2020-06-29 12:25:50.276801 0 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:50.276818 0 s61:WAXS:EndExposureTime 2020-06-29 12:25:50.276856 2020-06-29T12:25:50.276848365 adsky:cam1:AcquireTime 2020-06-29 12:25:56.293131 0.0011 adsky:cam1:Acquire 2020-06-29 12:25:59.255956 Acquire s61:WAXS:StartExposureTrigger 2020-06-29 12:25:59.256382 1 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:59.256391 1 s61:WAXS:StartExposureTime 2020-06-29 12:25:59.256414 2020-06-29T12:25:59.256405742 adsky:cam1:Acquire 2020-06-29 12:25:59.257766 Done s61:WAXS:StartExposureTrigger 2020-06-29 12:25:59.258094 0 s61:WAXS:EndExposureTrigger 2020-06-29 12:25:59.258116 0 s61:WAXS:EndExposureTime 2020-06-29 12:25:59.258177 2020-06-29T12:25:59.258168296 adsky:cam1:AcquireTime 2020-06-29 12:26:04.751942 0.00011 adsky:cam1:Acquire 2020-06-29 12:26:07.521181 Acquire adsky:cam1:Acquire 2020-06-29 12:26:07.522303 Done s61:WAXS:StartExposureTrigger 2020-06-29 12:26:07.522644 1 s61:WAXS:EndExposureTrigger 2020-06-29 12:26:07.522652 1 s61:WAXS:StartExposureTrigger 2020-06-29 12:26:07.522653 0 s61:WAXS:EndExposureTrigger 2020-06-29 12:26:07.522654 0 s61:WAXS:StartExposureTime 2020-06-29 12:26:07.522757 2020-06-29T12:26:07.522746669 s61:WAXS:EndExposureTime 2020-06-29 12:26:07.522765 2020-06-29T12:26:07.522762989 ```
prjemian commented 4 years ago

Now, need to test that these values are recorded into the HDF5 file. ...

prjemian commented 4 years ago

XML Attributes file:

<?xml version="1.0" standalone="no" ?>
<!-- Attributes -->
<Attributes
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:noNamespaceSchemaLocation="../../../../../ADCore/XML_schema/NDAttributes.xsd"
    >

    <Attribute 
        name="AcquireTime"
        type="EPICS_PV"
        source="adsky:cam1:AcquireTime"
        dbrtype="DBR_NATIVE"
        description="Camera acquire time"/>
    <Attribute 
        name="StartExposureTime"
        type="EPICS_PV"
        source="s61:WAXS:StartExposureTime"
        dbrtype="DBR_NATIVE"
        description="Camera start acquire timestamp"/>
    <Attribute 
        name="EndExposureTime"
        type="EPICS_PV"
        source="s61:WAXS:EndExposureTime"
        dbrtype="DBR_NATIVE"
        description="Camera end acquire timestamp"/>
</Attributes>
prjemian commented 4 years ago

HDF5 file structure with attributes files and default layout (not specified by user):

/tmp/docker_ioc/iocadsky/tmp/timestamps_000.h5 : NeXus data file
  entry:NXentry
    data:NXdata
      data:NX_UINT8[1024,1024] = [ ... ]
    instrument:NXinstrument
      NDAttributes:NXcollection
        AcquireTime:NX_FLOAT64 = 0.01
        EndExposureTime:NX_CHAR[256] = 2020-06-29T12:26:07.522762989
        NDArrayEpicsTSSec:NX_UINT32 = 962300839
        NDArrayEpicsTSnSec:NX_UINT32 = 827523058
        NDArrayTimeStamp:NX_FLOAT64 = 962300839.8171176
        NDArrayUniqueId:NX_INT32 = 353
        StartExposureTime:NX_CHAR[256] = 2020-06-29T12:47:19.817772956
      detector:NXdetector
        data:NX_UINT8[1024,1024] = [ ... ]
        NDAttributes:NXcollection
          ColorMode:NX_INT32 = 0
      performance
        timestamp:NX_FLOAT64[1,5] = [ ... ]
prjemian commented 4 years ago

The EndExposureTime is before the StartExposureTime. We need a layout file to change this.

prjemian commented 4 years ago

Using the layout from ADSimDetector:

<?xml version="1.0" standalone="no" ?>
<hdf5_layout
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:noNamespaceSchemaLocation="../../../../../ADCore/XML_schema/hdf5_xml_layout_schema.xsd"
    >
  <group name="entry"> 
    <attribute name="NX_class" source="constant" value="NXentry" type="string"></attribute> 
    <group name="instrument"> 
      <attribute name="NX_class" source="constant" value="NXinstrument" type="string"></attribute> 
      <group name="detector"> 
        <attribute name="NX_class" source="constant" value="NXdetector" type="string"></attribute> 
        <dataset name="data" source="detector" det_default="true"> 
          <attribute name="NX_class" source="constant" value="SDS" type="string"></attribute> 
          <attribute name="signal" source="constant" value="1" type="int"></attribute> 
          <attribute name="target" source="constant" value="/entry/instrument/detector/data" type="string"></attribute> 
        </dataset> 
        <group name="NDAttributes"> 
          <attribute name="NX_class" source="constant" value="NXcollection" type="string"></attribute> 
          <dataset name="StartExposureTime" source="ndattribute" ndattribute="StartExposureTime" />
          <dataset name="EndExposureTime" source="ndattribute" ndattribute="EndExposureTime" when="OnFileClose" />
        </group>          <!-- end group NDAttribute --> 
      </group>            <!-- end group detector --> 
      <group name="NDAttributes" ndattr_default="true"> 
        <attribute name="NX_class" source="constant" value="NXcollection" type="string"></attribute> 
      </group>            <!-- end group NDAttribute (default) --> 
      <group name="performance"> 
        <dataset name="timestamp" source="ndattribute"></dataset> 
      </group>            <!-- end group performance --> 
    </group>              <!-- end group instrument --> 
    <group name="data"> 
      <attribute name="NX_class" source="constant" value="NXdata" type="string"></attribute> 
      <hardlink name="data" target="/entry/instrument/detector/data"></hardlink>
      <!-- The "target" attribute in /entry/instrument/detector/data is used to 
           tell Nexus utilities that this is a hardlink -->
    </group>              <!-- end group data --> 
  </group>                <!-- end group entry -->
</hdf5_layout>

Still out of order:

/tmp/docker_ioc/iocadsky/tmp/timestamps_001.h5 : NeXus data file
  entry:NXentry
    data:NXdata
      data --> b'/entry/instrument/detector/data'
    instrument:NXinstrument
      NDAttributes:NXcollection
        AcquireTime:NX_FLOAT64 = 0.01
        ColorMode:NX_INT32 = 0
        NDArrayEpicsTSSec:NX_UINT32 = 962301431
        NDArrayEpicsTSnSec:NX_UINT32 = 917622428
        NDArrayTimeStamp:NX_FLOAT64 = 962301431.9073813
        NDArrayUniqueId:NX_INT32 = 354
        timestamp:NX_FLOAT64[1,5] = [ ... ]
      detector:NXdetector
        data --> /entry/instrument/detector/data
        NDAttributes:NXcollection
          EndExposureTime:NX_CHAR[256] = 2020-06-29T12:47:19.829206307
          StartExposureTime:NX_CHAR[256] = 2020-06-29T12:57:11.908051543
      performance
prjemian commented 4 years ago

Even with the HDF5 blocking, the file is closed before EndExposureTime is updated.

Summary: Don't expect this in the HDF5 file. At least not to be useful.

prjemian commented 4 years ago

Noting that camonitor can sometimes report updates out of chronological order, this is a sorted time sequence:

adsky:cam1:Acquire             2020-06-29 13:16:56.393667 Acquire  
s61:WAXS:StartExposureTrigger  2020-06-29 13:16:56.394085 1  
s61:WAXS:EndExposureTrigger    2020-06-29 13:16:56.394165 1  
s61:WAXS:StartExposureTime     2020-06-29 13:16:56.394429 2020-06-29T13:16:56.394410391  
adsky:cam1:Acquire             2020-06-29 13:16:56.404842 Done  
adsky:HDF1:WriteFile_RBV       2020-06-29 13:16:56.404875 Writing STATE MINOR
s61:WAXS:StartExposureTrigger  2020-06-29 13:16:56.405129 0  
s61:WAXS:EndExposureTrigger    2020-06-29 13:16:56.405145 0  
s61:WAXS:EndExposureTime       2020-06-29 13:16:56.406312 2020-06-29T13:16:56.406304973  
adsky:HDF1:FullFileName_RBV 2020-06-29 13:16:56.409652 /tmp/timestamps_007.h5  
adsky:HDF1:WriteFile_RBV       2020-06-29 13:16:56.409771 Done  

It shows that Writing has started before the s61:WAXS:EndExposureTime has updated.

I don't know how to impose any delay here to reverse this order.

jilavsky commented 4 years ago

Just note to ourselves. Once solution is found, we need to implement for WAXS, SAXS, and USAXS - same set of PVs is also needed in Flyscans, in spec and BlueSky ;-) So we are looking for generic solution here...

prjemian commented 4 years ago

Exactly. This needs to be re-useable both at your instrument and other instruments, too. So, it's part of the design here. Last challenge is to figure out how to make this happen before HDF starts writing the file, it seems.

prjemian commented 4 years ago

@MarkRivers: We're back to the point of wanting to record the start and end of exposure as string time stamps in our HDF5 file from area detector.

We have a separate stringin PV for each and these are in the attributes XML file.
The StartExposureTime is written when AD:cam1:Acquire goes to 1, then EndExposureTime is written when AD:cam1:Acquire goes to 0.
AD:cam1:WaitForPlugins is No, so that theEndExposureTime is updated before the HDF5 file is closed.
Still, we can't update that fast enough to get the revisedEndExposureTime into the layout for onFileClose.

Any advice?

MarkRivers commented 4 years ago

We have a separate stringin PV for each and these are in the attributes XML file.

Which attributes XML file, the one for the detector or the one for the HDF5 plugin?

Can you please run the following test when you see the problem.

camonitor -tc EndExposureTime AD:cam1:Acquire AD:HDF1:WriteFile_RBV AD:HDF1:Capture_RBV

prjemian commented 4 years ago

I put the attributes into the CAM module. Should go in HDF5 Writer instead? I'll run that diagnostic next.

prjemian commented 4 years ago

raw:

adsky:cam1:Acquire             (2020-06-29 15:04:27.092920) Acquire  
adsky:cam1:AcquireBusy         (2020-06-29 15:04:27.092961) Acquiring STATE MINOR
adsky:cam1:StatusMessage_RBV (2020-06-29 15:04:27.092969) Acquiring data  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:04:27.092977) Acquire  
s61:WAXS:StartExposureTrigger  (2020-06-29 15:04:27.092992) 1  
s61:WAXS:EndExposureTrigger    (2020-06-29 15:04:27.093002) 1  
s61:WAXS:StartExposureTime     (2020-06-29 15:04:27.093009) 2020-06-29T15:04:27.092679728  
s61:WAXS:StartExposureTrigger  (2020-06-29 15:04:27.109798) 0  
s61:WAXS:EndExposureTrigger    (2020-06-29 15:04:27.109833) 0  
s61:WAXS:EndExposureTime       (2020-06-29 15:04:27.109838) 2020-06-29T15:04:27.107379316  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:04:27.109943) Readout  
adsky:cam1:StatusMessage_RBV (2020-06-29 15:04:27.109954) Waiting for acquisition  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:04:27.109959) Idle  
adsky:cam1:Acquire             (2020-06-29 15:04:27.109962) Done  
adsky:HDF1:WriteFile_RBV       (2020-06-29 15:04:27.109968) Writing STATE MINOR
adsky:cam1:AcquireBusy         (2020-06-29 15:04:27.109972) Done  
adsky:HDF1:FullFileName_RBV (2020-06-29 15:04:27.113431) /tmp/timestamps_017.h5  
adsky:HDF1:WriteFile_RBV       (2020-06-29 15:04:27.113546) Done  
prjemian commented 4 years ago

Clipboard01

prjemian commented 4 years ago
  1. restarted the area detector IOC
  2. loaded attribute XML file into HDF plugin
  3. loaded layout XML file into HDF plugin
  4. took an image

The order looks right now: EndExposureTime > StartExposureTime

/tmp/docker_ioc/iocadsky/tmp/timestamp_003.h5 : NeXus data file
  entry:NXentry
    data:NXdata
      data --> b'/entry/instrument/detector/data'
    instrument:NXinstrument
      NDAttributes:NXcollection
        AcquireTime:NX_FLOAT64 = 0.1
        ColorMode:NX_INT32 = 0
        EndExposureTime:NX_CHAR[256] = 2020-06-29T15:32:24.740323227
        NDArrayEpicsTSSec:NX_UINT32 = 962310744
        NDArrayEpicsTSnSec:NX_UINT32 = 739296895
        NDArrayTimeStamp:NX_FLOAT64 = 962310744.6369283
        NDArrayUniqueId:NX_INT32 = 4
        StartExposureTime:NX_CHAR[256] = 2020-06-29T15:32:24.637291038
        timestamp:NX_FLOAT64[1,5] = [ ... ]
      detector:NXdetector
        data --> /entry/instrument/detector/data
      performance

camonitor trace:

adsky:cam1:Acquire             (2020-06-29 15:32:24.637115) Acquire  
adsky:cam1:AcquireBusy         (2020-06-29 15:32:24.637238) Acquiring STATE MINOR
adsky:cam1:StatusMessage_RBV (2020-06-29 15:32:24.637248) Acquiring data  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:32:24.637257) Acquire  
s61:WAXS:StartExposureTrigger  (2020-06-29 15:32:24.637276) 1  
s61:WAXS:EndExposureTrigger    (2020-06-29 15:32:24.637286) 1  
s61:WAXS:StartExposureTime     (2020-06-29 15:32:24.637399) 2020-06-29T15:32:24.637291038  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:32:24.739737) Readout  
adsky:cam1:StatusMessage_RBV (2020-06-29 15:32:24.740078) Waiting for acquisition  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:32:24.740121) Idle  
adsky:cam1:Acquire             (2020-06-29 15:32:24.740129) Done  
adsky:HDF1:WriteFile_RBV       (2020-06-29 15:32:24.740135) Writing STATE MINOR
adsky:cam1:AcquireBusy         (2020-06-29 15:32:24.740143) Done  
s61:WAXS:StartExposureTrigger  (2020-06-29 15:32:24.740158) 0  
s61:WAXS:EndExposureTrigger    (2020-06-29 15:32:24.740169) 0  
s61:WAXS:EndExposureTime       (2020-06-29 15:32:24.740443) 2020-06-29T15:32:24.740323227  
adsky:HDF1:FullFileName_RBV (2020-06-29 15:32:24.746714) /tmp/timestamp_003.h5  
adsky:HDF1:WriteFile_RBV       (2020-06-29 15:32:24.746748) Done  
prjemian commented 4 years ago

Retries, sometimes the EndExposureTimestamp is stale:

/tmp/docker_ioc/iocadsky/tmp/timestamp_008.h5 : NeXus data file
  entry:NXentry
    data:NXdata
      data:NX_UINT8[1,1024,1024] = [ ... ]
    instrument:NXinstrument
      NDAttributes:NXcollection
        AcquireTime:NX_FLOAT64 = 0.01
        ColorMode:NX_INT32 = 0
        EndExposureTime:NX_CHAR[256] = 2020-06-29T15:39:21.544578650
        NDArrayEpicsTSSec:NX_UINT32 = 962311216
        NDArrayEpicsTSnSec:NX_UINT32 = 905580911
        NDArrayTimeStamp:NX_FLOAT64 = 962311216.8951572
        NDArrayUniqueId:NX_INT32 = 9
        StartExposureTime:NX_CHAR[256] = 2020-06-29T15:40:16.895446484
        timestamp:NX_FLOAT64[1,5] = [ ... ]
      detector:NXdetector
        data:NX_UINT8[1,1024,1024] = [ ... ]
      performance
prjemian commented 4 years ago

Could be it is stale when I have not pressed Capture before Acquire? Not so. Here is example when Capture before Acquire but End < Start:

camonitor:

adsky:HDF1:Capture_RBV         (2020-06-29 15:43:41.742097) Capturing STATE MINOR
adsky:HDF1:FullFileName_RBV    (2020-06-29 15:43:41.742146) 0  
adsky:cam1:StatusMessage_RBV (2020-06-29 15:43:43.393940) Acquiring data  
adsky:cam1:Acquire             (2020-06-29 15:43:43.393990) Acquire  
adsky:cam1:AcquireBusy         (2020-06-29 15:43:43.393998) Acquiring STATE MINOR
adsky:cam1:DetectorState_RBV   (2020-06-29 15:43:43.394006) Acquire  
s61:WAXS:StartExposureTrigger  (2020-06-29 15:43:43.395571) 1  
s61:WAXS:EndExposureTrigger    (2020-06-29 15:43:43.395649) 1  
s61:WAXS:StartExposureTime     (2020-06-29 15:43:43.395662) 2020-06-29T15:43:43.394329451  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:43:43.404936) Readout  
adsky:cam1:StatusMessage_RBV (2020-06-29 15:43:43.404975) Waiting for acquisition  
adsky:cam1:DetectorState_RBV   (2020-06-29 15:43:43.404983) Idle  
adsky:cam1:Acquire             (2020-06-29 15:43:43.404990) Done  
adsky:HDF1:WriteFile_RBV       (2020-06-29 15:43:43.404997) Writing STATE MINOR
adsky:cam1:AcquireBusy         (2020-06-29 15:43:43.405004) Done  
s61:WAXS:StartExposureTrigger  (2020-06-29 15:43:43.408694) 0  
s61:WAXS:EndExposureTrigger    (2020-06-29 15:43:43.408733) 0  
s61:WAXS:EndExposureTime       (2020-06-29 15:43:43.408741) 2020-06-29T15:43:43.405108071  
adsky:HDF1:FullFileName_RBV (2020-06-29 15:43:43.412516) /tmp/timestamp_012.h5  
adsky:HDF1:WriteFile_RBV       (2020-06-29 15:43:43.412554) Done  
adsky:HDF1:Capture_RBV         (2020-06-29 15:43:43.412563) Done  

HDF5 contents:

/tmp/docker_ioc/iocadsky/tmp/timestamp_012.h5 : NeXus data file
  entry:NXentry
    data:NXdata
      data:NX_UINT8[1,1024,1024] = [ ... ]
    instrument:NXinstrument
      NDAttributes:NXcollection
        AcquireTime:NX_FLOAT64 = 0.01
        ColorMode:NX_INT32 = 0
        EndExposureTime:NX_CHAR[256] = 2020-06-29T15:43:24.515425030
        NDArrayEpicsTSSec:NX_UINT32 = 962311423
        NDArrayEpicsTSnSec:NX_UINT32 = 404532488
        NDArrayTimeStamp:NX_FLOAT64 = 962311423.3938062
        NDArrayUniqueId:NX_INT32 = 13
        StartExposureTime:NX_CHAR[256] = 2020-06-29T15:43:43.394329451
        timestamp:NX_FLOAT64[1,5] = [ ... ]
      detector:NXdetector
        data:NX_UINT8[1,1024,1024] = [ ... ]
      performance

It is not consistent.

MarkRivers commented 4 years ago

Who is setting the EndExposureTime PV, SPEC or something in the IOC? What triggers it?

It seems like this is what should be happening: 1) The detector stops 2) Something detects this and sets the EndExposureTime PV 3) The NDArray callback to the HDF5 file plugin occurs. 4) The HDF5 file plugin gets a CA monitor on the EndExposureTime PV 5) The HDF5 file plugin reads its NDAttributes 6) HDF5 file plugins writes the NDArray and the attributes.

There are lots of race conditions here.

Why do you need to EndExposureTime PV? The NDArray.timeStamp and NDArray.epicsTS attributes are the timestamps when the acquisition finished. They are always saved in the HDF5 file.

prjemian commented 4 years ago

The timestamp PVs (and associated triggers) are run as a database in a separate IOC. See https://github.com/APS-USAXS/ipython-usaxs/issues/351#issuecomment-651259079

The area detector IOC is running in a docker container on workstation mint-vm. The IOC with the timestamps is running directly on workstation mint-vm.

Perhaps this is the best advice and we can avoid trying to get the end time altogether by this very indirect method:

The NDArray.timeStamp and NDArray.epicsTS attributes are the timestamps when the acquisition finished. They are always saved in the HDF5 file.

@jilavsky: Will either (or both of) the two NDArray attributes meet your needs?

MarkRivers commented 4 years ago

You can easily convert the EPICS timestamp into an ASCII date. From @prjemian example where it appeared to be working above:

        EndExposureTime:NX_CHAR[256] = 2020-06-29T15:32:24.740323227
        NDArrayEpicsTSSec:NX_UINT32 = 962310744
        NDArrayEpicsTSnSec:NX_UINT32 = 739296895

EPICS timestamps begin on Jan. 1, 1990. To convert to Posix timestamps that begin on Jan. 1, 1970 you add 631152000.

>>> import datetime
>>> t = datetime.datetime.fromtimestamp(962310744 + 631152000)
>>> t.strftime("%Y-%m-%d %H:%M:%S")
'2020-06-29 15:32:24'

You now need to add the nanoseconds = 0.739296895 seconds.

So the timestamp is

2020-06-29 15:32:24.739296895

That is within 1 ms of the EndTimeStamp

 2020-06-29T15:32:24.740323227
jilavsky commented 4 years ago

Either of those NDarrays is fine - in my case, we do not need to worry about ns ;-)

prjemian commented 4 years ago

So, we'll delete the end time and also make a small database (re-useable) to get ISO8601-formatted timestamp PVs for the start time of the various detectors. We could run that database on ioclax, no?

prjemian commented 4 years ago

EndExposureTime PV deleted from detector attributes files in https://github.com/APS-USAXS/AreaDetectorConfig/commit/dd92e59e9bdfb16ee33cf7eab0ea5ee58620888f

prjemian commented 4 years ago

above, it was mentioned that

also make a small database ...

This needs to be a separate issue due to its specific nature.

prjemian commented 4 years ago

Once we get that database, we'll add the PVs to the area detector attributes files. That will close this issue.

prjemian commented 4 years ago

Confirmation of the order number (also shows the metadata updated):

In [1]: from instrument.plans.sample_imaging import record_sample_image_on_demand

In [2]: newUser("Pete")
I Fri-17:03:18 - Change working directory to /share1/USAXS_data/2020-09/09_11_Pete
I Fri-17:03:18 - SPEC file name : 09_11_Pete.dat
I Fri-17:03:18 - File will be created at end of next bluesky scan.
W Fri-17:03:18 - No unexpired ESAFs found that match user Pete
W Fri-17:03:18 - No unexpired proposals found that match user Pete
W Fri-17:03:18 - APSBSS not updated.
W Fri-17:03:18 - You should check that PVs in APSBSS contain correct information.
Out[2]: '/share1/USAXS_data/2020-09/09_11_Pete'

In [3]: md = {}

In [4]: terms.FlyScan.order_number
Out[4]: EpicsSignal(read_pv='9idcLAX:USAXS:FS_OrderNumber', name='terms_FlyScan_order_number', parent='terms_FlyScan', timestamp=1598026643.046929, auto_monitor=False, string=False, write_pv='9idcLAX:USAXS:FS_OrderNumber', limits=False, put_complete=False)

In [5]: terms.FlyScan.order_number.get()
Out[5]: 1

In [6]: %mov terms.FlyScan.order_number 42

In [7]: RE(record_sample_image_on_demand("Jemian", "sample_name", md))
D Fri-17:04:20 - make_filename: /mnt/share1/USAXS_data/2020-09/09_11_Pete/09_11_Pete_Jemian/sample_name_0042.jpg
D Fri-17:04:20 - write_path: /mnt/share1/USAXS_data/2020-09/09_11_Pete/09_11_Pete_Jemian/
Out[7]: ()                                                                                                                                  

In [8]: 
prjemian commented 4 years ago

FYI, example database for 9idFLY2: has been running all last week. Here is camonitor output from the past few minutes:

usaxs@usaxscontrol /share1/USAXS_data $ cainfo 9idFLY2:acquire_started:timestamp
9idFLY2:acquire_started:timestamp
    State:            connected
    Host:             usaxsserver.xray.aps.anl.gov:41586
    Access:           read, write
    Native data type: DBF_STRING
    Request type:     DBR_STRING
    Element count:    1
usaxs@usaxscontrol /share1/USAXS_data $ camonitor 9idFLY2:acquire_started:timestamp
9idFLY2:acquire_started:timestamp 2020-09-19 09:58:46.885460 2020-09-19 09:58:46.885
9idFLY2:acquire_started:timestamp 2020-09-19 09:59:32.039760 2020-09-19 09:59:32.040
9idFLY2:acquire_started:timestamp 2020-09-19 10:00:07.182118 2020-09-19 10:00:07.182
9idFLY2:acquire_started:timestamp 2020-09-19 10:00:42.224578 2020-09-19 10:00:42.225
9idFLY2:acquire_started:timestamp 2020-09-19 10:01:17.366120 2020-09-19 10:01:17.366
9idFLY2:acquire_started:timestamp 2020-09-19 10:02:06.724864 2020-09-19 10:02:06.725
9idFLY2:acquire_started:timestamp 2020-09-19 10:02:51.979579 2020-09-19 10:02:51.980
9idFLY2:acquire_started:timestamp 2020-09-19 10:03:26.920422 2020-09-19 10:03:26.920
9idFLY2:acquire_started:timestamp 2020-09-19 10:04:02.061577 2020-09-19 10:04:02.062
9idFLY2:acquire_started:timestamp 2020-09-19 10:04:43.209233 2020-09-19 10:04:43.209
9idFLY2:acquire_started:timestamp 2020-09-19 10:05:18.350462 2020-09-19 10:05:18.350
9idFLY2:acquire_started:timestamp 2020-09-19 10:05:53.392766 2020-09-19 10:05:53.393

This is an example to test the capability and has not been made into production IOCs (IOCs that restart automatically) nor has its PV been added to any instrument data files. BUT, looks like it satisifies the request. @jilavsky Agree?

prjemian commented 4 years ago
usaxs@usaxscontrol /share1/USAXS_data $ caget 9idFLY2:acquire_started:timestamp
9idFLY2:acquire_started:timestamp 2020-09-19 10:07:03.576
prjemian commented 4 years ago

As noted, we should run a separate instance of this database for each area detector. We can do all that in IOC 9idcLAX:.

prjemian commented 4 years ago

The example is this process (running in a screen session on usaxsserver):

usaxs@usaxsserver ~ $ ps -ef | grep softIoc | grep FLY2
usaxs     6815  6507  0 Sep14 pts/13   00:37:11 softIoc -m A=9idFLY2:cam1:Acquire,CALC=A>0.5,P=9idFLY2:,D=acquire_started:,OOPT=Transition To Non-zero -d timestamp.db

It is in screen process 6506.pts-12.usaxsserver:

usaxs@usaxsserver ~ $ screen -ls
There are screens on:
        1926.ioc9idFLY1 (Detached)
        31184.ioc9idFLY2        (Detached)
        6506.pts-12.usaxsserver (Detached)
        20736.9idcPI    (Detached)
        10909.ioc9idcbss        (Detached)
        16928.9idcEXP   (Detached)
        16855.ioc9idBLEPS       (Detached)
        16795.9id_bss   (Detached)
        16739.ioc9idaPLC        (Detached)
        16520.9idcTEMP  (Detached)
        16390.9idcSample        (Detached)
        2583.ioc9idcRIO (Detached)
12 Sockets in /var/run/screen/S-usaxs.