Timer1 and Serial.print

Hello guys I need some help on some timing problem.
My arduino has a really weird behaviour when running with timer1 callback function and serial.print command.

Code is compiling as below:

/***********************************************
 * Nariz Eletronico v1.3
 * Autor: Gabriel Takaoka Nishimura
 * Data: 14/09/2015
 * *********************************************/
#include <TimerOne.h>
#define N_SENSORS 4
#define RELAY_PIN 13
uint8_t sensors[N_SENSORS] = {A1, A2, A3, A4};
unsigned long t_start, t_cycle, t_trigger;
int t_exposure = 5000, // ms
    t_recovery = 3000, // ms
    n_cycles = 2, // each cycle
    n_readings = 16, // per cycle
    current_cycle = 1, 
    i; // aux var

/** configure analog pins as inputs, relay as output,
  start serial comm and start process */
void setup() {
    for (i = 0; i < N_SENSORS; i++) {
        pinMode(sensors[i], INPUT);
    }
    pinMode(RELAY_PIN, OUTPUT);
    Serial.begin(230400);
    Serial.println("Welcome");
    start_process();
}

/** enables or disables led 13 according to elapsed time */
void loop() {
  long t = millis() - t_start;
  if (t % t_cycle >= t_exposure) {
    digitalWrite(RELAY_PIN, LOW); // deactivating relay
  } else if (t % t_cycle < t_exposure) {
    current_cycle = t / t_cycle + 1;
    if (current_cycle >= n_cycles + 1) {
      Timer1.stop();
    }
    digitalWrite(RELAY_PIN, HIGH); // activating relay
  }
}

/** Initialize t_start variable with current time, activate gas relay and initializes timer1 */
void start_process() {
    t_cycle = t_exposure + t_recovery; // ms 
    t_trigger = t_cycle * 1000 / n_readings; //us
    t_start = millis();
    digitalWrite(RELAY_PIN, HIGH);
    Timer1.initialize(t_trigger);
    Timer1.attachInterrupt(send_over_serial); // timer1 callback
}

/** Function that sends data read over serial */
void send_over_serial() {
    long t_elapsed = millis() - t_start; // elapsed time since start of counting
    Serial.print((float)t_elapsed / (float)1000);
    Serial.print(" ");
    for (i = 0; i < N_SENSORS; i++) {
        Serial.print(analogRead(sensors[i])); // analog measure
        if (i != N_SENSORS - 1) {
            Serial.print(" ");
        }
    }
    Serial.println();
}

well, my output is here:

Welcome
0.50 261 240 238 265
1.00 207 203 212 247
1.50 202 200 209 241
2.00 199 197 208 238
2.50 198 197 206 236
3.00 198 196 205 236
3.50 195 195 204 234
4.00 196 194 205 234
4.50 195 194 204 234
4.99 190 191 202 234
5.49 187 188 199 229
5.99 186 188 199 229
6.49 188 189 199 230
6.99 188 189 200 231
7.49 187 188 198 231
7.99 186 187 198 230
8.49 190 188 199 235
8.99 190 187 198 233
9.49 189 186 196 233
9.99 190 186 197 233
10.49 193 189 197 231
10.99 193 191 198 230
11.49 193 191 199 231
11.99 194 190 200 230
12.49 193 190 200 230
12.99 194 191 199 230
13.49 189 187 197 224
13.98 190 189 197 226
14.48 189 189 198 227
14.98 190 189 198 226
15.48 189 188 198 226
15.98 189 189 198 227

but that shoudnt happen, because t_trigger is 0,5s… so each time printing should happen at each 500000us, right?
Somehow my code is running faster than I specified… how is this even happening?

Done some searching but it seems that Serial.print doesnt even block execution (it is asynchronous, interrupt driven, and uses timer0)… Even if it did block execution, it should run slower if something! What shoud I do?

Thanks in advance,

Gabriel

if (t % t_cycle >= t_exposure) {

Can you explain the logic behind this? I'm not able to follow your timing here.

In the Timer 1 library, Timer1.attachInterrupt() wraps the timer overflow interrupt ISR(TIMER1_OVF_vect) around the user defined function which in your case is send_over_serial().

You can not serial print from within an ISR because interrupts are disabled.

Your interrupt function is not as short and quick as it should be. Better you should just set a flag in the isr, and do the sensor reading and printing within the loop if the flag is set. Clear it when you are done. The flag should be a volatile variable because it is modified within the isr.

My guess about the "speed up" timing issues is that the interrupts being disabled within the isr is affecting the millis timer.

Creating a flag worked, thanks!