Optimizing the debug stream

[jpearman]

I’ve been meaning to dig a little more into the system serial port on the cortex. We often see lost data when using the ROBOTC debugStream or PrintToScreen in EasyC but I did not expect the same issues to be present with the firmware I’ve been writing over the last few weeks. So lets take a look at the path the data takes from cortex to PC when we are debugging.

[ATTACH]7531[/ATTACH]

This diagram shows the path debugStream (or PrintToScreen) information takes. The data is generated in the user cpu and transmitted using asynchronous serial protocol at 230400 baud (bits per second) to the master cpu. The master cpu turns this stream into packets (more on that below) and sends it over either the USB tether or VEXnet to the joystick. In the joystick the packets are assembled back into an asynchronous serial stream but this time running at 115200 baud. This is sent via the programming adapter into the prolific serial adapter (or now the new vex adapter) which again turns the data back into packets that are sent to the PC over USB.

So the first obvious issue that limits how fast data can be sent is the slower of the two serial communication channels. The connection between user and master processors is at 230400 baud whereas the output of the joystick is at half this speed. Constantly sending data from user to master processors would overload the output of the joystick even if the intermediate stages were not present.

The next issue is the way the master processor turns the stream of data into packets. If the user processor is sending data slowly, say one byte at a time, it’s not very efficient to take each of these and send them over to the joystick as they arrive. For this reason, the master processor buffers the incoming bytes and waits for a gap in communication of perhaps a couple of mS. When it sees the gap it takes any buffered information and sends that in one or more packets over the USB tether to the joystick. Here is an example oscilloscope trace showing serial data (the yellow trace) leaving the user processor and then arriving out of the joystick about 3mS later (blue trace).

[ATTACH]7532[/ATTACH]

So life is good, but what happens when we throw a much larger amount of data at the master processor. Here is a trace showing 512 bytes of data leaving the user processor (yellow) and it arriving out of the joystick (blue).

[ATTACH]7533[/ATTACH]

Notice how the joystick output (blue) has it’s data grouped with small gaps between, this is due to the way the master processor is sending the data over the USB link. Without going into the gory details of how USB works, what we find if we dig into the USB stream with an analyzer is that the serial debug data is turned into packets with a maximum payload of 63 bytes. In the trace above, the 512 bytes sent from the user processor becomes eight 63 byte packets with the remaining sent in a smaller ninth packet.

Sending more than 512 bytes from the user processor starts to cause problems, there seems to be a 512 byte buffer in the master processor firmware that can be overwritten before it has time to packetize it and send over the USB link. This is the problem in EasyC when multiple PrintToScreen command are used back to back.

The next issue we face with ROBOTC is the way its proprietary communications protocol works. As discussed before in other posts, there is a 2000 byte buffer that debugStream data occupies before being sent to be displayed. ROBOTC will request a new chunk (I’m avoiding calling this a packet so as not to confuse with the USB packets) of data for display in the debug window at periodic intervals. It does this between also requesting all sorts of other information such as motor status and global variables. ROBOTC will ask for up to 250 bytes to be sent for display in one message, sometimes it will ask for several 250 byte chunks in a row before asking for other status, but the overhead of the protocol does not allow for anywhere near the theoretical maximum serial throughput to be reached. Here is an example of communication from user processor to PC showing debugSteam packets. This is in a similar format to the previous traces, it only shows serial data going from user processor to PC, it does not show the ROBOTC data requests.

[ATTACH]7534[/ATTACH]

As before, the yellow trace is data from user cpu to master cpu, the blue trace is the data out of the joystick and half the baud rate of the yellow data. In this example, two small packets are followed by three 250 byte debugStream packets. Note that data is flowing from the joystick for approximately 50% of the time available dropping the effective baud rate to something like 57600.

So we determine the maximum data rate for ROBOTC to be perhaps 5760 characters per second minus the overhead used for other messages, a safe speed would probably be about 3000 characters per second.

[fretless_kb]

I’ve been meaning to dig a little more into the system serial port on the cortex. We often see lost data when using the ROBOTC debugStream or PrintToScreen in EasyC but I did not expect the same issues to be present with the firmware I’ve been writing over the last few weeks.

I didn’t see if you mentioned what behavior you observed with ConVEX. do you see better or worse debug performance in terms of throughput?

Cheers Kb

[jpearman]

I didn’t see if you mentioned what behavior you observed with ConVEX. do you see better or worse debug performance in terms of throughput?

Cheers Kb

It’s somewhat independent of the user processor firmware. With ROBOTC, the IDE/debugger running on the PC is acting as a host and will request data when ready and at a rate that is compatible with what all the other firmware can handle.

With EasyC, data is lost if too many printToScreen statements are called (or used to be, I forget if they included a delay as part of this).

With ConVEX, I was (still am in a small way) having an issue with what I call the apollo display, a constantly updating text display of all important data (and called Apollo as an homage to the NASA program of the same name and which I will forever be in awe, even though they did their console displays in a very different way that’s a whole other discussion), the remedy so far is to not overload the serial to USB conversion that takes place in the master processor. I use a function like this to slow down transmission.

static void
apolloPut( uint8_t c )
{
    static  int count = 0;

    // We are on a serial console
    sdPut( SD_CONSOLE, c );

    // add 8mS delay every 32 chars
    if( ++count == 32 )
        {
        count = 0;
        chThdSleepMilliseconds(8);
        }
}

[fretless_kb]

I had been conducting some research / tests on various forms of logging debug data. comparing the inherent write to debug stream / print to screen and sending data out the Serial port via an XBee wireless or hardwired connection to an arduino with an SD disk / logging capability. I’ll have to dust off some of the project and see if I can get it written up.

I stopped at a certain point due to your revelation of the serial comm buffer in Robot C having limitations, and finding that for small amounts of data, e.g. I was focused on capturing PID function internals, I had better luck with Robot C debug stream than the serial port.
Ultimately the data stream will always be limited by the slowest serial link as you pointed out, and further slowed by the processing time in the chain.Since both Robot C debugger (joystick) / and the Cortex Serial port limit throughput to 115200 baud it seems these two paths ought to be on par at least for performance.

Thanks for the update - Kb