Timing of Hardware Semaphore

[cbcooper]

We're using a STM32H747IGT6 and using hardware semaphores to coordinate between the two cores.

On the CM4 I've set up TIMER3 to run at full blast:

    LL_APB1_GRP1_EnableClock(LL_APB1_GRP1_PERIPH_TIM3);
    LL_TIM_SetPrescaler(TIM3, 0); // Count at system clock
    LL_TIM_SetAutoReload(TIM3, 0xFFFF);
    LL_TIM_EnableARRPreload(TIM3);
    LL_TIM_SetCounterMode(TIM3, LL_TIM_COUNTERMODE_UP);
    LL_TIM_SetClockDivision(TIM3, LL_TIM_CLOCKDIVISION_DIV1);
    LL_TIM_EnableCounter(TIM3);

I believe that means the timer is running at 240 MHz (do you agree?) which is one tick every 4.166 nsec.

So now I grab and release a hardware semaphore that is not used anywhere else in the code:

        start_timer = LL_TIM_GetCounter(TIM3);
        WRITE_REG(HSEM->R[TEST_SEMAPHORE_NUMBER], (HSEM_R_LOCK | LL_HSEM_COREID | SHMEM_CM4_PID));
        uint32_t readBack = HSEM->R[TEST_SEMAPHORE_NUMBER];
        if (readBack == (HSEM_R_LOCK | LL_HSEM_COREID | SHMEM_CM4_PID))
            WRITE_REG(HSEM->R[TEST_SEMAPHORE_NUMBER], (LL_HSEM_COREID | SHMEM_CM4_PID));
        end_timer = LL_TIM_GetCounter(TIM3);
        delta_timer = end_timer - start_timer;

and inspect the value of 'delta_timer'.  What I see is that it often takes 84 ticks (350 ns) but on occasion takes as many as 232 (967 ns).

Why does it sometimes take 3x longer, since no other process in the system is using that hardware semaphore?   Can the HSEM only think about one semaphore at a time, and some other semaphore is being processed?

[TDK]

Wrap it in __enable_irq/__disable_irq to ensure no interrupts fire in the middle.

[cbcooper]

Woah ... ok, this is a good news / bad news situation.

Good news: you were 100% correct, other interrupts were firing in the middle.  If I wrap that code in __enable_irq/__disable_irq it drops from 350 - 967 nsec to a consistent 75 nsec.  Nice!

Bad news: I added some code in increment counters in all 4 of my IRQ handlers, trying to figure out which one is eating up all my CPU time, and not one of them is firing (which is what I expected).  That means there are IRQs firing in the CM4 that I don't know anything about, and apparently firing an insane amount.

I've inherited this code so don't know it completely, but it's relatively straightforward and the hardware configuration code is pretty clear.

Is there a clever way to figure out what interrupt(s) are firing on the CM4?

[TDK]

Look at VECTPENDING in SCB->ICSR just prior to re-enabling the interrupt.

[cbcooper]

Here's the hardware configuration:

    ConfigureDAC();
    ConfigureADC();
    ConfigureTimer1(); 
    ConfigureTimer2();
    ConfigureTimer3();
    ConfigureHSEM();

void ConfigureDAC()
{
   // Configure GPIO pins
   LL_GPIO_SetPinMode(GPIOA, LL_GPIO_PIN_5, LL_GPIO_MODE_ANALOG);
   LL_APB1_GRP1_EnableClock(LL_APB1_GRP1_PERIPH_DAC12);
   LL_APB1_GRP2_EnableClock(LL_APB1_GRP2_PERIPH_OPAMP);
  /* DAC configuration*/
   // LL_DAC_SetTriggerSource(DAC1, LL_DAC_CHANNEL_2, LL_DAC_TRIG_SOFTWARE);
   LL_DAC_SetTriggerSource(DAC1, LL_DAC_CHANNEL_2, LL_DAC_TRIG_EXT_TIM1_TRGO);
   LL_DAC_ConfigOutput
   (  
      DAC1, 
      LL_DAC_CHANNEL_2, 
      LL_DAC_OUTPUT_MODE_NORMAL, 
      LL_DAC_OUTPUT_BUFFER_ENABLE, 
      LL_DAC_OUTPUT_CONNECT_GPIO
   );
   LL_DAC_Enable(DAC1, LL_DAC_CHANNEL_2);
   LL_DAC_ConvertData12RightAligned(DAC1, LL_DAC_CHANNEL_2, 0xFFF);
   LL_DAC_EnableTrigger(DAC1, LL_DAC_CHANNEL_2);
}

No interrupts enabled there.

void ConfigureADC()
{
    // Enable ADC interrupt
    NVIC_SetPriority(ADC_IRQn, 1);
    NVIC_EnableIRQ(ADC_IRQn);
    LL_ADC_EnableIT_OVR(ADC1);
    LL_ADC_REG_StartConversion(ADC1);
}

Most of the ADC configuration is done by the CM7.  It's got a very exciting interrupt handler.

void ADC_IRQHandler()
{
    numADCIRQs++;
    if(LL_ADC_IsActiveFlag_OVR(ADC1))
      LL_ADC_ClearFlag_OVR(ADC1);
}

