Program Execution and Timing

EDIT - please see my 2nd post update.

Hi All. I’m working on setting up a frequency step sweep (using DDS9850) from F1 to F2 with a set “dwell” time on each frequency step.

At the moment, I’m just interested in the sweep() function and how it works.

On my breadboard, I have the Arduino connected to the DDS module, but I am testing the code on a stand-alone pro-mini now and my timings are grossly different from the breadboard. I imagine that the code to push data to the DDS chip may have irregular timings, so I commented that out here. At some point I need to create a “dwell” calibration.

I first wonder why my code returns sweep switching time of 8. to 10. microseconds. Why so long and why the variance of a couple of us?

Now, on the breadboard, when I have the following and the SetFrequency() function enabled:

long timeDwell = 0; the switching time returns ~890 us/pt.
long timeDwell = 100000; the switching time returns ~139200 us/pt. Why not 100890 us/pt?
long timeDwell = 200000; the switching time returns ~179500 us/pt. Why not 200890 us/pt?

On the standalone pro-mini, now I’m getting:

long timeDwell = 0; the switching time returns ~8.80 us/pt (it varies a few).
long timeDwell = 100000; the switching time returns ~100009.40 us/pt (does not vary).
long timeDwell = 200000; the switching time returns ~200009.40 us/pt (does not vary).

void sweep()
{
  Serial.println("AD9850 DDS");
  Serial.println("Sweep Mode");
  long F1 = 1000000;
  long F2 = 1500000;
  long fStep = 100000;
  long freq = F1 + fStep;
  long timeDwell = 200000;
  Serial.print("Start Frequency: ");
  Serial.print(long (F1));
  Serial.println(" Hz");
  long timeStart = micros();
  long timeStepStart = micros();
  //SetFrequency(F1);  // freq
  while (freq <= F2) {
    if ((micros() - timeStepStart) > timeDwell) {
      //SetFrequency(freq);  // freq
      freq = freq + fStep;
      timeStepStart = micros();
    }
  }
  long timeStop = micros();
  long timeSweep = timeStop - timeStart;
  float timeSwitch = (((float)timeSweep * (float)fStep) / ((float)(F2 - F1) + 1));
  Serial.print("Stop Frequency: ");
  Serial.print(long (freq));
  Serial.println(" Hz");
  Serial.print("Start Time: ");
  Serial.print(timeStart);
  Serial.println(" us");
  Serial.print("Stop Time: ");
  Serial.print(timeStop);
  Serial.println(" us");
  Serial.print("Sweep Time: ");
  Serial.print((timeStop - timeStart));
  Serial.println(" us");
  Serial.print("Switching Time: ");
  Serial.print(float(timeSwitch));
  Serial.println(" us/pt");
  Serial.println("");
  delay(1500);
}

The other possibility is that that variables may overflow ?

Thanks

Hi again, I just had to tinker with the code a bit, not much has changed, but I am capturing some more data.

I now print the frequency value and time stamp at each frequency step, results as follows:

1
42108
3
42520
5
43284
7
44136
9
44984
11
45920
13
46856
15
47788

Start Time:
42004

This corresponds to the following deltas:

from start to F1
104
to next freq
412
to next freq
764
to next freq
852
to next freq
848
to next freq
936
to next freq
936
to F2
932

void sweep()
{
  Serial.println("AD9850 DDS");
  Serial.println("Sweep Mode");
  long F1 = 1;
  long F2 = 15;
  long fStep = 2;
  long freq = F1;
  long timeDwell = 1;
  Serial.println("Start Frequency: ");
  Serial.println(long (F1));
  Serial.println(" Hz");
  long timeStart = micros();
  long timeStepStart = micros();
  while (freq <= F2) {
    if ((micros() - timeStepStart) > timeDwell) {
      timeStepStart = micros();
      //SetFrequency(freq);  // freq
      Serial.println(freq);
      Serial.println(micros());
      freq = freq + fStep;
    }
  }
  long timeStop = micros();
  long timeSweep = timeStop - timeStart;
  long numStep = ((F2 - F1)/(fStep)) + 1;
  float timeSwitch = (float)timeSweep / (float)numStep;
  Serial.println("Stop Frequency: ");
  Serial.println(long (F2));
  Serial.println(" Hz");
  Serial.println("Start Time: ");
  Serial.println(timeStart);
  Serial.println(" us");
  Serial.println("Stop Time: ");
  Serial.println(timeStop);
  Serial.println(" us");
  Serial.println("Sweep Time: ");
  Serial.println((timeStop - timeStart));
  Serial.println(" us");
  Serial.println("Number of Steps: ");
  Serial.println(long(numStep));
  Serial.println(" points");
  Serial.println("Switching Time: ");
  Serial.println(float(timeSwitch));
  Serial.println(" us/pt");
  Serial.println("");
  delay(5000);
}

