[Bug] EV3 SPI DMA for ADC has inconsistent duration

[laurensvalk]

While a program is running (the display animation is running), some ADC operations appear to take about 7x longer.

start	        complete      duration (microseconds)
150521076	150523056	1980
150523897	150538786	14889
150538625	150541258	2633
150541099	150543258	2159
150543099	150545240	2141
150545082	150547239	2157
150547080	150549260	2180
150549098	150551263	2165
150551100	150553261	2161
150553099	150555243	2144
150555080	150557251	2171
150557099	150559259	2160
150559097	150561242	2145
150561111	150563056	1945
150563897	150578969	15072
150578808	150581241	2433
150581082	150583258	2176
150583099	150585257	2158
150585099	150587240	2141
150587081	150589261	2180
150589098	150591240	2142
150591081	150593260	2179
150593098	150595261	2163
150595098	150597262	2164
150597099	150599262	2163
150599099	150601263	2164
150601100	150604296	3196
150604138	150619102	14964
150618973	150621259	2286
150621100	150623258	2158
150623099	150625256	2157
150625097	150627256	2159
150627098	150629257	2159
150629099	150631258	2159
150631099	150633259	2160
150633097	150635262	2165
150635099	150637260	2161
150637098	150639261	2163

When no program is running, it is more consistently near 2160 microseconds.