I'm not sure why the author felt the need to enable the overrun interrupt and then ignore it, but this function isn't getting called anyway (numADCIRQs stays at zero)

void ConfigureTimer1()
{
    // Allocate TIM1 to the CM4.  It looks like TIM1 uses the APB2 clock.
   LL_APB2_GRP1_EnableClock(LL_APB2_GRP1_PERIPH_TIM1);

   // In lcs_cm7_bsp.c we see this:
   // LL_RCC_SetAPB2Prescaler(LL_RCC_APB2_DIV_2);
   // This sets the D2 domain APB2 prescaler to "rcc_hclk1 / 2"

   LL_TIM_SetPrescaler(TIM1, 0); // Counter runs at full speed

   /*
   * "In upcounting mode, the counter counts from 0 to the auto-reload value (content of the
      TIMx_ARR register), then restarts from 0 and generates a counter overflow event."
   */
   // Set the auto-reload to LCS_ADC_SAMPLE_PERIOD = 240 so we get one overflow event every 1 usec (?)
   LL_TIM_SetAutoReload(TIM1, LCS_ADC_SAMPLE_PERIOD);

   LL_TIM_SetCounterMode(TIM1, LL_TIM_COUNTERMODE_UP);

   LL_TIM_SetRepetitionCounter(TIM1, 0);

   // Set TIM1's MMS (Master Mode Selection) to "Update"
   // ("The update event is selected as trigger output (TRGO). For instance a master
   //   timer can then be used as a prescaler for a slave timer.")
   LL_TIM_SetTriggerOutput(TIM1, LL_TIM_TRGO_UPDATE);

   // Set TIM1's CCMR ("capture/compare mode register")
   // CC1S ("capture/compare 1 selection") to 0 (CC1 channel is output)
   // and OC1M ("output compare 1 mode") to 0110 (PWM mode 1) meaning
   // "In upcounting, channel 1 is active as long as TIMx_CNT<TIMx_CCR1 else inactive"
   // Since we set CCR1 to 120, this means channel 1 is active 50% of the time
   LL_TIM_OC_SetMode(TIM1, LL_TIM_CHANNEL_CH1, LL_TIM_OCMODE_PWM1);

   LL_TIM_OC_ConfigOutput(TIM1, LL_TIM_CHANNEL_CH1, LL_TIM_OCPOLARITY_HIGH);

   // Set TIM1's CCR1 ("capture/compare register 1") to 120
   LL_TIM_OC_SetCompareCH1(TIM1, (LCS_ADC_SAMPLE_PERIOD / 2));

   LL_TIM_CC_EnableChannel(TIM1, LL_TIM_CHANNEL_CH1);
   LL_TIM_SetTriggerOutput2(TIM1, LL_TIM_TRGO2_OC1);

   LL_TIM_EnableCounter(TIM1);
}

It doesn't look like any TIM1 interrupts are enabled, it's only used to trigger the ADC.  There is an IRQ handler defined for TIM1, but it doesn't get called (numTIM1IRQs stays at zero)

void TIM1_UP_IRQHandler()
{
    numTIM1IRQs++;
    if(LL_TIM_IsActiveFlag_UPDATE(TIM1))
      LL_TIM_ClearFlag_UPDATE(TIM1);
}

 TIM2 is used to generate a 64-bit timer with millisecond accuracy:

void ConfigureTimer2()
{
    // It looks like the CM7 doesn't use any timers so we can use them on the CM4 as much as we want
    // Enable peripheral clock
    LL_APB1_GRP1_EnableClock(LL_APB1_GRP1_PERIPH_TIM2);
    // It appears that the APB1 clock is running at 240 MHz; that's one timer tick every 4.1666 nsec.
    // If we want to update our timer tick variable once a millisecond, that's an auto-reload
    // value of (10^-3 / (4.16666 * 10^-9)) = 240,000
    LL_TIM_SetPrescaler(TIM2, 0); // Count at system clock
    LL_TIM_SetAutoReload(TIM2, 240000);
    LL_TIM_EnableARRPreload(TIM2);
    LL_TIM_SetCounterMode(TIM2, LL_TIM_COUNTERMODE_UP);
    LL_TIM_SetClockDivision(TIM2, LL_TIM_CLOCKDIVISION_DIV1);
    LL_TIM_EnableIT_UPDATE(TIM2);
    LL_TIM_EnableCounter(TIM2);
    NVIC_SetPriority(TIM2_IRQn, 0);  // Highest priority
    NVIC_EnableIRQ(TIM2_IRQn);
}

The IRQ handler only gets called once every millisecond, so the odds of it firing while I'm timing the hardware semaphore are slim:

void TIM2_IRQHandler()
{
    numTIM2IRQs++;
    if (LL_TIM_IsActiveFlag_UPDATE(TIM2))
    {
        LL_TIM_ClearFlag_UPDATE(TIM2);
        LCSBufferIncrementTick();
    }
}

