Requirements

Two embedded devides talk using a serial UART connection. On top of the UART, the whole network protocol is implented in the devices' hardware/software. However, something goes wrong and a need is arised to thoroughly debug the protocol between these devices. From this, the following requirements arise:

1. OS - Windows, most probably Win2K
2. Continuously monitor a COM port, logging the incoming data into a file.
3. Support full-duplex communication, i.e. monitor more than two COM ports simultaneously (at least 2).
4. To make sense of which transmission comes first in a full-duplex communication, support time stamping on incoming bytes.
5. The dump file should contain data from all monitored ports, tagged by source (which port it came from) and a time tag (as accurate as possible).
6. The minimal performance is successfully keep up with two ports each receiving an almost continuous stream of data at 2400 baud.
7. Convenient user interface

Believe it or not, I found no such program in the Internet (I'll be delighted if someone has...). There are several COM monitors around the web, but almost none use time stamping, and almost none monitor more than one port simultaneously. Therefore, there was a need to implement such a program. The language of choice (as is always the case for me :-) - Perl.

Initial implementation considerations

From the requirements we can immediately derive the tools needed to complete the task.

• For COM port access - use the Win32::SerialPort module, which seems mature.
• For timestamps - use Time::HiRes
• For a GUI - use Tk.
• For the complex processing required (GUI and monitoring of several ports) - use either polling or threads.

What makes the task difficult is the time-stamping requirement. For it to happen, characters should be read from the port one-at-a-time, which imposes severe timing restrictions and we'll soon see.

It won't go without threads

The accepted way to do "background processing" in Tk is use "after" and "repeat" for timed events that execute "from time to time" in parallel with the GUI. However, a quick analysis of the timing involved proves that this approach is not feasible.

Even at the measly 2400 baud, in a continuous data stream a new character arrives each 4 ms. Even using Time::HiRes I couldn't achieve a reliable sleep time of less than 30 ms, and that's in idial conditions (lets remember that Windows is not even close to being a RTOS).

So, a background thread is necessary. The Tk GUI does its job (that is, sleeps most of the time), sending messages to a background monitoring thread when needed. The background thread is live all the time and not only on "wakeup" intervals, so it will be possible to achieve the harsh timing constraints.

Tk and threads - not the best friends...

The Perl Tk implementation is not thread save, and the Perl threads implementation is not especially Tk-aware. There you go for a nice friendship.

Fortunately, there is a solution. What we should do is create the background thread *before* the Tk GUI goes live. This way, its creation won't have to copy all the Tk data in, and Tk won't die when the thread exits - they are as independent as possible, the only thing connecting between them is a message queue. When the application exits, it kills this monitoring thread.

# 'manager' loggin thread: communication queues initialization
# and thread creation
#
my ($mgr_id, $mgr_req_q, $mgr_ack_q);
$mgr_req_q = new Thread::Queue;
$mgr_ack_q = new Thread::Queue;
$mgr_id = threads->create("SerialLogger::manager");

# Main window
#
my $w_top = MainWindow->new(-title => "COM Monitor");
...
...
# tk stuff
MainLoop;

# Clean up and exit (after MainLoop returned)
$mgr_req_q->enqueue("die");
$mgr_id->join();
exit(0);
[download]

Note the communication queues. I couldn't think of a better way than two, one for each direction.

Blocking vs. non-blocking serial port read

Win32::SerialPort provides us with two options for reading the serial port: blocking read() and non-blocking read_bg().

I first tried to non-blocking alternative, in an attempt to do all the monitoring in that single background thread. The idea: loop over all the open ports and ask them (non blockingly) if they have data for us, if they do, log it.

This approach worked - but had a serious flaw. The logging thread would take up 100% CPU and seriously clogged the PC - naturally, after all it ran an endless loop. The solution: wait/sleep/whatever between iterations. However, as I already said in the case of Tk's "after", we can't reliably wait for short periods (at least 30ms), and that caused missed characters and stuck communication.

So, the only solution left is blocking read(). When SerialPort::read(1) is called, it blocks until the monitored port receives a character, and then returns that character. This block is what I call "sleepy" - it keeps the CPU free (most likely that it's implemented with an interrupt deep down in the Windows API). Hurray ! We can monitor ports and keep the CPU free.

Not so quick... It would be fine if we only had one port to monitor. But when it's two or more, this approach won't work. While we block on one port, the other may receive data and we'll lose it after its buffer overflows (which happens quickly, especially in continuous data streams). Looks like a more complicated solution is due...

The manager-workers model

One of the best known methods of multi-threaded programming is the manager-workers model. A single manager thread creates worker threads to do jobs, and manages them. It keeps an eye on free workers and on incoming jobs. From the worker's point of view, it can either work on some job or wait for the manager to assign it one. From the manager's point of view, it receives jobs and sends them to workers. This is the approach that finally allowed me to fulfill the requirements:

As we saw, blocking read() is required to make the program's performance reasonable (installing a CPU clogging utility is very rude...). But a logging thread can't block on more than one port at the same time. SO... what we need is one (worker) thread per port, and a single (manager) thread to manage these workers.

The manager thread will keep a queue (actually two queues, for bidirectional communications) for each worker. It will send the worker "init", "run" and "stop" commands, and the worker will act according to those. To demonstrate, here is the complete "worker" thread function that is called (with threads->create) by the manager for each port it's told to monitor:

# worker thread function
#
sub serial_logger
{
    my ($num, $fh) = @_;
    my $state = "idle";
    my $mycom;
    
    print "worker $num born\n" if $THR_DEBUG;
    
    while (1)
    {
        if (my $msg = $worker_req_q[$num]->dequeue_nb())
        {
            print "worker $num got '$msg'\n" if $THR_DEBUG;
            
            if ($msg eq "die")
            {
                $worker_ack_q[$num]->enqueue("OK");
                return;
            }
            
            if ($state eq "idle")
            {
                my $ret;
                
                if ($msg =~ /^open\s(.*)$/)
                {
                    ($ret, $mycom) = @{open_com($1)};
                    $worker_ack_q[$num]->enqueue($ret);
                }
                elsif ($msg eq "run")
                {
                    $state = "running";
                }
            }
            elsif ($state eq "running")
            {
                if ($msg eq "stop")
                {
                    clean();
                    $state = "idle";
                }
            }
        }
        
        if ($state eq "running" and $mycom->{is_open} == 1)
        {
            eval
            {
                my ($rb, $byte) = $mycom->{port}->read(1);
                
                if ($rb > 0)
                {
                    my $s = gettimeofday();
                    my $prt = join(",", $mycom->{name}, ord($byte), "$
+s");
                    print $fh "$prt\n";
                }
            };
            if ($@)
            {
                $state = "idle";
            }
        }
        else
        {
            select(undef, undef, undef, 0.01);
        }
    }
}
[download]

As you can see, each worker has a state - it's either idle or running (monitoring). When idle, it just waits for 10 ms using 'select' (this will probably result in a 30 ms wait). We don't care waiting here, because it starts running only after the manager is being asked so by a GUI events. The non-blocking dequeue_nb() call checks if it has new messages from the manager on each iteration. When a command to open a port is received, the worker dutifully opens a Win32::SerialPort. When a command to run is received, the worker is in "running" state, where it no longer sleeps on each iteration, but reads data from the port with a blocking read, and logs it to the dump file when received.

To see the manager's side of the communication, here's the manager's response to the "open" and "run" messages from the GUI:

elsif ($msg =~ /^open\s(.*)$/)
{
    my $thrid = threads->create("serial_logger", $n_workers, $mgr_fh);
    push(@worker_id, $thrid);
    $worker_req_q[$n_workers]->enqueue($msg);
    my $ret = $worker_ack_q[$n_workers]->dequeue;
    $mgr_ack_q->enqueue($ret);
    ++$n_workers;
}
elsif ($msg eq "run")
{
    $mgr_state = "running";
    broadcast_to_workers("run");
}
[download]

When an "open" command arrives, the manager creates a worker thread to handle the port. When the "run" command is received, the manager sends a "run" command to all the workers. What about CPU clogging ? There's none. The manager thread sleeps on each iteration - it doesn't mind, it only responds to GUI requests. The workers sleep when not running, and block on read() when running, so no "naked loops" and the program hardly bothers the CPU.

Conclusion

This implementation answers all the requirements: multiple ports can be monitored simultaneously and logged into a single file with timestamping. The output is terrific for protocol debugging, we can see exactly what was going on the line and when. The program provides reasonable performance and doesn't block the CPU.

Some problems still remain:

• Win32::SerialPort is not an ace in error recovery (i.e. frame/parity errors), or I still haven't found out how. BTW, I don't like its documentation - it's very terse and doesn't cover many uses and questions.
• Though the monitor keeps up with two 2400 baud ports, when the baudrate is higher, the situation is quite worse. At 38400 baud, the monitor can't keep up with a continuous stream. I don't know how to solve this, since it's a basic Perl performance problem - handling each byte takes just too long (and bytes arrive each 260 micro-seconds...)
• When packaged with PAR, the performance of the monitor is lacking. PARred apps usually load slowly, but this one loads especially so. I believe that the problem is threads (which are implemented as separate interpreters in Perl). Opening each port (after the monitor loaded) also takes lots of time, since it involves creating a thread.

All in all, however, this task proves that Perl is good for just about anything. This is a serious industrial-level application, very useful for debugging serial protocols.

I'll be happy to hear insights on the problems I ran into. Tk/threads/SerialPort is a rare combination, and as you saw many interesting issues arise.

The full code can be downloaded from here