(We can also update the wait in the loop to use pbio_os_timer_extend, with a longer loop time than the average duration. That's not the issue here though.)

--- a/lib/pbio/drv/block_device/block_device_ev3.c
+++ b/lib/pbio/drv/block_device/block_device_ev3.c
@@ -43,6 +43,9 @@
 #include <pbio/int_math.h>
 #include <pbio/util.h>
 
+
+#include <pbdrv/../../drv/uart/uart_debug_first_port.h>
+
 //
 // Part 1: Common SPI setup and DMA configuration.
 //
@@ -115,6 +118,7 @@ static void spi_dma_complete(void) {
     SPIIntDisable(SOC_SPI_0_REGS, SPI_DMA_REQUEST_ENA_INT);
     pbio_os_request_poll();
     last_spi_dma_complete_time = pbdrv_clock_get_ms();
+    pbdrv_uart_debug_printf("%lu\n", pbdrv_clock_get_us());
 }
 
 /**
@@ -813,6 +817,8 @@ static pbio_error_t pbdrv_block_device_ev3_spi_begin_for_adc(const uint32_t *cmd
     EDMA3EnableTransfer(SOC_EDMA30CC_0_REGS, EDMA3_CHA_SPI0_RX, EDMA3_TRIG_MODE_EVENT);
     SPIIntEnable(SOC_SPI_0_REGS, SPI_DMA_REQUEST_ENA_INT);
 
+    pbdrv_uart_debug_printf("%lu, ", pbdrv_clock_get_us());
+
     return PBIO_SUCCESS;
 }

This is related to the flickering issue in #2301 since we wait on the ADC before taking a sample before toggling the light again. This could explain that variation.

[ArcaneNibble]

Oh this is cursed.

I see what you are seeing when I use your patch exactly, but I don't see it when I use the following:

diff --git a/lib/pbio/drv/block_device/block_device_ev3.c b/lib/pbio/drv/block_device/block_device_ev3.c
index 9198a64c..35f1408b 100644
--- a/lib/pbio/drv/block_device/block_device_ev3.c
+++ b/lib/pbio/drv/block_device/block_device_ev3.c
@@ -43,6 +43,8 @@
 #include <pbio/int_math.h>
 #include <pbio/util.h>

+#include <pbdrv/../../drv/uart/uart_debug_first_port.h>
+
 //
 // Part 1: Common SPI setup and DMA configuration.
 //
@@ -106,6 +108,7 @@ static struct {
 } spi_dev;

 static uint32_t last_spi_dma_complete_time;
+static uint32_t debug_completion;

 static void spi_dma_complete(void) {
     // Only complete once RX and TX complete.
@@ -115,6 +118,8 @@ static void spi_dma_complete(void) {
     SPIIntDisable(SOC_SPI_0_REGS, SPI_DMA_REQUEST_ENA_INT);
     pbio_os_request_poll();
     last_spi_dma_complete_time = pbdrv_clock_get_ms();
+    uint32_t dt = pbdrv_clock_get_us() - debug_completion;
+    pbdrv_uart_debug_printf("%lu\r\n", dt);
 }

 /**
@@ -813,6 +818,8 @@ static pbio_error_t pbdrv_block_device_ev3_spi_begin_for_adc(const uint32_t *cmd
     EDMA3EnableTransfer(SOC_EDMA30CC_0_REGS, EDMA3_CHA_SPI0_RX, EDMA3_TRIG_MODE_EVENT);
     SPIIntEnable(SOC_SPI_0_REGS, SPI_DMA_REQUEST_ENA_INT);

+    debug_completion = pbdrv_clock_get_us();
+
     return PBIO_SUCCESS;
 }

[laurensvalk]

Did you start the REPL both times? I forgot it once and didn't notice until reviewing the logs.

[ArcaneNibble]

I did, yes. I can see the blinking light sensor, but the values that are printed are always on the order of 152 microseconds.

[laurensvalk]

That's a lot less than the 2000us I was seeing. I'll have to try it with your patch.

[ArcaneNibble]

Even a patch like this

diff --git a/lib/pbio/src/os.c b/lib/pbio/src/os.c
index fc955bc4..f12810cd 100644
--- a/lib/pbio/src/os.c
+++ b/lib/pbio/src/os.c
@@ -11,6 +11,8 @@

 #include <pbdrv/clock.h>

+#include <pbdrv/../../drv/uart/uart_debug_first_port.h>
+
 /**
  * Sets the timer to expire after the specified duration.
  *
@@ -132,6 +134,8 @@ void pbio_os_process_make_request(pbio_os_process_t *process, pbio_os_process_re
     pbio_os_request_poll();
 }

+static uint32_t last_time;
+
 /**
  * Drives the event loop once: Runs one iteration of all processes.
  *
@@ -141,6 +145,10 @@ void pbio_os_process_make_request(pbio_os_process_t *process, pbio_os_process_re
  */
 bool pbio_os_run_processes_once(void) {

+    uint32_t us = pbdrv_clock_get_us();
+    pbdrv_uart_debug_printf("%lu\r\n", us - last_time);
+    last_time = us;
+
     // DELETEME: Legacy hook to drive Contiki processes until all are migrated.
     extern int process_run(void);
     bool pbio_event_pending = process_run();

shows occasional jumps up to ~15 milliseconds when an app is running.

[ArcaneNibble]

If I profile using this hacky code

diff --git a/lib/pbio/platform/ev3/platform.c b/lib/pbio/platform/ev3/platform.c
index c89c888b..46f57d27 100644
--- a/lib/pbio/platform/ev3/platform.c
+++ b/lib/pbio/platform/ev3/platform.c
@@ -396,7 +396,7 @@ unsigned int EDMAVersionGet(void) {
     return 1;
 }
 
-static void panic_puts(const char *c) {
+void panic_puts(const char *c) {
     while (*c) {
         UARTCharPut(SOC_UART_1_REGS, *(c++));
     }
@@ -406,7 +406,7 @@ static void panic_putu8(uint8_t x) {
     UARTCharPut(SOC_UART_1_REGS, hex[x >> 4]);
     UARTCharPut(SOC_UART_1_REGS, hex[x & 0xf]);
 }
-static void panic_putu32(uint32_t x) {
+void panic_putu32(uint32_t x) {
     panic_putu8(x >> 24);
     panic_putu8(x >> 16);
     panic_putu8(x >> 8);
diff --git a/lib/pbio/src/os.c b/lib/pbio/src/os.c
index fc955bc4..b2aaa4d8 100644
--- a/lib/pbio/src/os.c
+++ b/lib/pbio/src/os.c
@@ -11,6 +11,8 @@
 
 #include <pbdrv/clock.h>
 
+#include <pbdrv/../../drv/uart/uart_debug_first_port.h>
+
 /**
  * Sets the timer to expire after the specified duration.
  *
@@ -132,6 +134,12 @@ void pbio_os_process_make_request(pbio_os_process_t *process, pbio_os_process_re
     pbio_os_request_poll();
 }
 
+static uint32_t funcs[1000];
+static uint32_t times[1000];
+static uint32_t num_times;
+void panic_puts(const char *c);
+void panic_putu32(uint32_t x);
+
 /**
  * Drives the event loop once: Runs one iteration of all processes.
  *
@@ -141,6 +149,8 @@ void pbio_os_process_make_request(pbio_os_process_t *process, pbio_os_process_re
  */
 bool pbio_os_run_processes_once(void) {
 
+    uint32_t us = pbdrv_clock_get_us();
+
     // DELETEME: Legacy hook to drive Contiki processes until all are migrated.
     extern int process_run(void);
     bool pbio_event_pending = process_run();
@@ -158,14 +168,29 @@ bool pbio_os_run_processes_once(void) {
     poll_request_is_pending = false;
 
     pbio_os_process_t *process = process_list;
+    num_times = 0;
     while (process) {
         // Run one iteration of the process if not yet completed or errored.
         if (process->err == PBIO_ERROR_AGAIN) {
             process->err = process->func(&process->state, process->context);
         }
+        uint32_t dt = pbdrv_clock_get_us() - us;
+        funcs[num_times] = (uint32_t)process->func;
+        times[num_times++] = dt;
         process = process->next;
     }
 
+    if (times[num_times - 1] > 10000) {
+        for (uint32_t i = 0; i < num_times; i++) {
+            panic_puts("f");
+            panic_putu32(funcs[i]);
+            panic_puts(" t");
+            panic_putu32(times[i]);
+            panic_puts("\r\n");
+        }
+        pbdrv_uart_debug_printf("-----\r\n");
+    }
+
     // Poll requests may have been set while running the processes.
     return poll_request_is_pending || pbio_event_pending;
 }

It once again points at pbdrv_display_ev3_process_thread taking a huge amount of time, although ev3_spi_process_thread is also taking far longer than expected...

fC0032EF0 t00000770     ev3_spi_process_thread
fC00308D4 t00000779     
fC003369C t00003E91     pbdrv_display_ev3_process_thread
fC00346E4 t00003EA2
fC003490C t00003EB0
fC0030A94 t00003EC4
fC0030B38 t00003EC9
fC0030B38 t00003ECF
fC0030B38 t00003ED5
fC0030B38 t00003EDA
fC0030B38 t00003EE0
fC0036B7C t00003EFF
fC0036B7C t00003F27
fC0036B7C t00003F82
fC0039AF8 t00003FBD

[laurensvalk]

Even a patch like this

diff --git a/lib/pbio/src/os.c b/lib/pbio/src/os.c
index fc955bc4..f12810cd 100644
--- a/lib/pbio/src/os.c
+++ b/lib/pbio/src/os.c
@@ -11,6 +11,8 @@

 #include <pbdrv/clock.h>

+#include <pbdrv/../../drv/uart/uart_debug_first_port.h>
+
 /**
  * Sets the timer to expire after the specified duration.
  *
@@ -132,6 +134,8 @@ void pbio_os_process_make_request(pbio_os_process_t *process, pbio_os_process_re
     pbio_os_request_poll();
 }

+static uint32_t last_time;
+
 /**
  * Drives the event loop once: Runs one iteration of all processes.
  *
@@ -141,6 +145,10 @@ void pbio_os_process_make_request(pbio_os_process_t *process, pbio_os_process_re
  */
 bool pbio_os_run_processes_once(void) {

+    uint32_t us = pbdrv_clock_get_us();
+    pbdrv_uart_debug_printf("%lu\r\n", us - last_time);
+    last_time = us;
+
     // DELETEME: Legacy hook to drive Contiki processes until all are migrated.
     extern int process_run(void);
     bool pbio_event_pending = process_run();

shows occasional jumps up to ~15 milliseconds when an app is running.

This is a little bit worrying. Even if the DMA transfer is slow for whatever reason (like no caching) we would want it to delay in the background, not hold up the run loop. Any idea what is blocking here?

[ArcaneNibble]

As far as I can tell, it really is just memory latency making the CPU slow to a crawl when tight loops with lots of small memory accesses (i.e. display-related code) happen. It doesn't seem like the DMA is delaying anything, the CPU is just running that badly.

Remember that the CPU not only isn't caching, it can't do write-combining either. And DDR RAM can only be accessed in bursts. So certain access patterns can end up very pessimized without caches.