It does seem weird that I never see numTIM2IRQs increment while I'm timing the hardware semaphore.  The hardware semaphore timing code is firing once every 2 microseconds, so that's 500,000 times per second.  If the semaphore timing code takes 350 nsec, we can fit about 3000 of those into one TIM2 tick, so I would expect to have multiple "hits" every second (calls to TIM2_IRQHandler while doing hardware semaphore timing).

void ConfigureTimer3()
{
    // It looks like the CM7 doesn't use any timers so we can use them on the CM4 as much as we want
    // Enable peripheral clock
    LL_APB1_GRP1_EnableClock(LL_APB1_GRP1_PERIPH_TIM3);
    // It appears that the APB1 clock is running at 240 MHz; that's one timer tick every 4.1666 nsec.
    // If we want to update our timer tick variable once a millisecond, that's an auto-reload
    // value of (10^-3 / (4.16666 * 10^-9)) = 240,000
    LL_TIM_SetPrescaler(TIM3, 0); // Count at system clock
    // Tim3 is a 16-bit timer
    LL_TIM_SetAutoReload(TIM3, 0xFFFF);
    LL_TIM_EnableARRPreload(TIM3);
    LL_TIM_SetCounterMode(TIM3, LL_TIM_COUNTERMODE_UP);
    LL_TIM_SetClockDivision(TIM3, LL_TIM_CLOCKDIVISION_DIV1);
    // LL_TIM_EnableIT_UPDATE(TIM2);
    LL_TIM_EnableCounter(TIM3);
    // Don't enable interrupts
    //NVIC_SetPriority(TIM2_IRQn, 0);  // Highest priority
    //NVIC_EnableIRQ(TIM2_IRQn);
}

void ConfigureHSEM()
{
    // Enable HSEM interrupt #2
    NVIC_SetPriority(HSEM2_IRQn, 0);
    NVIC_EnableIRQ(HSEM2_IRQn);
    // Enable interrupt #2 when CFG_UPDATE_SEMAPHORE_FLAG changes
    LL_HSEM_EnableIT_C2IER(HSEM, CFG_UPDATE_SEMAPHORE_FLAG);
}

void HSEM2_IRQHandler(void)
{
    numSemIRQs++;
    // Does a whole bunch of stuff here that probably shouldn't be in an ISR
    // but numSemIRQs isn't getting incremented anyway
}

[cbcooper]

99.9% of the time, ICSR is 0x400000; the other 0.1% of the time it's 0x42C000.

If I'm reading the M4 manual correctly, that's telling me

400000
010000000000000000000000
               000000000 = active exception number
             00 = reserved
            0 = RETTOBASE
      000000 = VECTPENDING (no pending exceptions)
  0000 = reserved
 1 = interrupt pending
0 = reserved

42C000
010000101100000000000000
               000000000 = active exception number
             00 = reserved
            0 = RETTOBASE
      101100 = VECTPENDING
  0000 = reserved
 1 = interrupt pending
0 = reserved

so it is saying "yes, there's an interrupt pending" but no additional information, yes?

I need to read up more on exceptions to find out why there are any pending exceptions.

[cbcooper]

When VECTPENDING is set to 101100, that's decimal 44 which means IRQ28?

[cbcooper]

That seems to make sense.  IRQ28 is TIM2_IRQn, timer 2 is firing once every 1 msec and the hardware semaphore timing code takes 350 - 967 nsec so seeing the TIM2 IRQ 0.1% of the time seems reasonable.

I found an article on developer.arm.com that says this:

Therefore when the ICSR is read at the same time as a SysTick interrupt is triggered, the value returned depends upon the exact cycle in which the register is read relative to the cycle in which the interrupt is pended. For example, the returned value could be 0x04000000 in the cycle where SysTick becomes pended, or 0x0400f000 in the following cycle where the priority has been arbitrated and the SysTick is indicated as the VECTPENDING.

but I'm not sure if that is applicable in this instance

[TDK]

Yes. TIM2_IRQn. Certainly lines up with everything.

> The IRQ handler only gets called once every millisecond, so the odds of it firing while I'm timing the hardware semaphore are slim:

Slim, but also inevitable, yes? Unless you take measures for it not to happen, such as __disable_irq. Also note that timers run by default while debugging is paused.

[cbcooper]

I'm still unclear what's happening the other 99.9% of the time, when ICSR is 0x400000.  I found that article that talked about reading ICSR at the same time as a SysTick interrupt is triggered, but it seems vanishingly unlikely that I am reading ICSR at that exact moment every time - unless the interrupt is being triggered by something I'm doing, but I don't think that's happening.

The only hardware I'm accessing in my hardware semaphore test code is semaphore #4 and timer #3.  I pasted ConfigureTimer3() above, I'm not enabling any interrupts for him, and in ConfigureHSEM() I'm enabling the HSEM interrupt in general but only for semaphore #2:

    // Enable HSEM interrupt #2
    NVIC_SetPriority(HSEM2_IRQn, 0);
    NVIC_EnableIRQ(HSEM2_IRQn);

    // Enable interrupt #2 when CFG_UPDATE_SEMAPHORE_FLAG changes
    LL_HSEM_EnableIT_C2IER(HSEM, CFG_UPDATE_SEMAPHORE_FLAG);