If I change the dwell time to 1000 us, then:

from start to F1
1112
to next freq
1016
to next freq
1004
to next freq
1004
to next freq
1008
to next freq
1060
to next freq
1004
to F2
1012

Now, I interpret this as the shortest time is 1004 us and since there is a delay of 1000 us, then the print routine and other executions take as little as 4 us. The longest is 1112, so the variance is as much as 108 us, or about 10 kHz. Could the reference crystal vary that much? No, it does not seem possible.

So why the such a large variation in when the freq value is sent to the monitor (and DDS)?

I’m not sure if you were using ‘Serial’ during your tests, or just for debugging. However if during the tests you used serial; you will encounter timing variances.

The serial library uses interrupts to control the UART, so when it runs its ISR it’ll halt the timing interrupts which could miss events. Or simply there is too much data to send and it is bogging down the cpu, which takes the time seen in your latencies.

Maybe increase the Serial baud rate, or send less data.

Just to plug my new library here:
I’m working on a new library which will allow you to use print & printf on ram, so you could shrink your sets of Serial.println’s into one memory print, then print that to serial. Soon I’ll have a patch which will allow Serial.printf(), which will print directly to the output.

OK, how about writing each time to an array and then print after the while loop completes? this should remove serial events from the while loop.

I set the delay to 0, I think the while loop will write micros() to each array index for each iteration, so I’m still seeing about 12 us for each while loop to complete.

void sweep()
{
  Serial.println("AD9850 DDS");
  Serial.println("Sweep Mode");
  long F1 = 1;
  long F2 = 15;
  long fStep = 2;
  long freq = F1;
  long timeDwell = 0;
  Serial.println("Start Frequency: ");
  Serial.println(long (F1));
  Serial.println(" Hz");
  int i = 0;
  long data[10] = {0,0,0,0,0,0,0,0,0,0};
  long timeStart = micros();
  long timeStepStart = micros();

  while (freq <= F2) {
    if (micros() - timeStepStart > timeDwell) {
      timeStepStart = micros();
      data[i] = micros();
      freq = freq + fStep;
      i++;
    }
  }

  for (i = 0; i < 10; i = i + 1) {
    Serial.println(data[i]);
  }

Below are the serial data output and values that I calculated between each micros() record in the array.

data[0] =	42028	delta from start time = 24
data[1] =	42040	delta from previous time = 12
data[2] =	42052	delta from previous time = 12
data[3] =	42064	delta from previous time = 12
data[4] =	42076	delta from previous time = 12
data[5] =	42096	delta from previous time = 20
data[6] =	42108	delta from previous time = 12
data[7] =	42120	delta from previous time = 12
data[8] =	0	delta from previous time = -42120
data[9] =	0	delta from previous time = 0
Stop Frequency: 
15
 Hz
Start Time: 
42016
 us
Stop Time: 
46600
 us
Sweep Time: 
4584
 us
Number of Steps: 
8
 points
Switching Time: 
573
 us/pt

12 us is almost 200 arduino clock cycles, so I don’t see what is taking so long? Also, why the 6th time through the loop is it 20 us?

I also tried increasing dwell time to 100 us, the times and deltas are below:

42132	116 us from start time to data[0]
42236	104 us from data[0] to data[1]
42348	112 ...
42456	108
42564	108
42672	108
42776	104
42884	108
0	-42884
0	0

I know there is a section in the datasheet that indicates how long specific operations take. I seem to recall many took 4 clocks, so it’s not adding up. I’m missing something…

It seems to me you have a lot of code in your loop so I'm not surprised it takes 12 microseconds.

Try populating the array without a loop as in

data[0] = micros();
data[1] = micros();
etc.

and see what happens

I see, the total time is not really that important to me since I could compensate for that time. I am interested in consistency, which I am not getting. Each iteration of the while loop seems to take up to three times longer than another.

Below is a simple while loop that is very consistent at 4 us intervals for each data(i):

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

void loop() {
  int i = 0;
  long data[10] = {0,0,0,0,0,0,0,0,0,0};
  long timeStart = micros();
  while (i <= 9) {
      data[i] = micros();
      i++;
  }
  Serial.println(timeStart);
  for (i = 0; i < 10; i = i + 1) {
    Serial.println(data[i]);
  }
delay(5000);
}

When I add an if statement, the while loop takes 4, 8 or 12 us to store each data(i), so it seems to miss a step into the loop every once, twice, or third time…? I will not be able to compensate for a random variance.

void loop() {
  int i = 0;
  long data[10] = {0,0,0,0,0,0,0,0,0,0};
  long timeStart = micros();
  long timeStepStart = micros();
  while (i <= 9) {
    if (timeStepStart > 0) {
      data[i] = micros();
      timeStepStart = micros();
      i++;
    }
  }
  Serial.println(timeStart);
  for (i = 0; i < 10; i = i + 1) {
    Serial.println(data[i]);
  }
delay(5000);
}

The if statement that you have in your example seems pointless. TimeStepStart will always be greater than 0 (except, perhaps, when micros() rolls over). And why are you reading micros() twice in succession.

If I recall correctly assembler code takes an extra step when an if is satisfied compared to when it isn't (or vice versa). But I don't know how well the compiler optimizes if statements - and your if depends on a long rather than a byte.

If this is only code to demonstrate a problem perhaps the "real" code would suggest a solution.

...R

This gives you quite nice results:

void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);
}

