[serial] Review Terminal Emulation Over Serial

[erikbgithub]

Situation

The current implementation of SerialConn already offers a simple interface:

>>> import monk_tf.serial_conn as msc
>>> serialconn_obj = msc.SerialConn([details])
>>> serialconn_obj.cmd("ls")
bin coding Desktop Documents Downloads [...]
>>>

It is very likely that the functionality can be improved, now that we have more experience with the interface and the pyserial framework.

Task

Look into the serial_conn module and review the implementation of the cmd() interface and fundamental functionality. An implementation that only considers the best case is fine, because error handling will be added in another step.

Notes

• branch f-review-serial-cmd
• brain storming proposal
• first review
• second review
• current proposal

[erikbgithub]

My idea is that the cmd() method follows this process:

1. prepare if necessary (e.g. check if the serial_connection is open)
2. send a string
3. receive the response
4. analyse the response
5. give feedback if response wrong
6. filter response
7. return command's output

[erikbgithub]

To analyse and filter it is necessary to parse a pretty much random string. Not random because we don't know what comes back, but random because everything might get lost or changed on the way to the buffer in the software we can access. Therefore it makes sense to apply a general purpose parser framework to do the string parsing and filtering for us. It might be more stable and faster than anything we can write ourselves, and also included error handling, which our code might not have in this depth.

The basic structure of a successful response looks like follows:

<something left in the buffer><our command><EOL>
<command output><EOL> # optional (EOLs inside the command output treated as any character)
<prompt><space>

We can see that the command output is surrounded by our command at first and the prompt at last. In between might or might not be a command output. If there is a command output, it will be appended by an EOL statement.

The grammar has the following features:

• start and end of output is clear
• there is a chance to be certain of success, if <our command> and <prompt> are received exactly as expected
• there is a chance to guess an error happens, if <our command> is not exactly as the string we sent
• there is a chance to guess an error happens, if <prompt> is not received in the end

[erikbgithub]

Okay, I think I could simplify the idea to something that doesn't require a full blown grammar based parser.

The new plan for the function is that:

1. prepare if necessary (e.g. check if the serial_connection is open)
2. send a string
3. parse-read-loop
4. set object state
5. strip newlines (left over from the {cmd} and before the last {prompt})
6. return command's output

The parse-read-loop part would look like that (black perl = come from there; surrounded state or pearl=end):

to complete all tasks neither grammar nor regexes would be required. Only the default str.find(txt)->int function would be used.

[erikbgithub]

Another problem is the {prompt}. How do we know what is the {prompt}? Every system or user might set a different one, right?

The first idea, was to simply send an {EOL} and take the whole response, which should be a {prompt} as such. But that doesn't always work, because some parts in the prompt can change, e.g. the time or path.

Therefore I will try to set PS1 as the first step before starting serial communication to something static. Then we should have a deterministic behaviour. Still needs some experimenting, though.

[erikbgithub]

After reviewing the current code at the Stammtisch, some additional changes were proposed:

• [x] cmd() should return the confidence value as well, because a user of cmd should be forced to handle it in some way
• [ ] It should be possible to add more abort criteria beside the prompt, because it might happen, that you have a long running process and can determine on words like Error 42 that the call failed and don't have to wait until you receive a prompt or hit the timeout.
• [ ] the pyserial.read() function should be able to work in a blocking mode which should make waiting in the loop unnecessary.

[erikbgithub]

from last friday I'm currently working on the third point stated before: read() should be block itself while called.

The idea of reading single bytes in a blocking manner and looping until happens seems to be a bad feeling in Python, simply based on my instinct. There is a reason, why more bytes can be assigned to be read and there should be a better way to do it.

To find meaningful alternatives I'm going to ask stackoverflow for advice.

[erikbgithub]

I found a way to read everything that comes as a response to sending a command over the wire: readall(). This should be called automatically by read() if the number of bytes given is 0, which should be the default, not 1 as in pyserial. I added an Issue with that information to the pyserial bug tracker.

Currently readall() is really slow in pyserial, but fast enough with a test file. So I assume that a better read() implementation in pyserial would result in a useful read() and readall() behaviour, which makes most of my own implementation meaningless.

This is a good thing, because code we don't have to implement, we also don't have to maintain. :)

[erikbgithub]

