Why does the execution time of STM32F767ZIT6 (used in NUCLEO-F767ZI) not grow as expected when the amount of code to execute increases?

[Silvano]

I measure the execution time of a function by putting the toggle of a digital output and the function call into a cycle and measuring the period of the square wave at the digital output with an oscilloscope. The execution time is half a period.

To test the procedure, I used instead of the function a dummy code (see main function in the annex execution_time_main.c) where the cnt_max parameter allows me to vary the amount of code to execute.

The measured periods are visible in the attachment CRAZY_TIMES.jpg

I do not understand why both with the ARM V5 and V6 compiler in Keil uVision the trend of the periods is that shown in the attachment CRAZY_TIMES.jpg

• Comp V5, test case 8 to 9 cnt_max go from 8000 to 9000 (increases) and  period go from 485 us to 454 us (decreases) !
• Comp V5, test case 10 to 11 cnt_max go from 10 000 to 100 000 (x 10) and period go from 505 us to 11.1 ms (x 22) !
• Comp V6, test case 10 to 11 cnt_max go from 10 000 to 100 000 (x 10) and period go from 607 us to 29.6 ms (x 49) !

Thanks

[Silvano]

I wondered that I made some mistake in my clock_configure function so I disabled it leaving the default clock initialization (now SYSCLK frequency = 16 MHz and not 216 MHz as before, ...)

#if 0  

  clock_configure();

  SystemCoreClockUpdate();

#endif

The measured periods are visible in the attachment CRAZY_TIMES_2.jpg

I do not understand why (now i tested only with the ARM V5 compiler) the trend of the periods is that shown in the attachment CRAZY_TIMES_2.jpg

• Comp V5, test case 5 to 10 cnt_max go from 1 000 to 10 000 (x 10) and period go from 831 us to 20.3 ms (x 24) !
• Comp V5, test case 10 to 11 cnt_max go from 10 000 to 100 000 (x 10) and period go from 20.3 ms to 151 ms (x 7) !

just to make sure, I have also determined the periods using the debugger and they are in very good agreement with the measurements made with the oscilloscope.

So the problem is not in my clock_configure_function or in the oscilloscope.

[Tesla DeLorean]

Could you look at the generated code?

Alignment, caching, flash line placement?

Could you run without the debugger?

Could you run all the tests using a singular function, feeding that the iteration count, and self-timing via the DWT CYCCNT machine cycle counter?

[TDK]

Showing disassembly would be insightful. So would putting the delay into a function and calling that multiple times within the same program with different values. Could be the compiler rearranging things based on the compiled value.

[KiptonM]

If I had to guess you probably having the tick interrupt running in the background, and sometimes it happens during your timing, and sometimes it does not. (Or maybe some other interrupt.)

[Silvano]

Hi KiptonM

I did new tests with interrupts disabled.