void loop() {
  // put your main code here, to run repeatedly: 
  sweep();
  while(1);
}

void sweep()
{
  Serial.println("AD9850 DDS");
  Serial.println("Sweep Mode");
  long F1 = 10;
  long F2 = 110;
  long fStep = 1;
  long freq = F1;
  long timeDwell = 100;
  Serial.print("Start Frequency: ");
  Serial.print(long (F1));
  Serial.println(" Hz");
  int i;
  long data[100];

  delay(200); //  important - flush the uart buffer
  
  i = 0;
  long timeStepStart = micros();
  while (freq <= F2) {
    long timenow = micros();
    if ((timenow - timeStepStart) >= timeDwell) {
      timeStepStart = timenow;
      data[i] = timenow;
      freq = freq + fStep;
      i++;
    }
  }


  for (i = 0; i < 99; i = i + 1) {
    Serial.print(data[i]);
    Serial.print(" delta=");
    Serial.println(data[i+1]-data[i]);
  }
}
AD9850 DDS
Sweep Mode
Start Frequency: 10 Hz
201868 delta=100
201968 delta=100
202068 delta=100
202168 delta=100
202268 delta=100
202368 delta=100
202468 delta=100
202568 delta=100
202668 delta=100
202768 delta=100
202868 delta=100
202968 delta=100
203068 delta=100
203168 delta=100
203268 delta=100
203368 delta=100
203468 delta=100
203568 delta=100
203668 delta=100
203768 delta=100
203868 delta=100
203968 delta=100
204068 delta=100
204168 delta=100
204268 delta=100
204368 delta=100
204468 delta=100
204568 delta=100
204668 delta=100
204768 delta=100
204868 delta=100
204968 delta=100
205068 delta=100
205168 delta=100
205268 delta=100
205368 delta=100
205468 delta=100
205568 delta=100
205668 delta=100
205768 delta=100
205868 delta=100
205968 delta=100
206068 delta=100
206168 delta=100
206268 delta=100
206368 delta=100
206468 delta=100
206568 delta=100
206668 delta=100
206768 delta=100
206868 delta=100
206968 delta=100
207068 delta=100
207168 delta=100
207268 delta=100
207368 delta=100
207468 delta=100
207568 delta=100
207668 delta=100
207768 delta=100
207868 delta=100
207968 delta=100
208068 delta=100
208168 delta=100
208268 delta=100
208368 delta=100
208468 delta=100
208568 delta=100
208668 delta=100
208768 delta=100
208868 delta=100
208968 delta=100
209068 delta=100
209168 delta=100
209268 delta=100
209368 delta=100
209468 delta=100
209568 delta=100
209668 delta=100
209768 delta=100
209868 delta=100
209968 delta=100
210068 delta=100
210168 delta=100
210268 delta=100
210368 delta=100
210468 delta=100
210568 delta=100
210668 delta=100
210768 delta=100
210868 delta=100
210968 delta=100
211068 delta=100
211168 delta=100
211268 delta=100
211368 delta=100
211468 delta=100
211568 delta=100
211668 delta=100