Here is the default interface, provided by RawIOBase, a class that is inherited by serial.Serial.

pyserial overwrites read(), which is not analyzed yet.

[erikbgithub]

Feedback from today's Stammtisch:

• decision to try to use more of the standard behavior accepted
• tips for further investigation into POSIX filedescriptor blocking, termios configuration, and profiling the slow Serial.readall() call

Todo from today's Stammtisch:

• [x] profiling of slow readall() call
• [x] investigate POSIX filedescriptor blocking behavior
• [x] investigates TermIOs config options that might influence blocking, timeouts and EOF signalling

Conclusion

• best solution to accept default implementation
• use readall() instead of writing own read loop
• find good timeout by try & error
• current proposal implementation of cmd()

[erikbgithub]

Profiling of slow readall() calls

I found that the readall() of a serial.Serial object reacts rather slow. Therefore I want to profile, what exactly makes this function so slow.

Profiling Investigation

Because we've never done a profiling task in Python, the first step is to investigate profiling tools.

Resources

• There is a page about profiling in the CPython documentation.
• A good presentation can be found here
• A video with an example is here

Tools

Profilers:

• cProfile - which is considered the default choice
• profile - pure Python implementation of cProfile, which is slower but more flexible
• hotspot - an experimental tool, which isn't maintained anymore
• line profiler - runs a profile for lines not function calls

Profile Viewers:

• RunSnakeRun - simple, Python, seems easy to use
• KCacheGrind - more in depth, less viewable, supposedly doesn't run on Windows

Proposed Profiling Process

1) run cProfile to create the profile file needed.

• with a simple Python command

>>> import cProfile as p, pstats as s
>>> p.run("<the command>", "<save as filename>")

• or from a terminal

python -m cProfile [-o output_file] [-s sort_order] myscript.py

• profiling specific functions in the call only

>>> import cProfile as p
>>> prof = p.Profile()
>>> prof.runcall(func_name, *args, **kwargs)

2) look at RunSnakeRun to find the problem areas of your code

 $ runsnake <stats filename>

3) fix the problem

4) repeat from 1 until global time okay.

some data

>>> ser = serial.Serial("/dev/ttyUSB1", 115200,timeout=1.5)
>>> p.run("ser.write('cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; \\n'); a=ser.readall()","restats"); s.Stats('restats').strip_dirs().sort_stats(-1).print_stats()
Fri Jun 28 16:53:13 2013    restats

         668 function calls in 3.270 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.270    3.270 <string>:1(<module>)
        2    0.002    0.001    3.270    1.635 serialposix.py:439(read)
        1    0.000    0.000    0.000    0.000 serialposix.py:464(write)
      266    0.000    0.000    0.000    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      131    0.000    0.000    0.000    0.000 {method 'extend' of 'bytearray' objects}
        1    0.000    0.000    3.270    3.270 {method 'readall' of '_io._RawIOBase' objects}
      131    0.002    0.000    0.002    0.000 {posix.read}
        1    0.000    0.000    0.000    0.000 {posix.write}
      133    3.266    0.025    3.266    0.025 {select.select}

>>> ser = serial.Serial("/dev/ttyUSB1", 115200,timeout=.5)
[...]
         613 function calls in 1.262 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.262    1.262 <string>:1(<module>)
        2    0.001    0.001    1.262    0.631 serialposix.py:439(read)
        1    0.000    0.000    0.000    0.000 serialposix.py:464(write)
      244    0.000    0.000    0.000    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      120    0.000    0.000    0.000    0.000 {method 'extend' of 'bytearray' objects}
        1    0.000    0.000    1.262    1.262 {method 'readall' of '_io._RawIOBase' objects}
      120    0.001    0.000    0.001    0.000 {posix.read}
        1    0.000    0.000    0.000    0.000 {posix.write}
      122    1.259    0.010    1.259    0.010 {select.select}

>>> ser = serial.Serial("/dev/ttyUSB1", 115200,timeout=2)
[...]
         4657 function calls in 9.239 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    9.239    9.239 <string>:1(<module>)
        9    0.021    0.002    9.239    1.027 serialposix.py:439(read)
        1    0.000    0.000    0.000    0.000 serialposix.py:464(write)
     1863    0.001    0.000    0.001    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      926    0.002    0.000    0.002    0.000 {method 'extend' of 'bytearray' objects}
        1    0.000    0.000    9.239    9.239 {method 'readall' of '_io._RawIOBase' objects}
      926    0.029    0.000    0.029    0.000 {posix.read}
        1    0.000    0.000    0.000    0.000 {posix.write}
      928    9.185    0.010    9.185    0.010 {select.select}

