Re: Serial port driver usage and status

[Itai Handler <itai.handler@gmail.com>]

Hi Michel,

If I understand correctly, you’re measuring the duration of the write function to a serial port.
I think that there is no guarantee that this function will return before the port finishes to transmit all data.
However that doesn’t explain why you’re observing longer than expected duration.
The difference in times of 4ms (from 8 to 12) suggests that the scheduler is involved.
I guess you’re working with CONFIG_HZ_250?
May I suggest that you use function graph tracing (ftrace) to analyze it?

Itai Handler



> On 5 Aug 2020, at 21:29, Michel Macena Oliveira <michel@austral-dynamics.com> wrote:
> 
> Hi, Thanks for your answers
> 
> I've written two simple codes to write a buffer of characters
> into the serial port. I'm reading the characters on another computer
> (windows 10, Termite as serial monitor). I did a simple time analysis
> to know how much time to write a given number of bytes into the port
> for both codes.
> In the first code the write function was called in the main function,
> in the second I put inside a thread function with sched priority 90.
> 
> I did the time analysis using the clock_gettime function with the
> CLOCK_REALTIME flag to get time before and after the write call inside
> a testing loop. Then I got the time measures, calculated the average
> and stored the maximum value.
> I got the same results with non-threaded (NT) and threaded (T) code.
> But I found something weird for both.
> 
> For 1000 testing loops:
> 
> buffer size:  1
> Average Time: NT= 8.044138785 ms  T= 8.126175254 ms
> Maximum Time: NT= 12.069355000 ms T= 12.102010000 ms
> 
> buffer size:  48
> Average Time:  NT= 8.021624309 ms  T= 8.038524315 ms
> Maximum Time:  NT= 12.018302000 ms T= 12.054890000 ms
> 
> buffer size:  49
> Average Time: NT= 12.010010796 ms T= 12.044165909 ms
> Maximum Time: NT= 16.019277000 ms T= 16.038130000 ms
> 
> buffer size:  96
> Average Time: NT= 12.057916205 ms T= 12.054206314 ms
> Maximum Time: NT= 16.101405000 ms T= 16.040888000 ms
> 
> buffer size:  144
> Average Time: NT= 16.043416532 ms T= 16.020754198 ms
> Maximum Time: NT= 20.069923000 ms T= 20.059298000 ms
> 
> buffer size:  145
> Average Time: NT= 20.039547930 ms T= 20.048668453 ms
> Maximum Time: NT= 24.029462000 ms T= 24.038915000 ms
> 
> The first weird thing as you can see is that the time taken is the
> same for a range as long as it is a multiple of 48 bytes. Also it
> doesn't change
> between the prioritized threaded version and non-threaded version.
> 
> The Second weird thing is that for buffer sizes with some values
> multiples of 24 gives the message "stack smashing detected". Some
> values are 72 and 120 bytes.
> 
> Any Ideas of what it could be?
> 
> My settings for serial:
> - 115200 bauds. 8 bits, No parity bit, 1 stop bit
> - ASYNC_LOW_LATENCY flag is set
> - Raw input/output
> 
> Also if I consider the settings above, I would have a frame of 10 bits
> (given 8N1 setting) per second received/delivered from which 8 bits
> are useful data. So it gives 11520 chars (or useful bytes) per second.
> For example, to send 96 bytes it would take 96/11520 seconds or
> approx. 8.33 ms. I know that there is the overhead to system calls and
> other OS complexities, but is there any way to diminish the time taken
> from 12 ms to something at least closer to 8.33 ms?
> 
>> Em qui., 16 de jul. de 2020 às 17:40, Austin Schuh
>> <austin.linux@gmail.com> escreveu:
>> 
>>> On Thu, Jul 16, 2020 at 1:21 PM Michel Macena Oliveira
>>> <michel@austral-dynamics.com> wrote:
>>> 
>>> Em qui., 16 de jul. de 2020 às 16:26, Itai Handler
>>> <itai.handler@gmail.com> escreveu:
>>>> 
>>>> Hi Michel,
>>>> 
>>>> On 7/16/20, Michel Macena Oliveira <michel@austral-dynamics.com> wrote:
>>>>> Hi, sorry for my newbie question,
>>>>> What is the status of the serial port driver?
>>>>> I've written some code to use serial ports  for the generic kernel linux,
>>>>> And now I want to write something similar for the real time kernel, do
>>>>> I have to use some specific library, flags or something or is it just
>>>>> the same settings?
>>>>> 
>>>>> I'm asking because now I need to take into account the serial access
>>>>> in the scheduler to ensure a real time behavior .
>>>>> 
>>>>> Any help, advice, hint or tips would be appreciated.
>>>>> 
>>>> 
>>>> Do you mean that you wrote some code that works with a /dev/tty* serial port?
>>>> 
>>>> In some kernel versions (e.g 4.19) we saw high latencies in the rx
>>>> path of serial drivers.
>>>> I think that this is due to rx handled in the context of a workqueue
>>>> which also handles other system activities.
>>>> We found a workaround to this problem. If I remember correctly we
>>>> create a dedicated thread for the port and assign it a high priority.
>>>> 
>>>> Itai Handler
>>> 
>>> Thanks for the answer,
>>> Yes I wrote a code that works with  /dev/tty* serial using termios.h.
>>> I thought exactly what you suggested, to use a dedicated thread, but
>>> how to properly implement it?
>>> I mean in a simple way, just need to put open and write calls inside
>>> the high priority (RT) thread?
>>> 
>>> Current kernel: 4.4.208-rt198 #1 SMP PREEMPT RT
>> 
>> Itai is talking about the kernel work to handle the serial data, not
>> the userspace work.  We found the same thing, that the work goes
>> through a work queue in the kernel, which adds unbounded latency.
>> 
>> https://www.spinics.net/lists/linux-serial/msg07341.html looks
>> relevant and matches my memory of what we did to solve this.  There's
>> either a flag in userspace or patch to apply to the kernel (and then a
>> flag) to skip the work queue.
>> 
>> Austin