Actual execution time measurement

[Dan]

Is there a way to externally measure the execution time of our code?

I'm interested in the actual time from the serin command to the serout command. We have a scope, etc.

I understand the 26ms cycle, that's not what I'm interested in.

[Dave Flowerday]

We did some timing measurements like this early in the build season. We used an old robot controller that was out of warranty and took the cover off. We hooked up a logic analyzer probe to the lead of the BASIC Run LED and then toggled this at certain times in software. The BASIC Run LED doesn't go through the input or output processors so it changes as soon as you set it in the BASIC code (this is unlike all other outputs which only change when the output processor decides to change them, which as we discovered can be up to something like 16 milliseconds AFTER the serout command by the Stamp!).

If you have a controller you don't mind taking apart you should be able to recreate this easily, although measuring it with a scope will probably be a little more difficult than with a logic analyzer. If you don't have a controller that you're willing to take apart, you could always hook up a phototransistor or something similar and just tape it down over the LED on the outside of the controller.

[DKolberg]

Another method is to develop a delay routine that can be called a number of times. You can change the code to the simple serial in and out with nothing else, set up a loop to call the delay n times. Monitor the delay_t value and keep increasing n until a one is picked up in the delay_t. Now you can calculate the time of the delay routine by taking the inverse of 38*n. From this you can just check how much time is remaining in your code by adding a loop after the serial out to delay n times and up n until the delay_t goes to 1. This will tell you how much room you have left. Just remember to comment out the loop before competition.

[KenWittlief]

I put a line in the code right after the RUN LED toggle line to set a relay output = the inverse of itself

and put a digital scope on the (middle ?) pin of the relay output.

I was surprized to see the period of the resulting toggling signal is about 20 Hz (goes high, goes low)

BUT the duty cycle is NOT 50% - the HI and LOW times were something like 16.6mS and 33.4mS - very consistantly

so the average cycle frequency for 2 cycles is 40 Hz, but individual passes through the code happen at a rate of 60Hz and 30Hz.

I have no idea why this is.

I also have noticed, if you program a toggle switch on the robot switch inputs to control an LED on the operator interface - there is a NOTICABLE delay from when you throw the switch until the LED goes on.

I did not measure it with a scope -but Im guessing its a quarter second at least. If this is true the other way too - that it takes a quarter second for inputs at the operator interface to reach the relay or PWM outputs on the robot, that would be interesting.

It would mean the robot doesnt respond very quickly to operator commands. I will test this 'system propagation delay' with the digital scope sometime when Im not swamped with other tasks.

[Dave Flowerday]

We did a lot of this kind of testing and our results match what Ken is seeing. The first thing that we figured out is that the RC outputs do NOT change at the moment that the Stamp sends the serout command. We determined that the outputs change at 16ms intervals (independent of when the Stamp executes a serout), just as Ken found. What we believe is happening is that there is a timer inside the RC that changes the outputs every 16ms. Since the Stamp only sends new outputs every 26ms, you get the situation described above. Because of the different I/O frequencies (40Hz versus 60Hz), sometimes the RC changes the outputs once between serouts and sometimes it's able to change them twice. If the RC changes the outputs twice in between serouts, it doesn't actually have new output values so it keeps them all the same. This is where the 33ms interval comes from.

Anyway, the bottom line is that from the point at which the Stamp executes a serin to read the state of the joysticks and RC inputs, there can be a delay of up to 42 milliseconds before the outputs respond! It's very likely that a similar situation exists on the OI side, which could easily double the total delay in the system which brings it up near 1/10 of a second, which is where the delay starts to get noticeable.

[kmcclary]

Originally posted by Dan
Is there a way to externally measure the execution time of our code?

I'm interested in the actual time from the serin command to the serout command. We have a scope, etc. I understand the 26ms cycle, that's not what I'm interested in.

Hi! I'm an embedded microprocessor development Engineer.

Well, knowing the loop rate is one thing, but in reality you still have to deal with the numerous I/O processor latency steps as well...

One problem is the RC's Stamp is not running the I/O lines. A slave PIC is doing that job asynchronously. The Stamp SERIN and SEROUT statements in the default program talk to this I/O processor, which then updates the outputs some time later.