Thanks, pito…

If I use timenow as the data time, then I do not know how long the if statement takes and the real time for the data event, but it is interesting that the interval is consistent to a point.

When I used your code with the delay = 0, then I get 4, 8, or 12 us deltas.

Now I recall reading somewhere that micros() is accurate to about 3 us, so maybe that is the best time resolution possible? Or it was only accurate above 3 us. I am curious why there are 4 us time steps.

If I change one line to data(i) = micros(); then I get deltas that vary by +/- 4 us (i.e., 100, 94, 104…), so again, why 4 us variances and not 1 or 2, or 5?

Well, I found this article which helps answer some questions, but is a bit over my head understanding how to use the AVR's timers.

C2:
I am curious why there are 4 us time steps.

I haven't looked into why your code is taking a variable time to run, but the reason the length is varying by multiples of four microseconds is that on 16MHz Arduinos the value of micros() increments in steps of 4 usecs. Given that a given execution of the loop will not necessarily start exactly on the boundary of a change in the value of micros() it would be expected that the execution time of the loop could vary by up to 4usec even if the actual execution time was absolutely consistent. This doesn't account for variations of more than one 4usec 'unit'.

With unsigned int I get good results at dwell=0. It seems the signed long calculations take time with an 8bitter :slight_smile:

void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);
}

void loop() {
  // put your main code here, to run repeatedly: 
  sweep();
  while(1);
}

void sweep()
{
  Serial.println("AD9850 DDS");
  Serial.println("Sweep Mode");
  unsigned int F1 = 10;
  unsigned int F2 = 110;
  unsigned int fStep = 1;
  unsigned int freq = F1;
  unsigned int timeDwell = 0;
  Serial.print("Start Frequency: ");
  Serial.print(long (F1));
  Serial.println(" Hz");
  unsigned int i;
  unsigned int data[100];

  delay(200); //  important

  i = 0;
  unsigned int timeStepStart = micros();
  while (freq <= F2) {
    unsigned int timenow = micros();
    if ((timenow - timeStepStart) >= timeDwell) {
      timeStepStart = timenow;
      data[i] = timenow;
      freq = freq + fStep;
      i++;
    }
  }


  for (i = 0; i < 99; i = i + 1) {
    Serial.print(data[i]);
    Serial.print(" delta=");
    Serial.println(data[i+1]-data[i]);
  }
}
AD9850 DDS
Sweep Mode
Start Frequency: 10 Hz
5156 delta=4
5160 delta=4
5164 delta=4
5168 delta=4
5172 delta=4
5176 delta=4
5180 delta=4
5184 delta=4
5188 delta=4
5192 delta=0
5192 delta=4
5196 delta=4
5200 delta=4
5204 delta=4
5208 delta=4
5212 delta=4
5216 delta=4
5220 delta=4
5224 delta=0
5224 delta=4
5228 delta=4
5232 delta=4
5236 delta=4
5240 delta=4
5244 delta=4
5248 delta=4
5252 delta=4
5256 delta=0
5256 delta=4
5260 delta=4
5264 delta=4
5268 delta=4
5272 delta=4
5276 delta=4
5280 delta=4
5284 delta=4
5288 delta=0
5288 delta=4
5292 delta=4
5296 delta=4
5300 delta=4
5304 delta=4
5308 delta=4
5312 delta=4
5316 delta=4
5320 delta=0
5320 delta=4
5324 delta=4
5328 delta=4
5332 delta=4
5336 delta=4
5340 delta=4
5344 delta=4
5348 delta=4
5352 delta=0
5352 delta=4
5356 delta=4
5360 delta=4
5364 delta=4
5368 delta=4
5372 delta=4
5376 delta=4
5380 delta=4
5384 delta=0
5384 delta=4
5388 delta=4
5392 delta=4
5396 delta=4
5400 delta=4
5404 delta=4
5408 delta=4
5412 delta=4
5416 delta=4
5420 delta=0
5420 delta=4
5424 delta=4
5428 delta=4
5432 delta=4
5436 delta=4
5440 delta=4
5444 delta=4
5448 delta=4
5452 delta=0
5452 delta=4
5456 delta=4
5460 delta=4
5464 delta=4
5468 delta=4
5472 delta=4
5476 delta=4
5480 delta=4
5484 delta=0
5484 delta=4
5488 delta=4
5492 delta=4
5496 delta=4
5500 delta=4
5504 delta=4
5508 delta=4

The 4usecs noise with micros() is normal, I think. With higher dwells the timing seems to be precise.
PS: interestingly the “0” comes every 9th/10th measurement in the above…

It’s something to do with this line in wiring.c:

return ((m << 8) + t) * (64 / clockCyclesPerMicrosecond());

That will effectively round the time to a multiple of four, probably to make the calculation fast.

return ((m << 8) + t) * (64 / clockCyclesPerMicrosecond());

Here:

m - number of timer0 overflows  (256 ticks to overflow)
t - timer0 content
64 - timer0 prescaler set to 64
clockCyclesPerMicrosecond() - 16 for 16MHz

micros = (m*256 + t) * 64 / 16 = (m*256 + t) * 4 = m<<10 + t<<2

BUT - the results with

return (m<<10)+(t<<2);

are worse (more 4usec jitter) than with the original :roll_eyes:
So unsigned long shifting <<10 and <<2 is slow…

Thanks for all the insights and help here. I'm not sure how to apply this all, or if it really can be the way I'm coding. Generally, this implies to me that delaymicros() also has a 4 us resolution. If that is true, then the reference example would have an actual delay of 52 us.

I suspect that the timers could be used differently to get higher accuracy, but this may not even be necessary in my code because I'm not necessarily interested in calculating the exact time as much as I am in when the code executes. Also, rather than writing values to an array, I'll be calling a SetFrequency function that is currently taking a few hundred us to complete (and I'll probably revisit that in another topic soon).

Another hurdle though is not just the point-to-point time, but also the sweep-to-sweep time that must be addressed. The time between the last point (F2) and restarting at F1 should also be equal to the dwell time. I'll be moving all of the serial comms and variable assignments out of the function and sending them in with the call. I'm not sure how to accomplish this since the function exits when complete and the main loop will return its call unless some other event happens. I'm planning just one external button interrupt to break out of any routine, so is there a way to stay in this function until that happens? Maybe with a while loop that checks the button...

I understand there is a pretty easy way to use the timers to get very accurate triggers if you want to do it. If what you want is a more consistent timing interval, here’s one way… (Modified your code a little bit)

...
  unsigned int data[100];

  delay(200); //  important

  TCCR2A = 0;                        // Normal mode
  TCCR2B = 1 << CS20;                // Prescaler = 1
  i = 0;
  unsigned int timeStepStart = micros();
  TCNT2 = 0;            // Start the clock counter at 0
  bitSet(TIFR2, TOV2);              // Clear the overflow flag
  for (i = 0; i < 100; ++i)
  {
    while (!bitRead(TIFR2, TOV2));  // Wait for the overflow flag
    bitSet(TIFR2, TOV2);            // Clear the overflow flag
    data[i] = micros();
  }

  for (i = 0; i < 99; i = i + 1) {
...

Output:

AD9850 DDS
Sweep Mode
Start Frequency: 10 Hz
4068 delta=16
4084 delta=16
4100 delta=16
4116 delta=16
4132 delta=16
4148 delta=16
4164 delta=16
4180 delta=16
...                     They're ALL 16
5588 delta=16
5604 delta=16
5620 delta=16
5636 delta=16

The overflow gets set on a very consistent basis. Accurate to one system clock cycle. The loop that checks it is a little bit less accurate, but is within 4 clock cycles of the bit getting set. Maybe even as close as 3 – I’m not sure exactly how the sbis/rjmp pair works as far as clock cycles go. In any case, that’s accurate within a quarter of a microsecond, with no drift. The scaler value could be used to increase the times, while keeping the same accuracy.

Thanks Tan. I've looked at the code a few times and will have to read a bit more about timers to understand what's happening there. I actually need to read a lot more about programming since I have a few other fundamental aspects of my project that are not working yet...but I've made huge progress thanks to everyone's help!!!