In TEST_RESULTS.jpg (in ATTACH_FILE_#1.zip) there is a summary of the test.

In ATTACH_FILE_#1.zip there are also list files (.lst) and source files (.c) about two tests case (the code is very short)

[Silvano]

Thanks Tesla DeLorean, TDK and KiptonM for the time you are dedicating to me.

Before answering you, I wanted to simplify the code as much as possible. See the attachment execution_time_main_#1.c.

When the line marked with @ 1 was commented, see the attachment execution_time_main_#2.c the period in the case of test case 10 went from 20.3 ms to 6.87 ms.

I find it incomprehensible since this line is not inside the while loop of the Dummy code.

The periods measured for all test cases are visible in the attachment CRAZY_TIMES_3.jpg

Now I turn to the answers to your questions.

1. Could you run without the debugger ? Periods in all test cases were measured with oscilloscope without debuggers. See attachment NO_DEBUGGER_SETUP.jpg
2. If I had to guess you probably having the tick interrupt running in the background. There should be no interrupts. All the code is what you see in attachment execution_time_ # 1.c or execution_time_ # 2.c
3. Could you look at the generated code? Alignment, caching, flash line placement? Showing disassembly would be insightful. See attachments assembly_#1.lst, startup_stm32f767xx_#1.lst, execution_time_#1.map about execution_time_main_#1.c and assembly_#2.lst, startup_stm32f767xx_#2.lst, execution_time_#2.map about execution_time_main_#2.c.
4. Could you run all the tests using a singular function, feeding that the iteration count, and self-timing via the DWT CYCCNT machine cycle counter? I have little experience with programming these microcontrollers so it is not clear to me what you are asking me to do when you write "feeding that the iteration count, and self-timing via the DWT CYCCNT machine cycle counter". I'm sorry.

[TDK]

No attachments came through. Putting the delay within a function and calling that multiple times with different values would clear up a lot of unknowns.
Using a scope to time instead of DWT->CYCCNT is fine.

[Silvano]

Hi TDK.

I did as you advised me.

In TEST_RESULTS.jpg (in ATTACH_FILE_#1.zip) there is a summary of the test tests.

In ATTACH_FILE_#1.zip there are also list files (.lst) and source files (.c) about two tests case (the code is very short)

[Silvano]

..., I forgot the attachments ... See ATTACH_FILE.zip

[LCE]

Here's how you enable the cycle counter on F767 (I'm using the same Nucleo board):

/* CPU cycle count activation for debugging */
#if DEBUG_CPU_TIMING
	CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;
	DWT->LAR = 0xC5ACCE55;
	DWT->CYCCNT = 0;
	DWT->CTRL |= DWT_CTRL_CYCCNTENA_Msk;
	DWT->CTRL |= DWT_CTRL_PCSAMPLENA_Msk;
#endif

Then you can start reading DWT->CYCCNT as shown above by TDL.

I have also found some weird timing behavior, it turned out that part of it depended on compiling as Debug version (using CubeIDE).

But some strange timings remained, I didn't have time to figure it out, I guess it might be some "memory domain border crossing" issue (DTCM, SRAM1, SRAM2).

[Silvano]

Very simple case for analysis

Hi

To simplify the analysis, I have now concentrated on a single anomaly that is highlighted by simply using the exact same source code except for the iterations parameter which assumes different values (100, ... 10 000 000).

Here I have collected the different suggestions given to me by @Community member​, @TDK​ and @KiptonM​. 

• Interrupt are disabled (__disable_irq(); in line 13).
• DWT->CYCCNT was used instead of the oscilloscope.
• All tests now use a single function
• Disassembly is now available (ATTACH_FILE_#2 list files $1.lst about test case 3 and $2.lst about test case 4)

Follow the code for test case 3 (iterations = 10000).

#include "stm32f767xx.h"
 
const uint32_t iterations = 10000UL;
volatile uint32_t total_for_watch = 0; 
 
void test_function (uint32_t iterations);
 
int main (void) 
{
 uint32_t start = 0;
 uint32_t finish = 0; 
 
 __disable_irq();
 
 for (;;)
 {
 start = DWT->CYCCNT;
 test_function(iterations);
 finish= DWT->CYCCNT;
 total_for_watch = finish - start; 
 }
 
 return 0;
}
 
void test_function (uint32_t iterations)
{
 uint32_t cnt = 0;
 
 /* Dummy code */ 
 while (cnt < iterations)
 { 
 cnt++;
 }
}

A summary of the results follows

The anomaly is that in test case 3 to 4 iterations go from 10 000 to 100 000 (x 10) and  total_for_watch go from 20020 cycles to 150029 cycles (x 7.5) ! 

All tests are with Compiler ARM V5 (in Keil uVision 5.36) without optimizations in C99 mode.

Note. In other tests not documented here I have seen that the total_for_watch  values are consistent with time measurements obtained using digital output 

toggles and oscilloscope. I therefore believe the total_for_watch values to be reliable.

[TDK]

You're still not calling the function multiple times within the same program. Create a program with all of them within the same program. Otherwise, you still have a compilation step which is changing the code.

uint32_t start = DWT->CYCCNT;
test_function(100);
uint32_t end1 = DWT->CYCCNT - start; 
test_function(1000);
uint32_t end2 = DWT->CYCCNT - end1; 
test_function(10000);
uint32_t end3 = DWT->CYCCNT - end2; 
test_function(100000);
uint32_t end4 = DWT->CYCCNT - end3; 
test_function(1000000);
uint32_t end5 = DWT->CYCCNT - end4; 

In your disassembly, you can see the compiler is doing different things based on the value you're using. It does seem like an alignment thing.

 0x08000374: f2427010 B..p MOV r0,#0x2710
 0x08000378: f000f80a .... BL test_function ; 0x8000390
 
 
 0x08000374: 4805 .H LDR r0,[pc,#20] ; [0x800038c] = 0x186a0
 0x08000376: f000f80d .... BL test_function ; 0x8000394

[Silvano]

Hi @Community member​, @KiptonM​, @TDK​  and @Community member​ 

TDK is right. Test results follow

The code used follows.

#include "stm32f767xx.h"
 
void test_function (uint32_t iterations);
 
uint32_t last_dwt_cyccnt, current_dwt_cyccnt;
 
/* Variable for watch */
volatile uint32_t computing_time_1, computing_time_2, computing_time_3,
 computing_time_4, computing_time_5, computing_time_6; 
 
int main (void) 
{
 __disable_irq();
 
 for (;;)
 {
 last_dwt_cyccnt = DWT->CYCCNT;
 
 test_function(100UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_1 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 
 test_function(1000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_2 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 
 test_function(10000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_3 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 
 test_function(100000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_4 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 
 test_function(1000000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_5 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 
 test_function(10000000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_6 = current_dwt_cyccnt - last_dwt_cyccnt; 
 }
 
 return 0;
}
 
void test_function (uint32_t iterations)
{
 volatile uint32_t cnt = 0;
 
 /* Dummy code */ 
 while (cnt < iterations)
 { 
 cnt++;
 }
}

But my original problem was that it seemed strange to me (and therefore I thought I had made some mistakes) that very small changes in the code could result in very large changes in the runtime. For example, consider the following code, which I call %2.

#include "stm32f767xx.h"
 
void test_function (uint32_t iterations);
 
uint32_t last_dwt_cyccnt, current_dwt_cyccnt;
 
/* Variable for watch */
volatile uint32_t computing_time_1, computing_time_2, computing_time_3; 
volatile uint32_t computing_time_4, computing_time_5, computing_time_6; 
 
int main (void) 
{
 
 volatile uint32_t system_core_clock_for_watch = SystemCoreClock; // @1
 
 __disable_irq();
 
 for (;;)
 {
 last_dwt_cyccnt = DWT->CYCCNT;
 test_function(1000000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_5 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 }
 
 return 0;
}
 
void test_function (uint32_t iterations)
{
 volatile uint32_t cnt = 0;
 
 /* Dummy code */ 
 while (cnt < iterations)
 { 
 cnt++;
 }
}

Then consider the following code, which I call %3.

The only difference is that in% 3 the line 14

volatile uint32_t system_core_clock_for_watch = SystemCoreClock; // @1

present in% 2 has been deleted.

#include "stm32f767xx.h"
 
void test_function (uint32_t iterations);
 
uint32_t last_dwt_cyccnt, current_dwt_cyccnt;
 
/* Variable for watch */
volatile uint32_t computing_time_1, computing_time_2, computing_time_3; 
volatile uint32_t computing_time_4, computing_time_5, computing_time_6; 
 
int main (void) 
{
 
 //volatile uint32_t system_core_clock_for_watch = SystemCoreClock; // @1
 
 __disable_irq();
 
 for (;;)
 {
 last_dwt_cyccnt = DWT->CYCCNT;
 test_function(1000000UL);
 current_dwt_cyccnt = DWT->CYCCNT;
 computing_time_5 = current_dwt_cyccnt - last_dwt_cyccnt;
 last_dwt_cyccnt = current_dwt_cyccnt;
 }
 
 return 0;
}
 
void test_function (uint32_t iterations)
{
 volatile uint32_t cnt = 0;
 
 /* Dummy code */ 
 while (cnt < iterations)
 { 
 cnt++;
 }
}

!!! computing_time_5 went from 5 444 543 cycles to 15 000 038 cycles (3 x).

See ATTACH_FILE_#3 list files %2.lst about code %2 and ATTACH_FILE_#3 list files %3.lst about code %3 (ARM compiler V5, C99, optimization level 0 (-O0)).

I also found similar behaviors also making other very small changes in the code other than the one now shown or with the ARM 6 compiler.

I am new with ARM. My previous experiences are related to Microchip's simple dsPIC MCUs or Motorola's older 68000 CPUs but I have never experienced such a high sensitivity of execution times towards the code.

Am I the only one who finds this behavior "strange" or for you who move in the ARM world with more experience than me is this behavior normal ?

[LCE]

I don't have much "ARM experience" (more with AVRs & FPGAs), anyway, that behavior is really strange.

Maybe somehow the debugging is kinda intrusive, always checking the volatile variable?

[Silvano]

I had similar problems without using the debugger, but measuring times by toggling a digital output and measuring the period with an oscilloscope

For example, consider the following code

#include "stm32f767xx.h"
 
 
void test_function (uint32_t iterations);
void initialize (void);
 
 
int main (void) 
{
 volatile uint32_t system_core_clock_for_watch = SystemCoreClock; // @1
 
 
 __disable_irq();
 initialize();
 
 for (;;)
 {
 GPIOB->ODR ^= GPIO_ODR_OD10; // Toggle PB10
 test_function(1000000UL);
 }
 
 return 0;
}
 
void test_function (uint32_t iterations)
{
 volatile uint32_t cnt = 0;
 
 
 /* Dummy code */ 
 while (cnt < iterations)
 { 
 cnt++;
 }
}
 
void initialize (void)
{
 volatile uint8_t cnt = 0; /* NOTE. cnt is only used to generate a small 
 delay. volatile ensures that compiler optimizations don't delete the 
 delay. */
 
 
 /*--------------------------------------------------------------------------
 * Configure PB10 (CN10.32 in NUCLEO-F767ZI) as DO
 *------------------------------------------------------------------------*/
 
 /* Enable IO port B clock */
 RCC->AHB1ENR |= RCC_AHB1ENR_GPIOBEN;
 
 /* Small delay. 
 NOTE. From RM0410 rev 4 par par 5.2.12.
 "Just after enabling the clock for a peripheral, software must wait for 
 a 2 peripheral clock cycles delay before accessing the peripheral
 registers." 
 Port B is on AHB bus and AHB bus frequency is equal to HCLK frequency
 that is equal to 216 MHz.*/
 cnt = 0;
 while (cnt < 100)
 {
 cnt++;
 }
 
 /* Configure MODER10 = 01b <==> General purpose output mode */
 GPIOB->MODER &= ~GPIO_MODER_MODER10;
 GPIOB->MODER |= (0 * GPIO_MODER_MODER10_1) | (1 * GPIO_MODER_MODER10_0);
 
 /* Configure OSPEEDR10 = 00b <==> low speed */
 GPIOB->OSPEEDR &= ~GPIO_OSPEEDR_OSPEEDR10;
 GPIOB->OSPEEDR |= (0 * GPIO_OSPEEDR_OSPEEDR10_1) | 
 (0 * GPIO_OSPEEDR_OSPEEDR10_0);
}

Period measured with oscilloscope of signal at PB10 digital output is 687.7 ms

 

If you delete line 10

volatile uint32_t system_core_clock_for_watch = SystemCoreClock; // @1

the period becomes 1.892 s (x 2.75)