>>> p.run('ser.cmd("cat /etc/passwd;")','restats'); s.Stats('restats').strip_dirs().sort_stats(-1).print_stats()Mon Jul  1 15:44:08 2013    restats

         98 function calls in 2.116 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.116    2.116 <stdin>:1(cmd)
        1    0.000    0.000    2.116    2.116 <string>:1(<module>)
        2    0.001    0.000    2.115    1.058 serialposix.py:439(read)
        1    0.000    0.000    0.000    0.000 serialposix.py:464(write)
       36    0.000    0.000    0.000    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
       16    0.000    0.000    0.000    0.000 {method 'extend' of 'bytearray' objects}
        1    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    2.115    2.115 {method 'readall' of '_io._RawIOBase' objects}
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'strip' of 'str' objects}
       16    0.001    0.000    0.001    0.000 {posix.read}
        1    0.000    0.000    0.000    0.000 {posix.write}
       18    2.114    0.117    2.114    0.117 {select.select}

>>> p.run('ser.cmd("cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; ")','restats'); s.Stats('restats').strip_dirs().sort_stats(-1).print_stats()
Mon Jul  1 15:45:02 2013    restats

         388 function calls in 2.455 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.455    2.455 <stdin>:1(cmd)
        1    0.000    0.000    2.455    2.455 <string>:1(<module>)
        2    0.002    0.001    2.455    1.228 serialposix.py:439(read)
        1    0.000    0.000    0.000    0.000 serialposix.py:464(write)
      152    0.000    0.000    0.000    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
       74    0.000    0.000    0.000    0.000 {method 'extend' of 'bytearray' objects}
        1    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    2.455    2.455 {method 'readall' of '_io._RawIOBase' objects}
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'strip' of 'str' objects}
       74    0.002    0.000    0.002    0.000 {posix.read}
        1    0.000    0.000    0.000    0.000 {posix.write}
       76    2.451    0.032    2.451    0.032 {select.select}

>>> p.run('ser.cmd("cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; cat /etc/passwd; ")','restats'); s.Stats('restats').strip_dirs().sort_stats(-1).print_stats()
Mon Jul  1 15:45:51 2013    restats

         1110 function calls in 3.316 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.316    3.316 <stdin>:1(cmd)
        1    0.000    0.000    3.316    3.316 <string>:1(<module>)
        3    0.005    0.002    3.315    1.105 serialposix.py:439(read)
        1    0.000    0.000    0.000    0.000 serialposix.py:464(write)
      441    0.000    0.000    0.000    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      218    0.001    0.000    0.001    0.000 {method 'extend' of 'bytearray' objects}
        1    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    3.315    3.315 {method 'readall' of '_io._RawIOBase' objects}
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'strip' of 'str' objects}
      218    0.006    0.000    0.006    0.000 {posix.read}
        1    0.000    0.000    0.000    0.000 {posix.write}
      220    3.304    0.015    3.304    0.015 {select.select}

Conclusions

• seems to be timeout dependent
• output doesn't have that much of an influence
• most time spent in select()
• making timeout too small loses data, because it isn't read yet
• making timeout too big loses data, because there might not be buffer left to store it
• compromise seems to be between 1-1.5 sec

[erikbgithub]

Filedescriptor Blocking

• every process has it's own file descripor table in the kernel
• the fd itself is an index to that table
• the entry in the table contains information about an open file
• filetypes:
  • file
  • directory
  • symlink
  • named pipes
  • unix domain socket
  • device file
  • door

Blocking

http://www.kegel.com/dkftpbench/nonblocking.html

• blocking means a read() or write() system call will wait as long as there are no bytes to read
• blocking is easier, non blocking faster - don't optimize too early
• most systems implement polling or interrupts
• interrupts can be implemented as separate lines in hardware to the CPU and as messages in software
• interrupts are preferred for performance, as long as they don't happen too often
• loops seem to be the simpler solution, but they waste processor time with unsuccessful loops and might be relatively inefficient if select is used