(Actually, I think someone said there are TWO PICs in the RC, to deal with both I/O and RF modem issues, but I haven't looked under the hood yet to confirm that...)

I did talk to IFI about this. They said the I/O pic is pretty fast at getting the outputs out there (WAY below "one loop time"). However, you COULD have an additional "I/O processor input scan loop" delay added to the loop time if the new inputs weren't ready to go when the SERIN handshake came in, so keep that in mind when totaling up your "control stick/switch wiggle input to output PWM reflection" time calculation.

Worst case, for operator controls you have the sum of:
1) The OI's I/O processor input scan maximum time
2) The OI's Modem PIC processor loop time
3) The EWave modems RF data transfer link latency
4) The RC's Modem PIC processor loop time
5) The RC SERIN start through SEROUT done loop time (user program)
6) The RC I/O PIC processor output maximum time

For RC sensor to output calculations you have the sum of:
1) The RC I/O PIC input scan loop maximum time
2) The RC SERIN start through SEROUT done loop time (program)
3) The RC I/O PIC processor maximum output time

As ALL of these are asynchronous, they're often tough to TRULY measure, without getting some PIC performance data from IFI. I *think* IFI said the IO PICs are fairly fast, and run their scanning loops on the order of tens of microseconds. Not too bad! However, I've NO clue as to the maximum latency of the EWave modem link on a congested channel. (That's something I wish to find out some day from EWave.)

Anyway... Given that there are other latencies, I'd advise simply toggling two output I/O bits that are unused in your user code as follows: one before the SERIN, and another one after the SEROUT. Watch them BOTH on a dual trace scope. This width will oscillate as you catch the various IO PICs at different times in their scanning cycles. The MINIMUM width is a good "first approximation" of the loop time. Subtracting that time off of the MAXIMUM width you see gives you a good approximation of the PIC I/O processor's output loop time.

Next: Tie one of those toggling output bits to an unused RC digital input bit, and have yet ANOTHER unused output bit "follow" it. Watching the latency (and compensating for the above times) now allows you to characterize a "typical" PIC *input* scanning loop time.

If you're truly interested in measuring the Stamp Loop Time at a FINER level (the original question):

Unfortunately, I don't see a simple way to measure the true loop time that wouldn't involve cracking the case. You can't do this with the current year's RC... Not only does that ruin the warranty, it makes your RC illegal for the contest.

Instead, for development work crack the case of LAST YEAR'S RC (that is out of warranty and won't be used for the current contest), and tap ITS Stamp with a clip-on logic probe. Now use IT as a development platform. Warning: If the RC has changed too much from the previous year, you'll have to buy an additional new "sacrificial" RC for this job. Luckily, if the RC hardware hasn't changed from the previous year, IFI *will* for a much smaller price upgrade your old RC's firmware to the current contest year (but then you may find you'll have to send in your old OI in as well for a firmware upgrade to continue using your OLD robot for team demos and driver practice, or risk orphaning the old OI out <sigh>).

Assuming you ARE cracking the RC's case, the constants COMA, COMB, COMC, and USERCPU in the default code show that the serial I/O and handshakes to/from the slave processor(s) run off of Stamp pins 1-4. Look up the SERIN/SEROUT statements in the PBASIC manual to see how those instructions work at the hardware level. Comparing that to the default code tells you which pins to use, and how to set your scope sync slope.

Now, using a dual trace scope, trigger on the SERIN handshake "request to send" assertion. Compare that time until the SEROUT handshake is completed on the other scope channel, and you're done!

DISCLAIMER: As I'm busy starting up rookie teams (this is my second rookie in two years I've started), I've never had an "old RC" yet to work with! (DARN!) Therefore, though I'm highly curious, I have NOT cracked open an RC's case yet, since *I* am not getting us in trouble for the contest itself! . Therefore, I don't know how accessible the Stamp is on the PCB for probe clips. However, I've developed embedded micro applications for years, and simply can tell these pins definitions are correct, by looking at the RC default code.

Once the warranties are ALL out though, I DO plan on checking out some of the IFI hardware "under the hood" to allow me to create finer resolution "FIRST control system system architecture overview diagram" training materials for our students than IFI gives us... (Of course if some team near Ann Arbor already has old hardware cracked open and/or documented, **PLEASE*** drop me a line and we'll go through it together!)

I hope this helps! If you have any other embedded micro development questions, please feel free to ask.

Good luck, and please send me the numbers you come up with!

- Keith