title: Why does sleeping increase the execution time of an independent piece of code that is executed before/afterwards?
body: <p>I noticed something really strange that I haven't seen before. The basic setup is described in this pseudo code:</p>
  
  <pre class="lang-none prettyprint-override"><code>TARGET_LOOP_TIME = X
  
  loop forever:
      before = now()
      payload()
      payload_time = now() - before
      sleep(TARGET_LOOP_TIME - payload_time)
  </code></pre>
  
  <p>This setup is fairly common, e.g. for keeping the loop at 60 FPS. The interesting part is: <strong>the <code>payload_time</code> depends on the sleep duration!</strong> If the <code>TARGET_LOOP_TIME</code> is high and the program will thus sleep a lot, the <code>payload_time</code> is way higher compared to when the program does not sleep at all.</p>
  
  <p>To measure this, I wrote this program:</p>
  
  <pre class="lang-rust prettyprint-override"><code>use std::time::{Duration, Instant};
  
  const ITERS: usize = 100;
  
  fn main() {
      // A dummy variable to prevent the compiler from removing the dummy prime
      // code.
      let mut x = 0;
  
      // Iterate over different target loop times
      for loop_time in (1..30).map(|n| Duration::from_millis(n)) {
          let mut payload_duration = Duration::from_millis(0);
  
          for _ in 0..ITERS {
              let before = Instant::now();
              x += count_primes(3_500);
              let elapsed = before.elapsed();
              payload_duration += elapsed;
  
              // Sleep the remaining time
              if loop_time &gt; elapsed {
                  std::thread::sleep(loop_time - elapsed);
              }
          }
  
          let avg_duration = payload_duration / ITERS as u32;
          println!("loop_time {:.2?}  \t=&gt; {:.2?}", loop_time, avg_duration);
      }
  
      println!("{}", x);
  }
  
  /// Dummy function.
  fn count_primes(up_to: u64) -&gt; u64 {
      (2..up_to)
          .filter(|n| (2..n / 2).all(|d| n % d != 0))
          .count() as u64
  }
  </code></pre>
  
  <p>I iterate over different target loop times to test (1ms to 30ms) and iterate for <code>ITERS</code> many times. I compiled this with <code>cargo run --release</code>. On my machine (Ubuntu), the program outputs:</p>
  
  <pre class="lang-none prettyprint-override"><code>loop_time 1.00ms    =&gt; 3.37ms
  loop_time 2.00ms    =&gt; 3.38ms
  loop_time 3.00ms    =&gt; 3.17ms
  loop_time 4.00ms    =&gt; 3.25ms
  loop_time 5.00ms    =&gt; 3.38ms
  loop_time 6.00ms    =&gt; 4.05ms
  loop_time 7.00ms    =&gt; 4.09ms
  loop_time 8.00ms    =&gt; 4.48ms
  loop_time 9.00ms    =&gt; 4.43ms
  loop_time 10.00ms   =&gt; 4.22ms
  loop_time 11.00ms   =&gt; 4.59ms
  loop_time 12.00ms   =&gt; 5.53ms
  loop_time 13.00ms   =&gt; 5.82ms
  loop_time 14.00ms   =&gt; 6.18ms
  loop_time 15.00ms   =&gt; 6.32ms
  loop_time 16.00ms   =&gt; 6.96ms
  loop_time 17.00ms   =&gt; 8.00ms
  loop_time 18.00ms   =&gt; 7.97ms
  loop_time 19.00ms   =&gt; 8.28ms
  loop_time 20.00ms   =&gt; 8.75ms
  loop_time 21.00ms   =&gt; 9.70ms
  loop_time 22.00ms   =&gt; 9.57ms
  loop_time 23.00ms   =&gt; 10.48ms
  loop_time 24.00ms   =&gt; 10.29ms
  loop_time 25.00ms   =&gt; 10.31ms
  loop_time 26.00ms   =&gt; 10.82ms
  loop_time 27.00ms   =&gt; 10.84ms
  loop_time 28.00ms   =&gt; 10.82ms
  loop_time 29.00ms   =&gt; 10.91ms
  </code></pre>
  
  <p>I made a plot of those numbers (the <code>sleep_time</code> is <code>max(0, loop_time - avg_duration)</code>):</p>
  
  <p><a href="https://i.stack.imgur.com/AbvrL.png" rel="noreferrer"><img src="https://i.stack.imgur.com/AbvrL.png" alt="enter image description here"></a></p>
  
  <p>When the program does not sleep at all, the payload needs approximately 3.3ms (as the first three measurements show). As soon as the loop starts to sleep after the payload, the payload duration rises! In fact, it increases to roughly 10.5ms where it stays. Sleeping even longer does not increase the payload time.</p>
  
  <p><strong>Why? Why does the execution time of the piece of code depend on something I do afterwards (or before)?</strong> That does not make sense to me! It looks like the CPU says "I'm gonna sleep afterwards anyway, so let's take it slowly". I thought about caching effects, especially of the instruction cache, but loading instruction data from the main memory does not take 7ms! Something else is going on here!</p>
  
  <p>Is there a way to fix this? I.e. to make the payload execute as quickly as possible regardless of sleep time?</p>