LEDS, ArtNet metrics

components/artnet/artnet.c

@@ -162,7 +162,7 @@ void artnet_get_stats(struct artnet *artnet, struct artnet_stats *stats)
 }
 
 // node in synchronous DMX mode?
-bool artnet_sync_state (struct artnet *artnet)
+bool artnet_is_sync_state (struct artnet *artnet)
 {
   if (artnet->sync_tick) {
     return xTaskGetTickCount() - artnet->sync_tick < ARTNET_SYNC_TICKS;

components/artnet/artnet.h

@@ -89,5 +89,3 @@ struct artnet {
 
   struct artnet_stats stats;
 };
-
-bool artnet_sync_state (struct artnet *artnet);

components/artnet/include/artnet.h

@@ -296,6 +296,11 @@ int artnet_get_input_state(struct artnet *artnet, int index, struct artnet_input
  */
 int artnet_get_output_state(struct artnet *artnet, int index, struct artnet_output_state *state);
 
+/**
+ * Return if node is expecting ArtSync.
+ */
+bool artnet_is_sync_state (struct artnet *artnet);
+
 /**
  * Sync all artnet outputs.
  *

components/artnet/include/artnet_stats.h

@@ -19,7 +19,7 @@ struct artnet_stats {
   /* Received ArtSync packets */
   struct stats_counter recv_sync;
 
-  /* Received ArtPoll packets */
+  /* Received unknown packets */
   struct stats_counter recv_unknown;
 
   /* Received packets, rejected as invalid */
@@ -38,30 +38,36 @@ struct artnet_input_stats {
   struct stats_counter dmx_recv;
 
   /* Output queue overflowed, previous packet overwritten */
-  struct stats_counter queue_overwrite;
+  struct stats_counter queue_overflow;
 };
 
 struct artnet_output_stats {
-  /* Received ArtSync packets */
-  struct stats_counter sync_recv;
-
   /* Received ArtDMX packets */
   struct stats_counter dmx_recv;
 
   /* Received ArtDMX packets in sync mode */
   struct stats_counter dmx_sync;
 
-  /* Received ArtDMX packets with seq larger than expected */
-  struct stats_counter seq_skip;
+  /* Received ArtDMX packets without seq */
+  struct stats_counter seq_zero;
 
-  /* Dropped ArtDMX packets with seq smaller than expected */
+  /* Received ArtDMX packets with expected seq */
+  struct stats_counter seq_good;
+
+  /* Received ArtDMX packets with seq larger than expected, missed packets */
+  struct stats_counter seq_miss;
+
+  /* Received ArtDMX packets with seq smaller than expected, dropping packet */
   struct stats_counter seq_drop;
 
   /* Received ArtDMX packets with seq resynced after timeout */
   struct stats_counter seq_resync;
 
+  /* Output queue updated */
+  struct stats_counter queue_update;
+
   /* Output queue overflowed, previous packet overwritten */
-  struct stats_counter queue_overwrite;
+  struct stats_counter queue_overflow;
 };
 
 /*

components/artnet/input.c

@@ -5,7 +5,7 @@
 static void init_input_stats(struct artnet_input_stats *stats)
 {
   stats_counter_init(&stats->dmx_recv);
-  stats_counter_init(&stats->queue_overwrite);
+  stats_counter_init(&stats->queue_overflow);
 }
 
 int artnet_add_input(struct artnet *artnet, struct artnet_input **inputp, struct artnet_input_options options)
@@ -59,7 +59,7 @@ void artnet_input_dmx(struct artnet_input *input, const struct artnet_dmx *dmx)
 
   // attempt normal send first, before overwriting for overflow stats
   if (xQueueSend(input->queue, dmx, 0) == errQUEUE_FULL) {
-    stats_counter_increment(&input->stats.queue_overwrite);
+    stats_counter_increment(&input->stats.queue_overflow);
 
     xQueueOverwrite(input->queue, dmx);
   }
@@ -163,7 +163,7 @@ int artnet_get_input_stats(struct artnet *artnet, int index, struct artnet_input
   struct artnet_input *input = &artnet->input_ports[index];
 
   stats->dmx_recv = stats_counter_copy(&input->stats.dmx_recv);
-  stats->queue_overwrite = stats_counter_copy(&input->stats.queue_overwrite);
+  stats->queue_overflow = stats_counter_copy(&input->stats.queue_overflow);
 
   return 0;
 }

components/artnet/output.c

@@ -4,13 +4,14 @@
 
 static void init_output_stats(struct artnet_output_stats *stats)
 {
-  stats_counter_init(&stats->sync_recv);
   stats_counter_init(&stats->dmx_recv);
-  stats_counter_init(&stats->dmx_sync);
-  stats_counter_init(&stats->seq_skip);
+  stats_counter_init(&stats->seq_zero);
+  stats_counter_init(&stats->seq_good);
+  stats_counter_init(&stats->seq_miss);
   stats_counter_init(&stats->seq_drop);
   stats_counter_init(&stats->seq_resync);
-  stats_counter_init(&stats->queue_overwrite);
+  stats_counter_init(&stats->queue_update);
+  stats_counter_init(&stats->queue_overflow);
 }
 
 int artnet_add_output(struct artnet *artnet, struct artnet_output **outputp, struct artnet_output_options options)
@@ -137,13 +138,14 @@ int artnet_get_output_stats(struct artnet *artnet, int index, struct artnet_outp
 
   struct artnet_output *output = &artnet->output_ports[index];
 
-  stats->sync_recv = stats_counter_copy(&output->stats.sync_recv);
   stats->dmx_recv = stats_counter_copy(&output->stats.dmx_recv);
-  stats->dmx_sync = stats_counter_copy(&output->stats.dmx_sync);
-  stats->seq_skip = stats_counter_copy(&output->stats.seq_skip);
+  stats->seq_zero = stats_counter_copy(&output->stats.seq_zero);
+  stats->seq_good = stats_counter_copy(&output->stats.seq_good);
+  stats->seq_miss = stats_counter_copy(&output->stats.seq_miss);
   stats->seq_drop = stats_counter_copy(&output->stats.seq_drop);
   stats->seq_resync = stats_counter_copy(&output->stats.seq_resync);
-  stats->queue_overwrite = stats_counter_copy(&output->stats.queue_overwrite);
+  stats->queue_update = stats_counter_copy(&output->stats.queue_update);
+  stats->queue_overflow = stats_counter_copy(&output->stats.queue_overflow);
 
   return 0;
 }
@@ -173,15 +175,20 @@ void artnet_output_dmx(struct artnet_output *output, struct artnet_dmx *dmx)
 
   stats_counter_increment(&output->stats.dmx_recv);
 
-  if (dmx->seq == 0 || output->state.seq == 0) {
+  if (output->state.seq == 0) {
     // init or reset
 
+  } else if (dmx->seq == 0) {
+    // disabled
+    stats_counter_increment(&output->stats.seq_zero);
+
   } else if (dmx->seq == artnet_seq_next(output->state.seq)) {
     // in-order
+    stats_counter_increment(&output->stats.seq_good);
 
   } else if (dmx->seq > output->state.seq || output->state.seq - dmx->seq >= 128) {
-    // skipped
-    stats_counter_increment(&output->stats.seq_skip);
+    // missed
+    stats_counter_increment(&output->stats.seq_miss);
 
   } else if (output->state.tick < tick && (tick - output->state.tick) > ARTNET_SEQ_TICKS) {
     LOG_WARN("resync address=%04x seq=%d < %d on timeout", output->options.address, dmx->seq, output->state.seq);
@@ -194,35 +201,32 @@ void artnet_output_dmx(struct artnet_output *output, struct artnet_dmx *dmx)
   } else {
     LOG_WARN("drop address=%04x seq=%d < %d", output->options.address, dmx->seq, output->state.seq);
 
+    // dropping
     stats_counter_increment(&output->stats.seq_drop);
 
     // do NOT update output->state.tick, in order to resync on timeout
     return;
   }
 
-  // advance
-  if (dmx->seq) {
-    output->state.seq = dmx->seq;
-  } else {
-    output->state.seq++;
-  }
-
+  // update
+  output->state.seq = dmx->seq;
   output->state.tick = tick;
 
   // attempt normal send first, before overwriting for overflow stats
   if (xQueueSend(output->queue, dmx, 0) == errQUEUE_FULL) {
-    stats_counter_increment(&output->stats.queue_overwrite);
+    stats_counter_increment(&output->stats.queue_overflow);
 
     xQueueOverwrite(output->queue, dmx);
+  } else {
+    stats_counter_increment(&output->stats.queue_update);
   }
 
   if (output->options.output_events) {
     xEventGroupSetBits(output->options.output_events, output->options.output_event_bit);
   }
 
-  if (artnet_sync_state(output->artnet)) {
+  if (artnet_is_sync_state(output->artnet)) {
     // wait for hard sync
-    stats_counter_increment(&output->stats.dmx_sync);
   } else if (output->options.event_group && output->options.dmx_event_bit) {
     // sync each update
     xEventGroupSetBits(output->options.event_group, output->options.dmx_event_bit);
@@ -264,8 +268,6 @@ int artnet_sync_outputs(struct artnet *artnet)
       continue;
     }
 
-    stats_counter_increment(&output->stats.sync_recv);
-
     if (output->options.event_group != event_group) {
       xEventGroupSetBits(output->options.event_group, output->options.sync_event_bit);
 

components/i2s_out/CMakeLists.txt

@@ -1,7 +1,7 @@
 idf_component_register(
   SRC_DIRS . ${IDF_TARGET}
   INCLUDE_DIRS "include"
-  PRIV_REQUIRES logging
+  PRIV_REQUIRES logging stats
   LDFRAGMENTS ${IDF_TARGET}.lf
 )
 

components/i2s_out/esp32/dma.c

@@ -556,9 +556,7 @@ int i2s_out_dma_flush(struct i2s_out *i2s_out, TickType_t timeout)
 
   taskENTER_CRITICAL(&i2s_out->mux);
 
-  dma_done = i2s_out->dma_done;
-
-  if (!dma_done) {
+  if (!(dma_done = i2s_out->dma_done)) {
     i2s_out->dma_done_task = xTaskGetCurrentTaskHandle();
   }
 

components/i2s_out/esp32/i2s.c

@@ -131,6 +131,9 @@ void i2s_out_i2s_start(struct i2s_out *i2s_out)
   i2s_out->i2s_done = false;
   i2s_out->i2s_done_task = NULL;
 
+  // track active time
+  i2s_out->stats_out_timer_start = stats_timer_start(&i2s_out->stats.out_timer);
+
   taskENTER_CRITICAL(&i2s_out->mux);
 
   // NOTE: there seems to always be three extra BCK cycles at the start of TX
@@ -139,6 +142,9 @@ void i2s_out_i2s_start(struct i2s_out *i2s_out)
   //      let's hope that the EOF frame is always zeroes, and zero bytes at the start are harmless...
   i2s_ll_tx_start(i2s_out->dev);
 
+  i2s_intr_clear(i2s_out->dev, I2S_TX_REMPTY_INT_CLR);
+  i2s_intr_enable(i2s_out->dev, I2S_TX_REMPTY_INT_ENA);
+
   taskEXIT_CRITICAL(&i2s_out->mux);
 }
 
@@ -151,13 +157,8 @@ int i2s_out_i2s_flush(struct i2s_out *i2s_out, TickType_t timeout)
 
   taskENTER_CRITICAL(&i2s_out->mux);
 
-  i2s_done = i2s_out->i2s_done;
-
-  if (!i2s_done) {
+  if (!(i2s_done = i2s_out->i2s_done)) {
     i2s_out->i2s_done_task = xTaskGetCurrentTaskHandle();
-
-    i2s_intr_clear(i2s_out->dev, I2S_TX_REMPTY_INT_CLR);
-    i2s_intr_enable(i2s_out->dev, I2S_TX_REMPTY_INT_ENA);
   }
 
   taskEXIT_CRITICAL(&i2s_out->mux);
@@ -188,6 +189,9 @@ void i2s_out_i2s_stop(struct i2s_out *i2s_out)
 
   taskENTER_CRITICAL(&i2s_out->mux);
 
+  i2s_intr_disable(i2s_out->dev, I2S_TX_REMPTY_INT_ENA);
+  i2s_intr_clear(i2s_out->dev, I2S_TX_REMPTY_INT_CLR);
+
   i2s_ll_tx_stop(i2s_out->dev);
 
   taskEXIT_CRITICAL(&i2s_out->mux);

components/i2s_out/esp32/intr_iram.c

@@ -40,6 +40,21 @@ static void i2s_out_intr_dma_done(struct i2s_out *i2s_out, BaseType_t *pxHigherP
   }
 }
 
+static void i2s_out_intr_i2s_done(struct i2s_out *i2s_out, BaseType_t *pxHigherPriorityTaskWoken)
+{
+  // unblock flush() task
+  i2s_out->i2s_done = true;
+
+  if (i2s_out->i2s_done_task) {
+    xTaskNotifyFromISR(i2s_out->i2s_done_task, I2S_OUT_TASK_NOTIFY_BIT_I2S_DONE, eSetBits, pxHigherPriorityTaskWoken);
+
+    i2s_out->i2s_done_task = NULL;
+  }
+
+  // stats
+  stats_timer_stop(&i2s_out->stats.out_timer, &i2s_out->stats_out_timer_start);
+}
+
 static void i2s_intr_out_dscr_err_handler(struct i2s_out *i2s_out)
 {
   uint32_t dscr_addr;
@@ -76,6 +91,10 @@ static void i2s_intr_out_eof_handler(struct i2s_out *i2s_out, BaseType_t *pxHigh
     i2s_out_intr_dma_out_desc(i2s_out, eof_desc, pxHigherPriorityTaskWoken);
     i2s_out_intr_dma_done(i2s_out, pxHigherPriorityTaskWoken);
 
+    // XXX: ensure tx rempty intr is enabled, in case it fired during DMA and was disabled?
+    i2s_intr_clear(i2s_out->dev, I2S_TX_REMPTY_INT_CLR);
+    i2s_intr_enable(i2s_out->dev, I2S_TX_REMPTY_INT_ENA);
+
   } else {
     LOG_ISR_ERROR("unknown desc=%p owner=%u len=%u", eof_desc, eof_desc->owner, eof_desc->len);
   }
@@ -89,13 +108,14 @@ static void i2s_intr_tx_rempty_handler(struct i2s_out *i2s_out, BaseType_t *pxHi
   i2s_intr_disable(i2s_out->dev, I2S_TX_REMPTY_INT_ENA);
   i2s_intr_clear(i2s_out->dev, I2S_TX_REMPTY_INT_CLR);
 
-  // unblock flush() task
-  i2s_out->i2s_done = true;
-
-  if (i2s_out->i2s_done_task) {
-    xTaskNotifyFromISR(i2s_out->i2s_done_task, I2S_OUT_TASK_NOTIFY_BIT_I2S_DONE, eSetBits, pxHigherPriorityTaskWoken);
+  if (!i2s_out->dma_done) {
+    // XXX: ignore if fired before dma_done, will be re-enabled
+    // XXX: may indicate a timing glitch in the output data?
+    LOG_ISR_WARN("tx rempty dma_done=%u i2s_done=%u", i2s_out->dma_done, i2s_out->i2s_done);
+  } else {
+    LOG_ISR_DEBUG("tx rempty dma_done=%u i2s_done=%u", i2s_out->dma_done, i2s_out->i2s_done);
 
-    i2s_out->i2s_done_task = NULL;
+    i2s_out_intr_i2s_done(i2s_out, pxHigherPriorityTaskWoken);
   }
 }
 

components/i2s_out/i2s_out.c

@@ -28,9 +28,11 @@ int i2s_out_init(struct i2s_out *i2s_out, i2s_port_t port)
   }
 #endif
 
-  #if CONFIG_IDF_TARGET_ESP32
-    portMUX_INITIALIZE(&i2s_out->mux);
-  #endif
+#if CONFIG_IDF_TARGET_ESP32
+  portMUX_INITIALIZE(&i2s_out->mux);
+#endif
+
+  i2s_out_stats_reset(&i2s_out->stats);
 
   return 0;
 }
@@ -76,6 +78,16 @@ int i2s_out_new(struct i2s_out **i2s_outp, i2s_port_t port, size_t buffer_size,
   return err;
 }
 
+void i2s_out_reset_stats(struct i2s_out *i2s_out)
+{
+  i2s_out_stats_reset(&i2s_out->stats);
+}
+
+struct i2s_out_stats i2s_out_stats(struct i2s_out *i2s_out)
+{
+  return i2s_out_stats_copy(&i2s_out->stats);
+}
+
 int i2s_out_open(struct i2s_out *i2s_out, const struct i2s_out_options *options, TickType_t timeout)
 {
   int err = 0;

components/i2s_out/i2s_out.h

@@ -1,4 +1,7 @@
 #include <i2s_out.h>
+#include <i2s_out_stats.h>
+
+#include <stats_timer.h>
 
 #include <freertos/FreeRTOS.h>
 #include <freertos/event_groups.h>
@@ -73,6 +76,10 @@ struct i2s_out {
   TaskHandle_t dma_out_task; // task waiting for dma_out_desc to update
   TaskHandle_t dma_done_task; // task waiting for dma_done to be set
   TaskHandle_t i2s_done_task; // task waiting for i2s_done to be set
+
+  struct i2s_out_stats stats;
+
+  stats_timer_start_t stats_out_timer_start;
 };
 
 /* dma.c */
@@ -107,3 +114,7 @@ void i2s_out_pin_teardown(struct i2s_out *i2s_out);
 /* intr.c */
 int i2s_out_intr_setup(struct i2s_out *i2s_out, const struct i2s_out_options *options);
 void i2s_out_intr_teardown(struct i2s_out *i2s_out);
+
+/* stats.c */
+void i2s_out_stats_reset(struct i2s_out_stats *stats);
+struct i2s_out_stats i2s_out_stats_copy(struct i2s_out_stats *stats);