0

I'm trying to write some extremely fast code for the ESP8266, so I'm trying to figure out how to time things. I've discovered CCLOCK, a register that reflects the number of clock cycles since startup. (https://github.com/esp8266/Arduino/issues/4632#issuecomment-380632906, and other references.) In testing it out, though, I've encountered some weird behavior. Consider the following code:

static inline volatile uint32_t asm_ccount(void) {
    uint32_t r;
    asm volatile ("rsr %0, ccount" : "=r"(r));
    return r;
}

char outgoingPacket[4];

...

void loop() {

  // ... some stuff ...

  uint32_t startTime = asm_ccount();
  uint32_t stopTime = asm_ccount();
  uint32_t elapsed = stopTime-startTime;
  
  outgoingPacket[0] = (elapsed >> 24) & 0xff;
  outgoingPacket[1] = (elapsed >> 16) & 0xff;
  outgoingPacket[2] = (elapsed >> 8) & 0xff;
  outgoingPacket[3] = elapsed & 0xff;
  Udp.beginPacket(targetUdpIp, targetUdpPort);
  Udp.write(outgoingPacket, 4);
  Udp.endPacket();
}

(On my computer, I have basically the following Java code running to receive these messages:)

    while (true) {
      DatagramPacket packet = new DatagramPacket(buf, buf.length);
      socket.receive(packet);

      byte[] data = packet.getData();
      StringBuilder sb1 = new StringBuilder();
      StringBuilder sb2 = new StringBuilder();
      for (int i = 0; i < packet.getLength(); i++) {
        sb1.append(String.format("%8s", Integer.toString(((int) data[i]) & 0xFF, 2)).replace(' ', '0'));
        sb2.append(String.format("%2s", Integer.toString(((int) data[i]) & 0xFF, 16)).replace(' ', '0'));
      }
      System.out.println(sb1 + " " + Integer.parseInt(sb2.toString(), 16));
    }

(Yes, it's a little hacky, I know, but the results have seemed correct.)

Now, most of the time, the output looks like

00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000000000000001 1

But about 5 times in 77000, I'll get lines like

00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000000110101000 424
00000000000000000000000000000001 1
00000000000000000000000000000001 1
...
00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000010010100001 1185
00000000000000000000000000000001 1
00000000000000000000000000000001 1
...
00000000000000000000000000000001 1
00000000000000000000000000000001 1
00000000000000000000010001001100 1100
00000000000000000000000000000001 1
00000000000000000000000000000001 1

I ran the code for 1 minute 4 seconds, and got 3 counts of 424, 1 of 1100, and 1 of 1185. It seems particularly odd that 424 would show up three times.

Given that, as far as I understand, the relevant lines of code (the two calls to asm_ccount) would have been compiled to a given set of instructions, I'd have expected it to take exactly the same number of cycles every time.

Why is this not happening?

Is it interrupts? Something something caching? Does that register not actually work as claimed or as I understand? Have I done something dumb in the transmission or logging code? Something else?

  • You've got interrupts running and interrupting your code. Those take some cycles to run. – Delta_G Jul 8 at 4:18
  • aHAH! I think you're right. When I disable interrupts around the critical code, its timing becomes almost perfectly stable. ...But then it stops working after a few dozen loops, so I guess I can't do that, haha. If you want to make your comment an answer, I'll accept it. – Erhannis Jul 8 at 4:40
2

You've got interrupts running and interrupting your code. Those take some cycles to run.

| improve this answer | |

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.