Get start timestamp and add it to header

CHANGELOG.rst

@@ -12,6 +12,7 @@ Unreleased
 
 - Fix error in scalar value formatting (github issue #29)
 - Add ``*BITS?`` command to return available bit bus entry names
+- Capture timestamp when PCAP becomes armed and enabled
 
 3.0a3_ - 2022-05-03
 -------------------

config_d/registers

@@ -4,7 +4,7 @@
 # set in *DRV changes or if the FPGA changes in any other way that requires a
 # driver change.  The driver will refuse to load if this does not match the
 # value returned by *DRV.DRV_COMPAT_VERSION
-DRIVER_COMPAT_VERSION = 0
+DRIVER_COMPAT_VERSION = 1
 
 # PandA Blocks compatibility version.  This is checked by the server when
 # loading the registers file, and should be updated when the interface to the

driver/panda_device.h

@@ -30,3 +30,5 @@ struct panda_block {
 #define PANDA_COMPLETION_FRAMING    2
 #define PANDA_COMPLETION_DMA        4
 #define PANDA_COMPLETION_OVERRUN    8
+
+#define PANDA_GET_START_TS _IOR('P', 4, struct timespec64)

driver/panda_stream.c

@@ -15,6 +15,7 @@
 #include <linux/delay.h>
 #include <linux/uaccess.h>
 #include <asm/atomic.h>
+#include <linux/time.h>
 
 #include "error.h"
 #include "panda.h"
@@ -27,12 +28,10 @@
 static int block_shift = 9;     // In log2 pages, default is 2MB
 static int block_count = 32;    // Number of buffers in circular buffer
 static int block_timeout = 12500000;    // 100ms in 125MHz FPGA clock ticks
-static int verbose = 0;
 
 module_param(block_shift, int, S_IRUGO);
 module_param(block_count, int, S_IRUGO);
 module_param(block_timeout, int, S_IRUGO);
-module_param(verbose, int, S_IRUGO);
 
 #define BUF_BLOCK_SIZE      (1U << (block_shift + PAGE_SHIFT))
 
@@ -80,6 +79,7 @@ struct stream_open {
     int isr_block_index;        // Block currently being written by hardware
     bool stream_active;         // If not set, any interrupts are unexpected
     uint32_t completion;        // Copy of final interrupt status register
+    struct timespec64 start_ts; // timestamp when PCAP becomes armed & enabled
 
     /* Reader status. */
     int read_block_index;       // Block being read
@@ -124,26 +124,28 @@ static inline int step_index(int ix)
  * timeout, or because data transfer is (currently) complete.
  *    The interrupt status register records the following information:
  *
- *   31              8 7 6 5 4 3 2 1 0
+ *   31            9 8 7 6 5 4 3 2 1 0
  *  +-----------------+-+-+-+-+-+-+-+-+
- *  | sample count    | | | | | | | | |
+ *  | sample count  | | | | | | | | | |
  *  +-----------------+-+-+-+-+-+-+-+-+
- *                     | | | | | | | +-- Transfer complete, no more interrupts
- *                     | | | | | | +---- Experiment disarmed
- *                     | | | | | +------ Capture framing error
- *                     | | | | +-------- DMA error
- *                     | | | +---------- DMA address not written in time
- *                     | | +------------ Timeout
- *                     | +-------------- Block complete
- *                     +---------------- Ongoing DMA (used to validate unload)
+ *                   | | | | | | | | +-- Transfer complete, no more interrupts
+ *                   | | | | | | | +---- Experiment disarmed
+ *                   | | | | | | +------ Capture framing error
+ *                   | | | | | +-------- DMA error
+ *                   | | | | +---------- DMA address not written in time
+ *                   | | | +------------ Timeout
+ *                   | | +-------------- Block complete
+ *                   | +---------------- Ongoing DMA (used to validate unload)
+ *                   +------------------ Start event (used to capture timestamp)
  * Bit 1 records whether further interrupts are to be expected.  If this bit is
  * set then one of bits 4:1 is set to record the completion reason, unless the
  * experiment completed normally, in which case they're all set to zero.  The
  * sample count is in 4-byte transfers. */
 #define IRQ_STATUS_DONE(status)         ((bool) ((status) & 0x01))
-#define IRQ_STATUS_LENGTH(status)       ((size_t) (((status) >> 8) << 2))
+#define IRQ_STATUS_LENGTH(status)       ((size_t) (((status) >> 9) << 2))
 #define IRQ_STATUS_DMA_ACTIVE(status)   ((bool) ((status) & 0x80))
 #define IRQ_STATUS_COMPLETION(status)   ((size_t) (((status) >> 1) & 0x0F))
+#define IRQ_STATUS_START_EVENT(status)  ((bool) ((status)  & 0x100))
 
 
 static void advance_isr_block(struct stream_open *open)
@@ -157,6 +159,7 @@ static void advance_isr_block(struct stream_open *open)
 
     if (block->state == BLOCK_FREE)
     {
+        dev_dbg(dev, "Advancing to block %p\n", block);
         dma_sync_single_for_device(
             dev, block->dma, BUF_BLOCK_SIZE, DMA_FROM_DEVICE);
         assign_buffer(open, next_ix);
@@ -173,6 +176,7 @@ static void receive_isr_block(
 {
     struct device *dev = &open->pcap->pdev->dev;
     block->length = length;
+    dev_dbg(dev, "Receiving block %p with data length %zu\n", block, length);
     dma_sync_single_for_cpu(dev, block->dma, BUF_BLOCK_SIZE, DMA_FROM_DEVICE);
 
     smp_wmb();
@@ -190,10 +194,13 @@ static irqreturn_t stream_isr(int irq, void *dev_id)
     void *reg_base = open->pcap->reg_base;
 
     uint32_t status = readl(reg_base + PCAP_IRQ_STATUS);
-    if (verbose)
-        printk(KERN_INFO "ISR status: %08x\n", status);
+    dev_dbg(&open->pcap->pdev->dev, "ISR status: %08x\n", status);
 
     smp_rmb();
+
+    if (IRQ_STATUS_START_EVENT(status))
+        ktime_get_real_ts64(&open->start_ts);
+
     if (open->stream_active)
     {
         struct block *block = &open->blocks[open->isr_block_index];
@@ -206,6 +213,7 @@ static irqreturn_t stream_isr(int irq, void *dev_id)
     }
     else
         printk(KERN_ERR "Panda: Unexpected interrupt %08x\n", status);
+
     return IRQ_HANDLED;
 }
 
@@ -282,6 +290,8 @@ static void start_hardware(struct stream_open *open)
     open->isr_block_index = 0;
     open->read_block_index = 0;
     open->read_offset = 0;
+    /* having a zeroed timestamp means the start event did not happen. */
+    open->start_ts = (const struct timespec64){0};
     /* After this point we can allow interrupts, they can potentially start as
      * soon as a DMA buffer is assigned. */
     smp_wmb();
@@ -489,13 +499,18 @@ static long panda_stream_ioctl(
     struct file *file, unsigned int cmd, unsigned long arg)
 {
     struct stream_open *open = file->private_data;
+    dev_dbg(&open->pcap->pdev->dev, "ioctl cmd: %x\n", cmd);
     switch (cmd)
     {
         case PANDA_DMA_ARM:
             arm_stream(open);
             return 0;
         case PANDA_COMPLETION:
             return stream_completion(open, (void __user *) arg);
+        case PANDA_GET_START_TS:
+            return copy_to_user(
+                (void __user *) arg, &open->start_ts,
+                sizeof(struct timespec64)) ? -EIO : 0;
         default:
             return -EINVAL;
     }

server/buffer.c

@@ -22,6 +22,7 @@ struct capture_buffer {
 
     pthread_mutex_t mutex;  // Locks all access
     pthread_cond_t signal;  // Used to trigger wakeup events
+    bool released_once;     // Used to wait for first data
 
     void *buffer;           // Base of captured data buffer
     /* Capture and buffer cycle counting are used to manage connections without
@@ -62,6 +63,7 @@ void start_write(struct capture_buffer *buffer)
         buffer->state = STATE_ACTIVE;
         buffer->in_ptr = 0;
         buffer->lost_bytes = 0;
+        buffer->released_once = false;
         memset(buffer->written, 0, buffer->block_count * sizeof(size_t));
         BROADCAST(buffer->signal);
     }
@@ -87,6 +89,7 @@ void release_write_block(struct capture_buffer *buffer, size_t written)
 
     WITH_MUTEX(buffer->mutex)
     {
+        buffer->released_once = true;
         /* Keep track of the total number of bytes in recycled blocks: we'll
          * need this so that late coming clients get to know how much data
          * they've missed. */
@@ -300,6 +303,9 @@ static bool wait_for_buffer_ready(
      * with or until the deadline expires. */
     while (true)
     {
+        while (!buffer->released_once && !buffer->shutdown)
+            pwait_deadline(&buffer->mutex, &buffer->signal, &deadline);
+
         if (buffer->shutdown)
             /* Shutdown forced. */
             return false;

server/data_server.c

@@ -99,6 +99,8 @@ static const struct captured_fields *captured_fields;
 static const struct data_capture *data_capture;
 /* PCAP ARM timestamp */
 static struct timespec pcap_arm_ts;
+/* PCAP becomes armed & enabled timestamp */
+static struct timespec pcap_start_ts;
 
 /* Data completion code at end of experiment. */
 static unsigned int completion_code;
@@ -119,6 +121,7 @@ static void capture_experiment(void)
     completion_code = 0;
 
     bool at_eof = false;
+    bool ts_captured = false;
     while (data_thread_running  &&  !at_eof)
     {
         void *block = get_write_block(data_buffer);
@@ -127,11 +130,22 @@ static void capture_experiment(void)
             count = hw_read_streamed_data(block, DATA_BLOCK_SIZE, &at_eof);
         while (data_thread_running  &&  count == 0  &&  !at_eof);
         if (count > 0)
+        {
+            if (!ts_captured)
+            {
+                hw_get_start_ts(&pcap_start_ts);
+                ts_captured = true;
+            }
             release_write_block(data_buffer, count);
+        }
 
         total_bytes += count;
         experiment_sample_count = total_bytes / sample_length;
     }
+
+    if (!ts_captured)
+        release_write_block(data_buffer, 0);
+
     completion_code = hw_read_streamed_completion();
 
     end_write(data_buffer);
@@ -671,7 +685,7 @@ error__t process_data_socket(int scon)
                 ok = send_data_header(
                     captured_fields, data_capture,
                     &connection.options, connection.file, lost_samples,
-                    &pcap_arm_ts);
+                    &pcap_arm_ts, &pcap_start_ts);
 
             uint64_t sent_samples = 0;
             if (ok)

server/hardware.c

@@ -45,6 +45,17 @@ struct register_fields {
         32 - BLOCK_REGISTER_BITS - BLOCK_INSTANCE_BITS - BLOCK_TYPE_BITS;
 };
 
+// This has to be bigger or same size than the linux kernel structure with the
+// same name.
+// We are using this to convert to a stardard timespec in a way that we are
+// compatible with 32-bit and 64-bit architectures, however, we will not
+// need it when we update to a newer glibc (which contains __timespec64)
+struct timespec64 {
+    __time64_t tv_sec;  /* Seconds */
+    uint32_t tv_nsec;   /* Nanoseconds */
+    uint32_t :32;       /* padding */
+};
+
 
 static unsigned int make_offset(
     unsigned int block_base, unsigned int block_number, unsigned int reg)
@@ -294,6 +305,15 @@ unsigned int hw_read_streamed_completion(void)
     return completion;
 }
 
+
+void hw_get_start_ts(struct timespec *ts)
+{
+    struct timespec64 compat_ts = (struct timespec64) {0};
+    error_report(TEST_IO(ioctl(stream, PANDA_GET_START_TS, &compat_ts)));
+    ts->tv_sec = (time_t) compat_ts.tv_sec;
+    ts->tv_nsec = (typeof(ts->tv_nsec)) compat_ts.tv_nsec;
+}
+
 #endif
 
 

server/hardware.h

@@ -1,4 +1,5 @@
 /* Hardware interface definitions. */
+#include <time.h>
 
 #define BIT_BUS_COUNT       128
 #define POS_BUS_COUNT       32
@@ -160,6 +161,9 @@ unsigned int hw_read_streamed_completion(void);
 /* Converts the completion code into a printable string. */
 const char *hw_decode_completion(unsigned int completion);
 
+/* This function gets the timestamp when PCAP becomes armed and enabled */
+void hw_get_start_ts(struct timespec *ts);
+
 /* This function controls the arm/disarm state of data capture.  Data capture is
  * armed by writing true with this function, after which hw_read_streamed_data()
  * should start returning calls with *data_end set to false.  Data streaming is

server/prepare.c

@@ -262,10 +262,23 @@ static const char *field_type_name(
 }
 
 
+static void format_timestamp_message(
+    char *timestamp_message, size_t max_len, struct timespec *tsp)
+{
+    struct tm tm;
+    gmtime_r(&tsp->tv_sec, &tm);
+    snprintf(timestamp_message, max_len,
+        "%4d-%02d-%02dT%02d:%02d:%02d.%03ldZ",
+        tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+        tm.tm_hour, tm.tm_min, tm.tm_sec, tsp->tv_nsec / 1000000);
+}
+
+
 static void send_capture_info(
     struct buffered_file *file,
     const struct data_capture *capture, const struct data_options *options,
-    uint64_t missed_samples, struct timespec *pcap_arm_tsp)
+    uint64_t missed_samples, struct timespec *pcap_arm_tsp,
+    struct timespec *pcap_start_tsp)
 {
     static const char *data_format_strings[] = {
         [DATA_FORMAT_UNFRAMED] = "Unframed",
@@ -283,15 +296,13 @@ static void send_capture_info(
     struct xml_element element =
         start_element(file, "data", options->xml_header, false, true);
 
-    struct tm tm;
     char timestamp_message[MAX_RESULT_LENGTH];
-    gmtime_r(&pcap_arm_tsp->tv_sec, &tm);
-    snprintf(timestamp_message, sizeof(timestamp_message),
-        "%4d-%02d-%02dT%02d:%02d:%02d.%03ldZ",
-        tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
-        tm.tm_hour, tm.tm_min, tm.tm_sec, pcap_arm_tsp->tv_nsec / 1000000);
-
+    format_timestamp_message(
+        timestamp_message, MAX_RESULT_LENGTH, pcap_arm_tsp);
     format_attribute(&element, "arm_time", "%s", timestamp_message);
+    format_timestamp_message(
+        timestamp_message, MAX_RESULT_LENGTH, pcap_start_tsp);
+    format_attribute(&element, "start_time", "%s", timestamp_message);
     format_attribute(&element, "missed", "%"PRIu64, missed_samples);
     format_attribute(&element, "process", "%s", data_process);
     format_attribute(&element, "format", "%s", data_format);
@@ -366,12 +377,13 @@ bool send_data_header(
     const struct data_capture *capture,
     const struct data_options *options,
     struct buffered_file *file, uint64_t missed_samples,
-    struct timespec *pcap_arm_tsp)
+    struct timespec *pcap_arm_tsp, struct timespec *pcap_start_tsp)
 {
     struct xml_element header =
         start_element(file, "header", options->xml_header, true, true);
 
-    send_capture_info(file, capture, options, missed_samples, pcap_arm_tsp);
+    send_capture_info(
+        file, capture, options, missed_samples, pcap_arm_tsp, pcap_start_tsp);
 
     /* Format the field capture descriptions. */
     struct xml_element field_group =

server/prepare.h

@@ -46,7 +46,7 @@ bool send_data_header(
     const struct data_capture *capture,
     const struct data_options *options,
     struct buffered_file *file, uint64_t lost_samples,
-    struct timespec *pcap_arm_tsp);
+    struct timespec *pcap_arm_tsp, struct timespec *pcap_start_tsp);
 
 
 /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */

server/sim_hardware.c

@@ -6,6 +6,7 @@
 #include <stdlib.h>
 #include <unistd.h>
 #include <string.h>
+#include <time.h>
 #include <sys/types.h>
 #include <sys/socket.h>
 #include <arpa/inet.h>
@@ -181,6 +182,12 @@ void hw_write_arm_streamed_data(void) { }
 uint32_t hw_read_streamed_completion(void) { return 0; }
 
 
+void hw_get_start_ts(struct timespec *ts)
+{
+    clock_gettime(CLOCK_REALTIME, ts);
+}
+
+
 /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */
 /* Long table support. */