STM32 DWT cycle counter (CYCCNT) surprising behavior (rust)

Question

I'm attempting to benchmark a number of functions destined for embedded use (STM743 arm cortex m7 microcontroller). All of the code is written in Rust. To benchmark my functions, I'm using the DWT CYCCOUNT (cycle counter) to count the number of processor clock cycles required for each of these functions to execute. I then display the count on the host computer with semihosting. I'm seeing results that depend on changes in the code that I don't believe should have an effect. Here's the code I'm using

#![no_std]
#![no_main]

use panic_halt as _;
use cortex_m::peripheral::{Peripherals, DWT};
use cortex_m_rt::entry;
use cortex_m_semihosting::hprintln;
use core::f32::consts::PI;

use trig_lib::{sin, cos, atan2};

const U32_MAX: u32 = 4_294_967_295u32;

macro_rules! op_cyccnt_diff {
    ( $( $x:expr )* ) => {
        {
            let before = DWT::get_cycle_count();
            $(
                let res = $x;
            )*
            let after = DWT::get_cycle_count();
            let diff =
                if after >= before {
                    after - before
                } else {
                    after + (U32_MAX - before)
                };
            (res, diff)
        }
    };
}

#[entry]
fn main() -> ! {
    let mut peripherals = Peripherals::take().unwrap();
    peripherals.DWT.enable_cycle_counter();
    let mut theta: f32 = 0.;
    let dtheta: f32 = 2. * PI / 10.6;

    loop {
        let (res, diff) = op_cyccnt_diff!(sin(theta));
        // test 1
        hprintln!("  sin({:.6})={:.6}: {}", theta, res, diff).unwrap();
        // test 2
        // hprintln!("  sin={:.6}: {}", res, diff).unwrap();

        theta += dtheta;
        if theta > 2. * PI {
            theta -= 2. * PI;
        }
    }
}

As you probably guessed, sin, cos, and atan2 are the trigonometric functions I'm benchmarking. I've only shown the test for sin here. I don't believe their implementation is critical to this question and their interface is standard.

If I use // test 1 I get something like:

  sin(0.000000)=0.000000          : 101
  sin(0.592753)=0.559139          : 171
  sin(1.185507)=0.927135          : 164
  sin(1.778260)=0.978837          : 140
  sin(2.371013)=0.697104          : 140
  sin(2.963767)=0.177065          : 147
  sin(3.556520)=-0.403504         : 172
  sin(4.149273)=-0.846134         : 179
  sin(4.742027)=-0.999605         : 172
  sin(5.334780)=-0.813040         : 172
  sin(5.927534)=-0.348535         : 172
  sin(0.237102)=0.235117          : 164
  sin(0.829855)=0.738394          : 164
  sin(1.422608)=0.989249          : 171
  sin(2.015362)=0.903282          : 140
  sin(2.608115)=0.508991          : 140

However, if I use // test 2 I get something like:

  sin=0.000000          : 99
  sin=0.559139          : 121
  sin=0.927135          : 121
  sin=0.978837          : 122
  sin=0.697104          : 122
  sin=0.177065          : 122
  sin=-0.403504         : 151
  sin=-0.846134         : 151
  sin=-0.999605         : 158
  sin=-0.813040         : 151
  sin=-0.348535         : 151
  sin=0.235117          : 121
  sin=0.738394          : 121
  sin=0.989249          : 121
  sin=0.903282          : 122
  sin=0.508991          : 122

The difference is whether I print the theta value. The results appear to indicate that not printing the theta value requires fewer clock cycles than printing it. However, the only statement between getting the beginning and ending cycle counts is let res = sin(theta);, so I don't see why printing theta has any effect on the result. Moreover, if I replace the hprintln! statement with hprintln!("{}", diff).unwrap(); I get even lower results:

Is my setup somehow flawed? Or, am I not measuring what I think I'm measuring? Why does changing hprintln! change the cycle count result? Is there a way to perform this test such that the result only depends on the number of clock cycles required to compute sin(theta)?

I've tried looking at the disassembly, but the compiler inlines a lot of functions and so it's difficult to map instructions to source code.

Edit

I tried wrapping the cycle count code in a compiler fence like so:

compiler_fence(Ordering::Acquire);
let before = DWT::get_cycle_count();
$(
    let res = $x;
)*
let after = DWT::get_cycle_count();
compiler_fence(Ordering::Release);

Unfortunately, this doesn't seem to have an effect.

Edit 2

I've moved the I/O out of the loop to attempt to separate the code I'm benchmarking with the displayed output. The relevant change is

    let mut i: usize = 0;
    let mut theta_log: [f32; ITER] = [0.; ITER];
    let mut sin_res_log: [f32; ITER] = [0.; ITER];
    let mut sin_diff_log: [u32; ITER] = [0; ITER];

    let mut cos_res_log: [f32; ITER] = [0.; ITER];
    let mut cos_diff_log: [u32; ITER] = [0; ITER];

    while i < ITER {
        let (res, diff) = op_cyccnt_diff!(sin(theta));
        theta_log[i] = theta;
        sin_res_log[i] = res;
        sin_diff_log[i] = diff;

        // let (res, diff) = op_cyccnt_diff!(cos(theta));
        // cos_res_log[i] = res;
        // cos_diff_log[i] = diff;

        theta += dtheta;
        if theta > 2. * PI {
            theta -= 2. * PI;
        }

        i += 1;
    }

    for i in 0..ITER {
        hprintln!("  sin({:.6})={:.6}          : {}", theta_log[i], sin_res_log[i], sin_diff_log[i]).unwrap();
        // hprintln!("  cos({:.6})={:.6}          : {}", theta_log[i], cos_res_log[i], cos_diff_log[i]).unwrap();
        // hprintln!("----------------------------").unwrap();
    }

    loop {
    }

The output for just the sine is all 2's and a few 8's (this seems too low...) and the output when the cosine part is uncommented is back up in the 100s.

STM32 DWT cycle counter (CYCCNT) surprising behavior (rust)

Edit

Edit 2

0 Answers