Pages: [1] 2   Go Down
Author Topic: Serial.print messing with Timer Interrupts  (Read 2705 times)
0 Members and 1 Guest are viewing this topic.
0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

I am currently implementing a somewhat timing critical thingy. Basically it uses timer2 to phase lock to a DCF77 signal.

It relies on msTimer2 to generate 1000 ticks per second. Clock jitter and long term stability is no concern. I compensate for this. The only thing that I really need is that on overage I get a tick each 16000 (+/- 100ppm) clock cycles. Obviously interrupts that are processed while timer2 triggers will introduce jitter into this schedule. This is something I understand and that is fine with me. Also it is clear that any means that blocks interrupts for more than 1ms will sooner or later block 2 timer 2 interrupts in a row and cause that I will lose timer2 ticks. Also understood.

Now here is what happens: if I let my code run everything is fine. But if I add Serial.print statements outside of all interrupts and if the statements print more than ~100 chars per second, then I start to miss some of the timer2 ticks. After 300s this is something in the order of magnitude of 50 ticks. So I assume I roughly lose about one 1ms tick per 6s.

BTW: I stopped timer 0, so the only interrupt sources I can think of are:
analog conversion,
timer 2,
serial transmission (sending, no receive)

Has anyone an idea what exactly could be blocking long enough to cause this issue?

It is not that it kills my code. Once I drop the (debug) print statements it works fine. What bugs me is that I can not find out why this happens. Has anyone any ideas what could cause such a behaviour?
Logged

Check out my experiments http://blog.blinkenlight.net

Global Moderator
Dallas
Offline Offline
Shannon Member
*****
Karma: 210
Posts: 13039
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

Quote
analog conversion,

Should only be enabled if you enabled it.  Did you?
Logged

Global Moderator
Dallas
Offline Offline
Shannon Member
*****
Karma: 210
Posts: 13039
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

Quote
if the statements print more than ~100 chars per second

What baud rate?
Logged

0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

115200 baud
Logged

Check out my experiments http://blog.blinkenlight.net

0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

The interesting part is: it does not matter if I print 100 cps or 300cps. The impact on lost ticks is imperceptible. I am really puzzled.
Logged

Check out my experiments http://blog.blinkenlight.net

Global Moderator
Offline Offline
Brattain Member
*****
Karma: 506
Posts: 19120
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

But if I add Serial.print statements outside of all interrupts and if the statements print more than ~100 chars per second, then I start to miss some of the timer2 ticks.

You say you are printing at 115200 baud. At that rate each character will be clocked out at 87 uS. How much Serial.print are you doing at one time? The Serial.prints are actually sent in an ISR, so they will be affecting interrupts.
Logged


0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

Argh - I think we are getting closer. In HardwareSerial.cpp it says

Code:
void serialEventRun(void)
{
#ifdef serialEvent_implemented
  if (Serial.available()) serialEvent();
#endif
#ifdef serialEvent1_implemented
  if (Serial1.available()) serialEvent1();
#endif
#ifdef serialEvent2_implemented
  if (Serial2.available()) serialEvent2();
#endif
#ifdef serialEvent3_implemented
  if (Serial3.available()) serialEvent3();
#endif
}


#if !defined(USART0_UDRE_vect) && defined(USART1_UDRE_vect)
// do nothing - on the 32u4 the first USART is USART1
#else
#if !defined(UART0_UDRE_vect) && !defined(UART_UDRE_vect) && !defined(USART0_UDRE_vect) && !defined(USART_UDRE_vect)
  #error "Don't know what the Data Register Empty vector is called for the first UART"
#else
#if defined(UART0_UDRE_vect)
ISR(UART0_UDRE_vect)
#elif defined(UART_UDRE_vect)
ISR(UART_UDRE_vect)
#elif defined(USART0_UDRE_vect)
ISR(USART0_UDRE_vect)
#elif defined(USART_UDRE_vect)
ISR(USART_UDRE_vect)
#endif
{
  if (tx_buffer.head == tx_buffer.tail) {
// Buffer empty, so disable interrupts
#if defined(UCSR0B)
    cbi(UCSR0B, UDRIE0);
#else
    cbi(UCSRB, UDRIE);
#endif
  }
  else {
    // There is more data in the output buffer. Send the next byte
    unsigned char c = tx_buffer.buffer[tx_buffer.tail];
    tx_buffer.tail = (tx_buffer.tail + 1) % SERIAL_BUFFER_SIZE;

  #if defined(UDR0)
    UDR0 = c;
  #elif defined(UDR)
    UDR = c;
  #else
    #error UDR not defined
  #endif
  }
}
#endif
#endif

#ifdef USART1_UDRE_vect
ISR(USART1_UDRE_vect)
{
  if (tx_buffer1.head == tx_buffer1.tail) {
// Buffer empty, so disable interrupts
    cbi(UCSR1B, UDRIE1);
  }
  else {
    // There is more data in the output buffer. Send the next byte
    unsigned char c = tx_buffer1.buffer[tx_buffer1.tail];
    tx_buffer1.tail = (tx_buffer1.tail + 1) % SERIAL_BUFFER_SIZE;

    UDR1 = c;
  }
}
#endif

#ifdef USART2_UDRE_vect
ISR(USART2_UDRE_vect)
{
  if (tx_buffer2.head == tx_buffer2.tail) {
// Buffer empty, so disable interrupts
    cbi(UCSR2B, UDRIE2);
  }
  else {
    // There is more data in the output buffer. Send the next byte
    unsigned char c = tx_buffer2.buffer[tx_buffer2.tail];
    tx_buffer2.tail = (tx_buffer2.tail + 1) % SERIAL_BUFFER_SIZE;

    UDR2 = c;
  }
}
#endif