Open reads: http://en.wikipedia.org/wiki/Everything_is_a_file

Conclusions

• blocking makes things easier
• non-blocking can perform much better
• first using blocking mode makes sense

[erikbgithub]

TermIOs blocking configuration options

• It is likely that we "receive" null bytes, because not setting the termios options IGNPAR and BRKINT results in presenting partiy or framing errors as null bytes.
• INLCR translates NL to CR and ICRNL the other way around (TODO: investigate)
• IUTF8 (linux >2.6.4 only) input as UTF-8
• ONLCR (XSI) Map NL to CR-NL on output
• ONLRET don't output CR
• XCASE (neither POSIX nor Linux) set uppercase everything
• VEOF does some stuff with EOF chars
• termios sets configuration in the driver on the client side of the interaction
• our UART-USB converter uses the driver ftdi_sio

Important flags:

• VMIN "Minimum number of characters for noncanonical read
• VTIME Timeout in deciseconds for noncanoncial read
• only for non-canonical mode

Canonical and noncanonical mode

• can be set with ICANON flag in c_lflag part of termios
• if either one of the following flags is >0 a call to read(2) will return with the requested byte or when he found at least VMIN bytes and/or after VTIME deciseconds have passed.
• This means, that VTIME can introduce select() like blocking behaviour

In Pyserial

• configuration does some decisions for us
• no direct way to influence behavior
• timeout is only implemented via select
• connection is raw, no echo, binary

Further Reading

• http://en.wikipedia.org/wiki/POSIX_terminal_interface
• http://en.wikipedia.org/wiki/Line_discipline
• http://en.wikipedia.org/wiki/Curses_%28programming_library%29
• http://www.linusakesson.net/programming/tty/

Conclusion

• VTIME can be used for select() like blocking behaviour, but only available in noncanonical mode
• some other things might be handled by the driver through this configuration, e.g. newline handling
• there seems to be a cannonical mode, which has some kind of timeout for it's premanipulation buffer, but that is still a little confusing. is that the same as cooked mode?

[erikbgithub]

Might curses be an option for handling characters system dependent?

[erikbgithub]

current solution

Although I start to feel rather unhappy with readall(), it seems to be the simplest solution for now and it seems to work in most cases, which is exactly the solution we wanted for this issue. Current cmd() would look like that:

def cmd(self, msg):
  self.write(msg.strip() + "\n")
  return "\n".join(self.readall().replace("\r","").split("\n")[1:-1])

In detail:

self.write(msg.strip() + "\n")

• use the serial write
• strip() removes all whitespace around the msg string
• + \n makes sure the serial terminal understands the msg string as command

  return "\n".join(self.readall().replace("\r","").split("\n")[1:-1])

• reading from inside out is important here
• self.readall() is the call to the Python std function which is inherited in serial
• .replace("\r","") removes the windows part of new lines that somehow sometimes appear
• .split("\n") split up the string to a list of lines, which makes the next step very simple
• [1:-1] remove the first and last list element, which is the first line (the command we just sent) and the last line (the next prompt). This can be checked later on, but is not necessary for completing this issue.

[erikbgithub]

the feedback from today's Stammtisch:

1. Last research state about terminal configuration, profiling and io blocking
2. the current proposal for the "sunshine case" cmd() implementation
3. the new compromise about practical MONK development and my master thesis

Results:

1. purely informative summary, see links above for details. termios and profiling might be useful for other problems as well.
2. possible problems were found, which will be handled at the right time
   • a lot of calls on our and probably other devices as well will take much longer than reasonable timeouts might consider. Those cases can't be handled with current cmd() implementation at all (link)
   • the current call takes longer than it normally would need to, because select waits once until timeout for sure, which might be a problem or not (link)
   • again we found that kernel output might turn an otherwise useful cmd() call into garbage, which might be handled with a kmod system call on the target device (link)
3. to have a theoretical foundation for a Master thesis the full stack of layers should be implemented minimally until October 1 2013. Afterwards they shall be made practically useful:
   • the serial cmd() as is
   • a device abstraction
   • a configuration method for MONK test cases
   • about 3 example test cases for presentation purposes

This means that the current "sunshine" implementation of cmd() should be used for now and will be replaced or extended later, when real case scenarios are added.

[erikbgithub]

ACKs come from the decision made in the last Stammtisch. Issue is assumed finished.