Current source code: multithreaded_logger.c.
Makefile: Makefile.
Doxygen documentation: here.
The documentation is generated with the configuration file Doxyfile
in the subdirectory doxygen/working/, and the output is placed in the subdirectory
doxygen/output/, via "doxygen doxygen/working/Doxyfile".
A bash script to list all threads of the program, showing including the priorities and CPU times:
showml.sh.
Example output with main (light-weight process (LWP) 1609), which started the serial reading threads (LWP 1632 and 1634), the timing thread for polling (LWP 1634),
one parallel port reading thread (LWP 1645) and at last the thread for flushing the log file (LWP 1649), at 30 kHz polling frequency after a few hours:
F S UID PID PPID LWP C NLWP PRI NI ADDR SZ WCHAN RSS PSR STIME TTY TIME CMD 4 S root 1609 787 1609 1 6 -37 - - 317723 hrtime 1201252 0 Apr25 ? 03:23:24 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1 S root 1609 787 1632 0 6 -38 - - 317723 poll_s 1201252 0 Apr25 ? 00:01:10 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1 S root 1609 787 1634 0 6 -38 - - 317723 poll_s 1201252 0 Apr25 ? 00:01:11 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1 S root 1609 787 1636 10 6 -40 - - 317723 hrtime 1201252 1 Apr25 ? 18:52:45 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 5 S root 1609 787 1645 15 6 -39 - - 317723 sigtim 1201252 0 Apr25 ? 1-04:39:08 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1 S root 1609 787 1649 0 6 -36 - - 317723 sigtim 1201252 1 Apr25 ? 00:00:09 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 USER PID PPID TT CMD CLS PRI RTPRIO root 1609 787 ? ./multithreaded_logger 34 4 RR 136 96 pid 1609's current scheduling policy: SCHED_RR pid 1609's current scheduling priority: 96 top - 08:34:44 up 7 days, 16:13, 3 users, load average: 0.40, 0.43, 0.41 Threads: 6 total, 0 running, 6 sleeping, 0 stopped, 0 zombie %Cpu(s): 7.0 us, 8.1 sy, 0.0 ni, 84.8 id, 0.1 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem: 3843228 total, 2588396 used, 1254832 free, 401704 buffers KiB Swap: 3004828 total, 0 used, 3004828 free. 612648 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1645 root -99 -20 1270892 1.146g 2120 S 13.3 31.3 1719:08 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1636 root rt -20 1270892 1.146g 2120 S 13.3 31.3 1132:45 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1609 root -97 -20 1270892 1.146g 2120 S 6.6 31.3 203:24.46 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1634 root -98 -20 1270892 1.146g 2120 S 0.0 31.3 1:11.24 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1632 root -98 -20 1270892 1.146g 2120 S 0.0 31.3 1:10.78 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10 1649 root -96 -20 1270892 1.146g 2120 S 0.0 31.3 0:09.37 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10
A C++ program to list all availible serial ports, source code:
findser.cpp.
But the program does not find RocketPort ports, which are at /dev/ttyR*.
Other ways are checking /dev/tty* with stty, checking the boot messages with "dmesg | grep tty" or grepping in /sys and using an alias (in ~/.bashrc):
# list all availible serial ports, works also with USB converters and in an Oracle VM VirtualBox
alias findserial='ls -l /sys/class/tty* | grep /p | grep -v virt | grep -v ../../devices/platform/'
A bash script to estimate the lowest and highest possible baud rate of a serial port, with the serial port name (e.g. ttyS0)
as command line parameter:
tty_speedtest.sh.
This script, and the findser program, also works with serial converters and modems,
e.g. with an USB-RS-232 converter at ttyUSB0 or the Samsung SGH D900i at ttyACM0.
A bash script to list all availible parallel ports:
findpar.sh.
It can not find parallel ports at USB adapters, which are usually at /dev/usb/lp* from the driver usblp.
But such adapters are rare and more than a thousand times slower as a parallel port onboard or on a PCI or PCIe
card. And an USB alternative is using the parallel input pins of USB serial adapters (CTS =Clear to Send, RI = Ring Indicator,
DSR = Data Set Ready and DCD = Data Carrier Detect, simple signals at RS-232, differential signals at RS-422/485).
Therefore multithreaded_logger reads the level of these signals via ioctl(), not port access because that does not work at
USB adapters.
But USB adapters should generally be avoided because USB often is not stable, so that sometimes an adapter can not be found
or vanishes at ttyUSB0 and comes back at ttyUSB1.
A C program to measure the time of a port access by doing 1e6 (one million)
readings/writings and see how long it takes, thus calculating how much time a port access takes at average, source code:
simpleportbenchmark.c.
The port latency is important for measuring the time of level changes with
a high time resolution and for hard real time applications, where
it makes a big difference if the latency of the port is about 1.5 µs
(PCI/PCIe/Expresscard) or 15 ms (USB adapter).
The C program swave12a.c for toggling the parallel port pins,
with three parameters: Priority, timer period and base address.
Example with priority 98, timer period 50,000 nanoseconds and base address 0x3008:
nice --20 ionice -c Realtime -n 0 ./swave12a 98 50000 0x3008
With a timer period of 50,000 ns the output is:
10 kHz on pin 2 = D0
5 kHz on D1
2 kHz on D2
500 Hz on D3
250 Hz on D4
100 Hz on D5
40 Hz on D6
20 Hz on D7
8 Hz on C0
4 Hz on C1
1.5 Hz on C2
0.5 Hz on C3.
So it produces square waves for oscilloscopes and blinking for the eyes or tones for the ears.
It causes about 9 % CPU load on a 3 GHz CPU.
A video, with green LEDs at the data pins (D*), yellow LEDs at the status pins (with integrated pullups) and
red LEDs at the control pins (C*):
The sound from D0 (10 kHz) under load with an RT Kernel (4.13-rt3):
The sound (and sometimes litte background noise) with an lowlatency kernel (4.0.5-040005-lowlatency):
With a non-RT kernel the latencies of many microseconds do cause clicks.
At the LED blinking there is no visible difference between RT and non-RT kernels.
A C program to read a byte from an I/O port, command line version of inb(), source code:
inb.c.
The pramameter, the port address, can be decimal, hexadecimal or octal.
A C program to write a byte to an I/O port, command line version of outb(), source code:
outb.c.
The pramameters, byte and port address, can be decimal, hexadecimal or octal.
A C program to show environment parameters like the size of an int, a pointer etc. and the Endianess because this is important for ports wider than 8 bits and generally at reading/writing more than 8 bits at a time, source code: environment_test.c.
A C program to set the 8 data pins of a parallel port as input pins,
with the parallel port number as command line parameter, source code:
setpar_bppin.c.
The program set also sets the port to mode bidirectional mode aka Byte mode aka PS/2 mode aka Tristate mode.
If you can set the parallel port type to Mode Bidirection in the BIOS, you should do so before to make sure
this mode is available.
This program is made to prepare the parallel port(s) for multithreaded_logger or other programs which do read from the parallel
port(s) data pins (D0-D7).
If the first arguments, the parallel port number, starting with 0, has a negative sign, this flag sets the port
to write mode. See also the online help of the program.
Example script with configuration for reading from two serial ports and one parallel port, including nice and ionice setting for the program: test3.sh. This script also prints some environment data, uses a lock file, configures the first parallel port 8 data pins as inputs and creates a log file for its output.
Command line:
./multithreaded_logger --help ./multithreaded_logger version 2015-12-23 (compiled Dec 26 2015, 10:58:31). Usage: ./multithreaded_loggerYou can specify up to 32 devices with device flags. Example: ./multithreaded_logger 200 2 ttyS0 1 ttyUSB0 3 0 0x10 for logging the serial data from the UART /dev/ttyS0 and /dev/ttyUSB0 and the parallel data from the /dev/ttyUSB0 and the first parallel port (/dev/parport0) with a polling time of 200 microseconds, which means 5 kHz polling frequency, and printing the parallel data into the log file only at the start and at rising edges. Polling time: 1 ... 2,147,483,648 microseconds. Filter types: 1: no filtering, 2: Only rising edges, 3: Only falling edges, 4: All edges (all changes) and first value (elimination of all redundant date, data compression), 5: Only when at least one bit is zero (not set), 6: Only when at least one bit is one (set), with negative sign: Print the bits as series of bits in (hexadecimal) bytes and not as single nibble (with value 0 for actual and previous value zero, 1 for actual and previous value one, 2 for falling edge and 3 for rising edge, so BIT0 is the current state and BIT1 indicates an edge. Device flags: 1 for UART input, 2 for parallel input from serial port (RI, DSR, DCD, CTS), 0x10 for parallel input from parallel port (all 13 input pins). For every reading, writing and timing thread a (posix) thread works, so at total +1)*2 threads are working for this program. For configuration of the serial devices use a program like stty. The current posix threads implementation is: Native POSIX Threads Library by Ulrich Drepper et al
This example logs the serial data from /dev/ttyS0 (device-number 0), ttyS1 and the parallel data (device-number -1) from the first serial port,
with a polling interval of 34 microseconds and filtering, so that parallel data are logged only at the first polling and after this start only
when there is a change, so that the data are lossless compressed.
The header and the footer have a lot of metadata and statistics. The first (zeroth) error bit counter is for serial devices the
counter of bit 0 in the line status register, which shows that the data is ready, that means that a byte was received in UART
and the receiver buffer is ready for reading.
The command line is:
nice --20 ionice -c Realtime -n 0 ./multithreaded_logger 34 4 ttyS0 1 ttyS1 1 0 0x10
This line is executed with the script test3.sh (above) and the output is also teeed to the log file
here.
Log file:
multithreaded_logger vers. 2015-12-21, last modified Tue Dec 22 08:03:40 2015, compiled with GCC version 4.9.2, at Dec 22 2015 08:03:43, start at 2015-12-22 08:06:10 UTC. Monitoring devices (number 0, 1, ...) with the flags: ttyS0 0x1 ttyS1 0x1 0 0x10 OS: Linux release 4.1.3-rt3 (version #2 SMP PREEMPT RT Tue Aug 11 06:59:47 UTC 2015) on x86_64, byte order little Endian Posix version: 200809, the current posix threads implementation is: Native POSIX Threads Library by Ulrich Drepper et al _POSIX_THREAD_PRIORITY_SCHEDULING is true, the POSIX real-time extensions are supported. Parallel port parport0: Base address 12296 = 0x3008. Used clock type: CLOCK_REALTIME with a resolution of 1 ns, scheduling time slice (sched_rr_get_interval): 0.100000000 s. Polling interval [microseconds]: 34, Filter type: 4, main() loop interval [ms]: 200. Date time daylight-saving-time device-number (hex)data: 2015-12-22 08:06:11.513216 0 -1 1 1 1 1 1 1 1 1 1 1 1 1 1 2015-12-22 08:07:00.656674 0 -1 2 2 2 2 2 2 2 2 2 2 2 2 2 2015-12-22 08:07:00.797094 0 -1 3 3 3 3 3 3 3 3 3 3 3 3 3 2015-12-22 08:07:01.087216 0 -1 2 2 2 2 2 2 2 2 2 2 2 2 2 2015-12-22 08:07:01.216382 0 -1 3 3 3 3 3 3 3 3 3 3 3 3 3 2015-12-22 08:07:01.349356 0 -1 2 2 2 2 2 2 2 2 2 2 2 2 2 2015-12-22 08:07:06.117163 0 0 00 2015-12-22 08:07:06.117163 0 1 00 2015-12-22 08:07:06.137154 0 1 01 2015-12-22 08:07:06.137164 0 0 01 2015-12-22 08:07:06.177139 0 1 02 2015-12-22 08:07:06.177141 0 0 02 2015-12-22 08:07:06.193476 0 -1 3 3 3 3 3 3 3 3 3 3 3 3 3 2015-12-22 08:07:06.217124 0 1 03 2015-12-22 08:07:06.217127 0 0 03 ... (truncated) 2015-12-22 08:07:18.512999 0 -1 2 2 2 2 2 2 2 2 2 2 2 2 2 2015-12-22 08:07:18.665420 0 -1 3 3 3 3 3 3 3 3 3 3 3 3 3 2015-12-22 08:07:23.123456 0 Termination at 2015-12-22 08:07:23 Minimum and maximum number of new elements (structures) when main reads from posix threads buffers (size 16384 elements) including fragmented ones: 4, 5883 (10501 reserve). Minimum and maximum number of (new) elements in the main buffer (size 32768 elements): 4775, 5899 (26869 reserve). Total number of from the UARTs received bytes: 512, packets: 512, number of packet defragmentations: 0 = 0 %. Minimum (serial) data packet length: 1, maximum length: 13. Minimum time difference in microseconds of (serial) data packets: 19925, maximum: 41375. Total number of parallel reads (samples): 2109003 = 2.11e+06 First parallel read thread, statistics of the polling timing in microseconds for 2109003 = 2.11e+06 time differences (actual -nominal value), including the offset for signal handling, clock_gettime etc.: Average deviation of the polling in microseconds: 3.971. Minimum deviation: 3.579. Maximum deviation: 30.40, at index 1606001 = 1.61e+06. Date and time of the maximum deviation (latency): 2015-12-22 08:07:06.117849 0 Filter statistics (delayed packets, to avoid non repeatable reads): 28750 because of fragmentation, 120181 because of maybe not committed packets. Error counts for each ot the 4 threads (parity error etc., for serial read threads first the bit counts from the line status register): 256 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 256 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 overrun error(s) of the timer thread (polling). 0 overrun error(s) of the main thread 359 = 3.59e+02 nanosleeps. Last received signal: 15, total signal count: 1. Shutdown process bits: 0x0. A shutdown is not pending. Current runlevel (usually 5): 5.
I corrected the function for getting the base address of a parallel port from /proc/sys/dev/parport/parportX/base-addr and added a program for port benchmarking, for measuring the average time of one port access (reading or writing).
I added the set_latency_target(void) from Cyclictest and munlockall() at termination.
Added handling and logging of overrun errors of the timer thread (polling), corrected packet counter printing.
I found out that
with select() it is difficult, almost impossible, to handle signals correctly and that
select() has a race, even when used with only one device, see
http://www.win.tue.nl/~aeb/linux/lk/lk-12.html#ss12.3.
So i will switch from select to pselect in multithreaded_logger.c in the next time.
The automatically loaded parallel port modules from linux are a little complicated:
For finding the base addresses the program needs them but when using them
they should be unloaded because they could disturb.
Therefore the program uses the modules at the start, unloads them before accessing the parallel port(s) and
loads them just before the exit.
So the script freepar.sh, for unloading the modules, is not needed anymore.
Added priorities so that this program has nearly the same worst case latency
as cyclictest (with one thread per CPU). With an old PC and old 3.0 RT
kernel I can use two serial ports and one parallel port with a polling frequency
of 10 kHz without overrun errors.
I made a new version which supports net devices like CAN bus adapters, automatically by the file name
of the serial device.
That should work, but i had no time to test it with net devices.
The current version is tested with 0..1 parallel ports and 0...4 serial ports, standard configuration
is 1 parallel port (13 input pins) at 30 kHz polling frequency plus 2 serial ports (at 19k2 8N1E).
I eliminated a bug which can occure when parallel and serial data are logged simultaneously and which filtered too much parallel data.
I added the picture with the tread structure (above) and made an article about hard real-time and multithreaded_logger in the (german) Linux-Magazin 03/2017: Harte Echtzeit mit Linux durch Preempt-RT zum Messen und Steuern.
I made the lecture 207 at the Chemnitz Linux Days 2017-03-12: https://chemnitzer.linux-tage.de/2017/en/programm/beitrag/207.
The program also works with slow signals and polling every 100,000 mikroseconds (instead of 35), and without hard realtime, e. g.
the Ubuntu Kernel 4.10.0-20-lowlatency (version #22-Ubuntu SMP PREEMPT Thu Apr 20 10:18:38 UTC 2017) on x86_64.
Cyclictest shows a worst-case latency of about 3 ms.
I use it for my mail box, with a cheap IR motion detector alarm set, Wireless Driveway Alert System ORNO OR-MA705, which uses 433-434 MHz and has a maximum range of 120 m.
The detector (OR-MA-705OR) is at the end of the mail box, mounted with a magnet holder. The LED is disconnected
for a longer battery life and to avoid attracting attention.
The electrical signal from the
the radio receiver (OR-MA705OD) comes from the cathode of the LEDs (ground) and their series resistance (blinking signal).
The input at the parallel port is secured with a 4.7 V Z-diode (5 Watt, type 1N5337B) and 1 kOhm series resistance:
The other 51 inputs of the TP35 card are unused.
The result is the logged LED blinking at motion detection, when something goes in or out of the mail box:
2017-05-20 04:46:16.418655 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 04:46:17.418655 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 04:46:17.718657 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 04:46:18.718656 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 04:46:19.018658 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 04:46:20.018658 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 04:46:20.318655 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 04:46:21.318654 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 10:46:04.218656 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 10:46:05.218657 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 10:46:05.518654 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 10:46:06.518653 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 10:46:06.818656 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 10:46:07.818655 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 10:46:08.018658 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 10:46:09.018657 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 15:50:17.518659 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 15:50:18.518662 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 15:50:18.818662 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 15:50:19.818661 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 15:50:20.118660 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 15:50:21.118659 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 15:50:21.418654 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 15:50:22.418654 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 19:19:16.418654 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 19:19:17.418656 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 19:19:17.718654 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 19:19:18.718653 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 19:19:19.018659 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 19:19:20.018659 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0 2017-05-20 19:19:20.218655 1 -1 0 0 0 0 0 0 0 3 0 0 0 0 0 2017-05-20 19:19:21.218655 1 -1 0 0 0 0 0 0 0 2 0 0 0 0 0
After some boots the PCIe card TP35 was not found because the PCIe slot is a loose contact.
So i made an improvisational card downholder by upcycling a little brown bottle with a compression spring and a srew which locks the screw into at the top:
I made some minor improvements: Removed new compiler wanings, changed "struct tm *tm;" to "struct tm *tm0", etc.. In the Makefile i moved the gcc option -lm to the last gcc option, because that was necessary for other programs.
With one added PCIe card i had the problem that the base address could not be found in /proc/ioports, but in the output from
lspci | cut -d: -f1-2 | grep "Parallel controller" | cut -d" " -f1 | while read f; do lspci -v -s $f | grep -m1 ports ; done
The solution is to load module parport_serial, which adds the i/o regions of the added card in /proc/ioports.
The PCIe card TP35 died, can not be found from the PCIe controller.