#ifdef USART3_UDRE_vect
ISR(USART3_UDRE_vect)
{
  if (tx_buffer3.head == tx_buffer3.tail) {
// Buffer empty, so disable interrupts
    cbi(UCSR3B, UDRIE3);
  }
  else {
    // There is more data in the output buffer. Send the next byte
    unsigned char c = tx_buffer3.buffer[tx_buffer3.tail];
    tx_buffer3.tail = (tx_buffer3.tail + 1) % SERIAL_BUFFER_SIZE;

    UDR3 = c;
  }
}
#endif

However I would have expected that this is not an issue because it returns after each character. So now my theory: my prints are to fast --> the serial buffer may sometimes be completely full --> serial interrupts will occur virtually each 87uS. Timer 2 Interrupts occur each 1000uS. Of course sometimes serial ISR may be triggered while timer 2 ISR is busy.  So far so good.

This is OK. But what I do not understand: how would this make me lose 1 timer 2 tick? I just do not get it.
Logged

Check out my experiments http://blog.blinkenlight.net

Seattle, WA USA
Online Online
Brattain Member
*****
Karma: 644
Posts: 50478
Seattle, WA USA
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

Quote
So now my theory: my prints are to fast
Too frequent, maybe. Not too fast.
Logged

Global Moderator
Offline Offline
Brattain Member
*****
Karma: 506
Posts: 19120
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

This might be a good time to show your code. I understand that with 87 uS per output character you would fit 11 or so of them into 1000 uS, and timer interrupts are higher priority than serial interrupts. So really, you should potentially only be slightly out. Maybe you are doing something else as well?
Logged


0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

OK, but here comes the disclaimer. This is work in progress, the code is nowhere close to done. It requires an open collector DCF77 module @ pin 19 and is assumes that all pins have leds connected to them ("Blinkenlight Shield").

The code is in a transitional state. So it is NOT a DCF77 decoder yet. It is also not yet documented. But you asked for it smiley-wink Please do not distribute or ask for in depth comments. I will document it in my Blinkenlightblog once it is finished. The code works as expected without the debug calls. Once the debug calls are in it slowly gets out of sync. If I remove the print statements it stays in sync.

Logged

Check out my experiments http://blog.blinkenlight.net

Global Moderator
Offline Offline
Brattain Member
*****
Karma: 506
Posts: 19120
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

So far I can't see anything obvious. I note that you are doing analogRead inside an ISR, so the time left (with interrupts enabled) is now down to 900 uS or less. Still, with serial interrupts every 87 uS that shouldn't push you over the 900 uS limit. Can you time (eg. with strobing pins and a logic analyzer) exactly how long the ISR takes? Maybe it is a lot longer than you think.

How do you know you are missing the ticks?
Logged


0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

I know because it is a phase locked loop that locks to DCF77. If I reduce the prints the lock stays exactly where it should. If I have all debug prints active the lock starts to drift out of phase. If I increase the band width while debugging the lock is able to follow faster and thus stays in phase. So I assume my code behaves as expected.

The point is I noticed it when I tried to tune the lock parameters. If the parameters would have been correct the crystal would be off by ~300ppm. I double checked with a frequency counter and the crystal is accurate to 10ppm. I checked it with the ISR active. Then I noticed that the behaviour changes if I change the print statements.

This is how I assume that the print statements cause the issue.
Logged

Check out my experiments http://blog.blinkenlight.net

Global Moderator
Offline Offline
Brattain Member
*****
Karma: 506
Posts: 19120
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

Can you time how long the ISR is active? Toggle a pin at the start and the end of it, measure the difference.
Logged


0
Offline Offline
Faraday Member
**
Karma: 24
Posts: 3496
20 LEDs are enough
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

Hi Nick, here is the toggle code:

Code:

#include <MsTimer2.h>
#include "dcf77_demodulator.h"

const uint8_t dcf77_sample_pin = 19; // A5
const uint8_t dcf77_analog_sample_pin = 5;

void process_one_sample() {
    digitalWrite(17,HIGH);
    const uint8_t sampled_data = analogRead(dcf77_analog_sample_pin)>200? 1: 0;
   
    DCF77_Demodulator::detector(sampled_data);
   
    digitalWrite(17,LOW);
}

void setup() {
    Serial.begin(115200); 

    pinMode(dcf77_sample_pin, INPUT);
    digitalWrite(dcf77_sample_pin, HIGH);
   
    DCF77_Demodulator::setup();
    MsTimer2::set(1, process_one_sample);
    MsTimer2::start();

    // disable timer0
    TIMSK0 = 0;

    pinMode(17, OUTPUT);
}

void loop() {
    DCF77_Demodulator::debug();
    DCF77_Decoder::debug();   
}

Because I was lazy I just took a picture of the attached LED with the same trick as described here: http://blog.blinkenlight.net/experiments/measurements/shutter-speed/ (see attachment).

The ticks are of course 1000us apart. As you can clearly see the duty cycle is below 50%. So this should not be causing the issue. I also can not see any significant jitter.


* IMG_3157.JPG (50.52 KB, 2592x1728 - viewed 18 times.)
Logged

Check out my experiments http://blog.blinkenlight.net

Global Moderator
Offline Offline
Brattain Member
*****
Karma: 506
Posts: 19120
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

I would rather have figures than dots. I am trying to rule in, or rule out, a hypothesis that the time taken in the ISR is long enough that, if delayed a bit by a serial interrupt, and then it takes long enough to overshoot the next 1000 uS, then it is delayed a bit more, that you might eventually creep over 2 x 1000 uS intervals.
Logged


Pages: [1] 2   Go Up
Jump to: