Wednesday September 29, 2010
Hello,
In my previous post I asked for help with implementing micros() before the release of Maple-IDE 0.0.7 because I want to determine if the problems I have with my ported LabVIEW/Maple code (which works with LabVIEW/Arduino Duemilanove 0017 IDE) was caused by a strcmp() bug. I did not want to attach my LabVIEW vi because it is large (and the LabVIEW vi still needs some development before it is ready for release).
Here is a link to my original post ("Arduino / Maple Time micros command"):
http://forums.leaflabs.com/topic.php?id=86&page=2#post-1420
In my LabVIEW/Maple code the problem (which occurs at iterations of 21n; see my previous post) is observed when a string of length 3 is sent by LabVIEW to the Maple. The problem is solved if the string sent by LabVIEW to the Maple is only 1. I did not test other string lengths (because I was happy that the LabVIEW/Maple code was finally working after several months of head banging).
I tried to look for strange behavior using just the strcmp() function (without LabVIEW) using just FOR loops and the millisecond timer millis(). I found some partially reproducible problems. I do not know if the "new" problems I observe with just the Maple code (in the absence of LabVIEW) is the cause of my LabVIEW/Maple problem.
My development system is Windows XP Pro SP3 and Maple-IDE 0.0.6. I power my Maple (Rev 3, summer 2010) with a USB 1.1 port. The Maple appears as COM7. I was using the Maple-IDE serial terminal (I did not test HyperTerminal or another serial terminal app).
In the code below I use a FOR loop where I set the interations (using LIMIT) to 1000 (1K), 10000 (10K), or 100000 (100K). The string length ranges from 0 to eleven characters (assuming you do not count the terminating null character).
Here is the data with some comments at the bottom of the "table":
string length LIMIT=1000 LIMIT=10000 LIMIT=100000
"0": 1000-> 3 ms; 10000-> 17 ms; 100000-> 162 ms
"01": 1000-> 3 ms; 10000-> 19 ms; 100000-> 182 ms
"012": 1000-> 3 ms; 10000-> 18 ms; 100000-> 174 ms"0123": 1000-> 3 ms; 10000-> 14 ms; 100000-> 135 ms
"01234": 1000-> 3 ms; 10000-> 16 ms; 100000-> 154 ms
"012345": 1000-> 3 ms; 10000-> 18 ms; 100000-> 174 ms
"0123456": 1000-> 3 ms; 10000-> 20 ms; 100000-> 193 ms"01234567": 1000-> 3 ms; 10000-> 17 ms; 100000-> 160 ms
"012345678": 1000-> 3 ms; 10000-> 19 ms; 100000-> 179 ms
"0123456789": 1000-> 3 ms; 10000-> 21 ms; 100000-> 199 ms
"01234567891": 1000-> 3 ms; 10000-> 23 ms; 100000-> 218 ms"": 1000-> 3 ms; 10000-> 3 ms; 100000-> 23 ms
in set "0123456789" with 1000 reps see occasional "spikes" of 15, 10, 23, 41 millis (compared to 3 ms)
in set "0123456789" with 10000 reps see occasional "spikes" of 38, 25, 35 millis (compared to 21 ms)
in set "0123456789" with 100000 reps no spikes were observedin set "" with 1000 reps observed one spike of 152 (without a preceding "End of loop" message)
in set "" with 10000 reps observed one abnormal 3 (no newline after 3; saw "3End of loop" on one line
in set "" with 100000 reps no unusual times observed, but why is it not 3 ms?
I was assuming the 1000 iterations column (3 ms for all) is measuring "overhead". Not a problem.
First "problem":
A "trend" is not predictable when the iterations are increased to 10K and 100K.
At 10K, with string lengths of 1, 2, and 3 chars the time starts at 17 ms, before an increase to 19 ms, and a decrease to 18 ms. This UP/DOWN pattern is also observed at 100K with the same string lengths.
At 10K, with string lengths of 4, 5, 6, and 7 chars the times drop to 14 ms, before increasing to 16, 18, and 20 ms. This DOWN/UP/UP/UP pattern is also observed at 100K with the same string lengths.
At 10K, with string lengths of 8, 9, 10, and 12 chars the times drop to 17 ms, before increasing to 19, 21, and 23 ms. This DOWN/UP/UP/UP pattern is also observed at 100K with the same string lengths.
I did not have time to test string lengths of 13, 14, 15, and 16 chars. I do not know if the same DOWN/UP/UP/UP pattern will be observed.
Question: why does a strcmp comparison of string length of 4 chars have the fastest execution time (especially when compared to shorter strings)?
Second "problem":
I did not notice this until I was testing the string of length 10 chars ("0123456789"). At 1000 iterations 3 ms was the most common time (with a little "noise"). However, when I was staring at the data stream by in the Maple serial terminal window I saw a blip of 15 ms (which was easy to see because it has two digits). When I looked through the data more carefully I saw other blips of 10, 23, and 41 ms.
Not many blips, but they were there. I guess it is possible to edit the sketch to count how many loops take significantly more time to finish.
When I used a string of zero characters (and 1000 iterations) I saw one spike of 152 ms. This point was also strange in that is did not follow an "End of loop" message.
When the iterations was increased to 10K I saw one line with "3End of loop" (which means the "SerialUSB.println(stop-start)" line did not print the newline character.
One small bug or a mixture of several bugs? I do not have the tools (eg. knowledge using a debugger) to test the problem in fine detail.
Thanks!
Stephen from NYC
Here is the test code ("shortest code"). LIMIT is set to 1000 and the string is set to "0123456789".
#include <string.h>
#define LIMIT 1000
void setup()
{
// this is not necessary, but I include it to make it easy to port my code between the Maple/Arduino.SerialUSB.begin();
delay(5000);
}void loop()
{
char stringArray[]="0123456789";int count=0;
long start=0;
long stop=0;start=millis();
for (count=0; count < LIMIT; count++)
{
if ((strcmp(stringArray, "0123456789") == 0) && (count == (LIMIT-1)))
{
SerialUSB.println("End of loop");
}
}stop=millis();
SerialUSB.println(stop-start);
}