RTSerial Difference in Behavior Between 2.6.4 & 3.1

RTSerial Difference in Behavior Between 2.6.4 & 3.1

[Alan Gaglio]

I am in the process of upgrading from 32-bit/Xenomai 2.6.4/Ubuntu 14.04.4/
Linux 3.16.7 to 64-bit/Xenomai 3.1/Ubuntu 20.04.1/Linux 5.4.77 and I'm
experiencing an rtserial event difference in behavior. Our application
depends on single-byte interrupts from rtserial ports, which we're
not seeing despite having configured rtserial ports the same between our 2
different image configurations that run on the same x86 hardware.
Attached is a modified cross-link.c example that highlights this
difference in behavior. Also included is relevant detail for each target,
build, and sample program output.

My modified cross-link.c transmits 26 characters every 1 second and prints
the number of RX_PEND events along with reception bins every 26 characters
read by the receive thread. Reception bins show the number of bytes
read per RX_PEND event [0-16,17+]. The total number of bytes
processed equals the sum of all bins multiplied by the quantity they
represent. For example, these snipped outputs (from the below greater
details) were taken following a total of 208 bytes transmitted. In
2.6.4 we have 208 events * 1 byte = 208 bytes and in 3.1 we have
48 events * 4 bytes + 8 events * 2 bytes = 208 bytes. We expect/desire the
second bin to be exclusively non-zero (2.6.4 output), indicating an RX_PEND
event for each byte that arrives on the serial port.

2.6.4 Output:
rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446
Count= 208 bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
3.1 Output:
rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954
Count=  56 bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0

I'm not sure where to take the next level of troubleshooting and am happy to
provide additional detail, run tests, etc. The attached cross-link includes
some preprocessor defines to modify program behaviors that I can explain if
helpful. Details shown below are also attached with line wrapping removed
for reference.

Thanks!
Alan

::32-bit System Details::
-BOOT_IMAGE=/boot/vmlinuz-3.16.7 root=UUID=1bfa0993-a88b-4a77-be72-0f1531acf3fa
ro quiet splash 8250.nr_uarts=4 xeno_hal.smi=-1 consoleblank=0 vt.handoff=7
-Xenomai retrieved from
https://www.xenomai.org/downloads/xenomai/stable/xenomai-2.6.4.tar.bz2
-config.log first 14 lines :
  It was created by Xenomai configure 2.6.4, which was
  generated by GNU Autoconf 2.69.  Invocation command line was

    $ ../configure --prefix=/home/delta/kernel/xenomai-libs --enable-x86-sep CFLAGS=-O3

  ## --------- ##
  ## Platform. ##
  ## --------- ##

  hostname = delta
  uname -m = i686
  uname -r = 3.16.7
  uname -s = Linux
  uname -v = #1 SMP Sun Jul 26 11:10:00 EDT 2015
-Ipipe patch retrieved from
https://www.xenomai.org/downloads/ipipe/v3.x/x86/older/ipipe-core-3.16.7-x85-5.patch
::32-bit Example Build::
gcc -o cross-link cross-link.c
-I/home/jbw/GitWorkTree/master/Development/Cobalt/include
-D_GNU_SOURCE -D_REENTRANT -D__XENO__
-I/home/jbw/GitWorkTree/master/Development/Cobalt/include
-D_GNU_SOURCE -D_REENTRANT -D__XENO__ -lrtdm
-L/home/jbw/GitWorkTree/master/Development/Cobalt/lib -lxenomai -lpthread -lrt -lnative
-L/home/jbw/GitWorkTree/master/Development/Cobalt/lib -lxenomai -lpthread -lrt
::32-bit Example Execution::
main : write-file opened
main : write-config written
main : read-file opened
main : read-config written
main : read-config gotten
main : write-task created
main : read-task created
main : starting write-task
main : starting read-task

Built for Xenomai 2.6.4
Write task sends 26 chars every 1.00 s
Printing on message size modulus of 26
Baud Rate = 115200
fifo_depth written = 0, fifo_depth received = 0
rx timeout written = 4294967295, rx timeout received = 4294967295
event timeout written = 0, event timeout received = 0

rx.events=1  | rx.rx_pending=1 | r_t=1618404161709825071
Count=  26 bins=0 26 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404162709820540
Count=  52 bins=0 52 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404163709821237
Count=  78 bins=0 78 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404164709821910
Count= 104 bins=0 104 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404165709817391
Count= 130 bins=0 130 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404166709818064
Count= 156 bins=0 156 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404167709818773
Count= 182 bins=0 182 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446
Count= 208 bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
::64-bit Target Details::
Xenomai version: Xenomai/cobalt v3.1 -- #932fc81c4 (2021-03-06 09:12:44 +0100)
Linux delta 5.4.77-Cobalt-v6 #1 SMP PREEMPT Wed Apr 7 16:51:16 EDT 2021
x86_64 x86_64 x86_64 GNU/Linux
Kernel parameters: BOOT_IMAGE=/boot/vmlinuz-5.4.77-Cobalt-v6
root=UUID=147f0e74-99ca-4816-9e22-4c3f4f5e8c66 ro isolcpus=1
xenomai.supported_cpus=0x01 splash quiet 8250.nr_uarts=4
xenomai.smi=enabled fsck.mode=force vt.handoff=7
I-pipe release #2 detected  (retrieved from: https://www.xenomai.org/downloads/ipipe/v5.x/x86/ipipe-core-5.4.77-x86-2.patch)
Cobalt core 3.1 detected
Compiler: gcc version 9.3.0 (Ubuntu 9.3.0-10ubuntu2)
Build args: --prefix=/home/delta/kernel/xenomai-libs --with-core=cobalt
--enable-smp --enable-pshared --enable-debug=symbols
::64-bit Build::
gcc -o cross-link cross-link.c
-I/home/jbw/GitWorkTree/sandbox/Development/Cobalt/include/cobalt
-I/home/jbw/GitWorkTree/sandbox/Development/Cobalt/include -D_GNU_SOURCE
-D_REENTRANT -fasynchronous-unwind-tables -D__COBALT__
 -I/home/jbw/GitWorkTree/sandbox/Development/Cobalt/include/alchemy
 -D__COBALT_WRAP__ -Wl,--no-as-needed
 -Wl,@/home/jbw/GitWorkTree/sandbox/Development/Cobalt/lib/cobalt.wrappers
-Wl,@/home/jbw/GitWorkTree/sandbox/Development/Cobalt/lib/modechk.wrappers
-lalchemy -lcopperplate
/home/jbw/GitWorkTree/sandbox/Development/Cobalt/lib/xenomai/bootstrap.o
-Wl,--wrap=main
 -Wl,--dynamic-list=/home/jbw/GitWorkTree/sandbox/Development/Cobalt/lib/dynlist.ld
-L/home/jbw/GitWorkTree/sandbox/Development/Cobalt/lib -lcobalt -lmodechk
-lpthread -lrt
::64-bit Execution::
main : write-file opened
main : write-config written
main : read-file opened
main : read-config written
main : read-config gotten
main : write-task created
main : read-task created
main : starting write-task
main : starting read-task

Built for Xenomai 3.1
Write task sends 26 chars every 1.00 s
Printing on message size modulus of 26
Baud Rate = 115200
fifo_depth written = 0, fifo_depth received = 0
rx timeout written = 18446744073709551615, rx timeout received = 18446744073709551615
event timeout written = 0, event timeout received = 0

rx.events=1  | rx.rx_pending=2 | r_t=1618406760806831175
Count=   7 bins=0 0 1 0 6 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406761806831122
Count=  14 bins=0 0 2 0 12 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406762806833636
Count=  21 bins=0 0 3 0 18 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406763806825651
Count=  28 bins=0 0 4 0 24 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406764806828562
Count=  35 bins=0 0 5 0 30 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406765806828508
Count=  42 bins=0 0 6 0 36 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406766806829031
Count=  49 bins=0 0 7 0 42 0 0 0 0 0 0 0 0 0 0 0 0 0
rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954
Count=  56 bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0

PRIVACY NOTICE: The information contained in this e-mail, including any attachments, is confidential and intended only for the named recipient(s). Unauthorized use, disclosure, forwarding, or copying is strictly prohibited and may be unlawful. If you are not the intended recipient, please delete the e-mail and any attachments and notify us immediately by return e-mail.
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: cross-link.c
URL: <http://xenomai.org/pipermail/xenomai/attachments/20210420/690665c9/attachment.c>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: DetailsLessLineWrapping.txt
URL: <http://xenomai.org/pipermail/xenomai/attachments/20210420/690665c9/attachment.txt>

Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1

[Jan Kiszka]

On 20.04.21 16:45, Alan Gaglio via Xenomai wrote:
> I am in the process of upgrading from 32-bit/Xenomai 2.6.4/Ubuntu 14.04.4/
> Linux 3.16.7 to 64-bit/Xenomai 3.1/Ubuntu 20.04.1/Linux 5.4.77 and I'm
> experiencing an rtserial event difference in behavior. Our application
> depends on single-byte interrupts from rtserial ports, which we're
> not seeing despite having configured rtserial ports the same between our 2
> different image configurations that run on the same x86 hardware.
> Attached is a modified cross-link.c example that highlights this
> difference in behavior. Also included is relevant detail for each target,
> build, and sample program output.
> 
> My modified cross-link.c transmits 26 characters every 1 second and prints
> the number of RX_PEND events along with reception bins every 26 characters
> read by the receive thread. Reception bins show the number of bytes
> read per RX_PEND event [0-16,17+]. The total number of bytes
> processed equals the sum of all bins multiplied by the quantity they
> represent. For example, these snipped outputs (from the below greater
> details) were taken following a total of 208 bytes transmitted. In
> 2.6.4 we have 208 events * 1 byte = 208 bytes and in 3.1 we have
> 48 events * 4 bytes + 8 events * 2 bytes = 208 bytes. We expect/desire the
> second bin to be exclusively non-zero (2.6.4 output), indicating an RX_PEND
> event for each byte that arrives on the serial port.
> 
> 2.6.4 Output:
> rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446
> Count= 208 bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
> 3.1 Output:
> rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954
> Count=  56 bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0
> 
> I'm not sure where to take the next level of troubleshooting and am happy to
> provide additional detail, run tests, etc. The attached cross-link includes
> some preprocessor defines to modify program behaviors that I can explain if
> helpful. Details shown below are also attached with line wrapping removed
> for reference.
> 

Didn't dig through all the detailed information you provided yet, but
the first questions that come up for me would be

 - do interrupts for the UART arrive at the expected rate, or are they
   already delayed?

 - already tried to collect a system trace (ftrace event tracing) to
   gain an overview of what the application does when and what happens
   Xenomai-wise in the core (context switch, interrupts, etc.)?

If interpreting the trace is tricky, share it. Also taking tracing on
both 2.6 and 3.1 setups can help to find differences.

Jan

-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux

RE: RTSerial Difference in Behavior Between 2.6.4 & 3.1

[Alan Gaglio]

> From: Jan Kiszka <jan.kiszka@siemens.com>
> Sent: Wednesday, April 21, 2021 3:00 AM
> To: Alan Gaglio <AGaglio@jerviswebb.com>; xenomai@xenomai.org
> Subject: Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1
>
> On 20.04.21 16:45, Alan Gaglio via Xenomai wrote:
> > I am in the process of upgrading from 32-bit/Xenomai 2.6.4/Ubuntu
> > 14.04.4/ Linux 3.16.7 to 64-bit/Xenomai 3.1/Ubuntu 20.04.1/Linux
> > 5.4.77 and I'm experiencing an rtserial event difference in behavior.
> > Our application depends on single-byte interrupts from rtserial ports,
> > which we're not seeing despite having configured rtserial ports the
> > same between our 2 different image configurations that run on the same
> x86 hardware.
> > Attached is a modified cross-link.c example that highlights this
> > difference in behavior. Also included is relevant detail for each
> > target, build, and sample program output.
> >
> > My modified cross-link.c transmits 26 characters every 1 second and
> > prints the number of RX_PEND events along with reception bins every 26
> > characters read by the receive thread. Reception bins show the number
> > of bytes read per RX_PEND event [0-16,17+]. The total number of bytes
> > processed equals the sum of all bins multiplied by the quantity they
> > represent. For example, these snipped outputs (from the below greater
> > details) were taken following a total of 208 bytes transmitted. In
> > 2.6.4 we have 208 events * 1 byte = 208 bytes and in 3.1 we have
> > 48 events * 4 bytes + 8 events * 2 bytes = 208 bytes. We expect/desire
> > the second bin to be exclusively non-zero (2.6.4 output), indicating
> > an RX_PEND event for each byte that arrives on the serial port.
> >
> > 2.6.4 Output:
> > rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446 Count= 208
> > bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
> > 3.1 Output:
> > rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954 Count=  56
> > bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0
> >
> > I'm not sure where to take the next level of troubleshooting and am
> > happy to provide additional detail, run tests, etc. The attached
> > cross-link includes some preprocessor defines to modify program
> > behaviors that I can explain if helpful. Details shown below are also
> > attached with line wrapping removed for reference.
> >
>
> Didn't dig through all the detailed information you provided yet, but the first
> questions that come up for me would be
>
>  - do interrupts for the UART arrive at the expected rate, or are they
>    already delayed?
>
>  - already tried to collect a system trace (ftrace event tracing) to
>    gain an overview of what the application does when and what happens
>    Xenomai-wise in the core (context switch, interrupts, etc.)?
>
> If interpreting the trace is tricky, share it. Also taking tracing on both 2.6 and
> 3.1 setups can help to find differences.
>
> Jan
>
> --
> Siemens AG, T RDA IOT
> Corporate Competence Center Embedded Linux

Interpretation support is appreciated, attached are traces from both setups
frozen following reception of the first 26 characters by the receive thread.
For 26 byte transmission at 115200 baud and my configured serial settings,
minimum time from write-to-receive ought to be ~2256 us. I've reviewed
from the start of transmission (rt_16550_write calls around lines 7888 X2_6/
6229 X3_1) at a surface level. Both traces show the first interrupt following
rt_16550_write 2322 us from trace freeze, so I don't see a meaningful delay
in overall message transmission time.

In 2.6, I count a total of 28 rt_16550_interrupts, which corresponds well to
the number of single-character reads output by my test program. These were
generated at appropriate intervals of ~86 (2322/27) us intervals.

In 3.1, I count a total of 16 rt_16550_interrupts, which I'm having difficulty
making sense of. UART interrupts are not arriving at the expected rate but
instead in less frequent batches in roughly 4 character-time intervals.
The behavior seems like the FIFO depth of the UART is still 4 characters deep
despite having specified a FIFO depth 1 in rtser_config and having read back
the configured depth for confirmation.
PRIVACY NOTICE: The information contained in this e-mail, including any attachments, is confidential and intended only for the named recipient(s). Unauthorized use, disclosure, forwarding, or copying is strictly prohibited and may be unlawful. If you are not the intended recipient, please delete the e-mail and any attachments and notify us immediately by return e-mail.
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: X2_6_4_Freeze_After_26_Chars_Received.txt
URL: <http://xenomai.org/pipermail/xenomai/attachments/20210422/64222751/attachment.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: X3_1_Freeze_After_26_Chars_Received.txt
URL: <http://xenomai.org/pipermail/xenomai/attachments/20210422/64222751/attachment-0001.txt>

Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1

[Jan Kiszka]

On 22.04.21 20:52, Alan Gaglio wrote:
>> From: Jan Kiszka <jan.kiszka@siemens.com>
>> Sent: Wednesday, April 21, 2021 3:00 AM
>> To: Alan Gaglio <AGaglio@jerviswebb.com>; xenomai@xenomai.org
>> Subject: Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1
>>
>> On 20.04.21 16:45, Alan Gaglio via Xenomai wrote:
>>> I am in the process of upgrading from 32-bit/Xenomai 2.6.4/Ubuntu
>>> 14.04.4/ Linux 3.16.7 to 64-bit/Xenomai 3.1/Ubuntu 20.04.1/Linux
>>> 5.4.77 and I'm experiencing an rtserial event difference in behavior.
>>> Our application depends on single-byte interrupts from rtserial ports,
>>> which we're not seeing despite having configured rtserial ports the
>>> same between our 2 different image configurations that run on the same
>> x86 hardware.
>>> Attached is a modified cross-link.c example that highlights this
>>> difference in behavior. Also included is relevant detail for each
>>> target, build, and sample program output.
>>>
>>> My modified cross-link.c transmits 26 characters every 1 second and
>>> prints the number of RX_PEND events along with reception bins every 26
>>> characters read by the receive thread. Reception bins show the number
>>> of bytes read per RX_PEND event [0-16,17+]. The total number of bytes
>>> processed equals the sum of all bins multiplied by the quantity they
>>> represent. For example, these snipped outputs (from the below greater
>>> details) were taken following a total of 208 bytes transmitted. In
>>> 2.6.4 we have 208 events * 1 byte = 208 bytes and in 3.1 we have
>>> 48 events * 4 bytes + 8 events * 2 bytes = 208 bytes. We expect/desire
>>> the second bin to be exclusively non-zero (2.6.4 output), indicating
>>> an RX_PEND event for each byte that arrives on the serial port.
>>>
>>> 2.6.4 Output:
>>> rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446 Count= 208
>>> bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
>>> 3.1 Output:
>>> rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954 Count=  56
>>> bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0
>>>
>>> I'm not sure where to take the next level of troubleshooting and am
>>> happy to provide additional detail, run tests, etc. The attached
>>> cross-link includes some preprocessor defines to modify program
>>> behaviors that I can explain if helpful. Details shown below are also
>>> attached with line wrapping removed for reference.
>>>
>>
>> Didn't dig through all the detailed information you provided yet, but the first
>> questions that come up for me would be
>>
>>  - do interrupts for the UART arrive at the expected rate, or are they
>>    already delayed?
>>
>>  - already tried to collect a system trace (ftrace event tracing) to
>>    gain an overview of what the application does when and what happens
>>    Xenomai-wise in the core (context switch, interrupts, etc.)?
>>
>> If interpreting the trace is tricky, share it. Also taking tracing on both 2.6 and
>> 3.1 setups can help to find differences.
>>
>> Jan
>>
>> --
>> Siemens AG, T RDA IOT
>> Corporate Competence Center Embedded Linux
> 
> Interpretation support is appreciated, attached are traces from both setups
> frozen following reception of the first 26 characters by the receive thread.
> For 26 byte transmission at 115200 baud and my configured serial settings,
> minimum time from write-to-receive ought to be ~2256 us. I've reviewed
> from the start of transmission (rt_16550_write calls around lines 7888 X2_6/
> 6229 X3_1) at a surface level. Both traces show the first interrupt following
> rt_16550_write 2322 us from trace freeze, so I don't see a meaningful delay
> in overall message transmission time.
> 
> In 2.6, I count a total of 28 rt_16550_interrupts, which corresponds well to
> the number of single-character reads output by my test program. These were
> generated at appropriate intervals of ~86 (2322/27) us intervals.
> 
> In 3.1, I count a total of 16 rt_16550_interrupts, which I'm having difficulty
> making sense of. UART interrupts are not arriving at the expected rate but
> instead in less frequent batches in roughly 4 character-time intervals.
> The behavior seems like the FIFO depth of the UART is still 4 characters deep
> despite having specified a FIFO depth 1 in rtser_config and having read back
> the configured depth for confirmation.

That is pointing to the driver, and you should be able to validate
actual against desired registers settings. Already tried to instrument
(printk...) the driver(s) along the evaluation of RTSER_SET_FIFO_DEPTH
[1] and other manipulations of FCR [2]?

Jan

[1]
https://source.denx.de/Xenomai/xenomai/-/blob/stable/v3.1.x/kernel/drivers/serial/16550A.c#L344
[2]
https://source.denx.de/Xenomai/xenomai/-/blob/stable/v3.1.x/kernel/drivers/serial/16550A.c#L748

-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux

RE: RTSerial Difference in Behavior Between 2.6.4 & 3.1

[Alan Gaglio]

> -----Original Message-----
> From: Jan Kiszka <jan.kiszka@siemens.com>
> Sent: Friday, April 23, 2021 1:52 AM
> To: Alan Gaglio <AGaglio@jerviswebb.com>; xenomai@xenomai.org
> Subject: Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1
>
> On 22.04.21 20:52, Alan Gaglio wrote:
> >> From: Jan Kiszka <jan.kiszka@siemens.com>
> >> Sent: Wednesday, April 21, 2021 3:00 AM
> >> To: Alan Gaglio <AGaglio@jerviswebb.com>; xenomai@xenomai.org
> >> Subject: Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1
> >>
> >> On 20.04.21 16:45, Alan Gaglio via Xenomai wrote:
> >>> I am in the process of upgrading from 32-bit/Xenomai 2.6.4/Ubuntu
> >>> 14.04.4/ Linux 3.16.7 to 64-bit/Xenomai 3.1/Ubuntu 20.04.1/Linux
> >>> 5.4.77 and I'm experiencing an rtserial event difference in behavior.
> >>> Our application depends on single-byte interrupts from rtserial
> >>> ports, which we're not seeing despite having configured rtserial
> >>> ports the same between our 2 different image configurations that run
> >>> on the same
> >> x86 hardware.
> >>> Attached is a modified cross-link.c example that highlights this
> >>> difference in behavior. Also included is relevant detail for each
> >>> target, build, and sample program output.
> >>>
> >>> My modified cross-link.c transmits 26 characters every 1 second and
> >>> prints the number of RX_PEND events along with reception bins every
> >>> 26 characters read by the receive thread. Reception bins show the
> >>> number of bytes read per RX_PEND event [0-16,17+]. The total number
> >>> of bytes processed equals the sum of all bins multiplied by the
> >>> quantity they represent. For example, these snipped outputs (from
> >>> the below greater
> >>> details) were taken following a total of 208 bytes transmitted. In
> >>> 2.6.4 we have 208 events * 1 byte = 208 bytes and in 3.1 we have
> >>> 48 events * 4 bytes + 8 events * 2 bytes = 208 bytes. We
> >>> expect/desire the second bin to be exclusively non-zero (2.6.4
> >>> output), indicating an RX_PEND event for each byte that arrives on the
> serial port.
> >>>
> >>> 2.6.4 Output:
> >>> rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446 Count= 208
> >>> bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
> >>> 3.1 Output:
> >>> rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954 Count=  56
> >>> bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0
> >>>
> >>> I'm not sure where to take the next level of troubleshooting and am
> >>> happy to provide additional detail, run tests, etc. The attached
> >>> cross-link includes some preprocessor defines to modify program
> >>> behaviors that I can explain if helpful. Details shown below are
> >>> also attached with line wrapping removed for reference.
> >>>
> >>
> >> Didn't dig through all the detailed information you provided yet, but
> >> the first questions that come up for me would be
> >>
> >>  - do interrupts for the UART arrive at the expected rate, or are they
> >>    already delayed?
> >>
> >>  - already tried to collect a system trace (ftrace event tracing) to
> >>    gain an overview of what the application does when and what happens
> >>    Xenomai-wise in the core (context switch, interrupts, etc.)?
> >>
> >> If interpreting the trace is tricky, share it. Also taking tracing on
> >> both 2.6 and
> >> 3.1 setups can help to find differences.
> >>
> >> Jan
> >>
> >> --
> >> Siemens AG, T RDA IOT
> >> Corporate Competence Center Embedded Linux
> >
> > Interpretation support is appreciated, attached are traces from both
> > setups frozen following reception of the first 26 characters by the receive
> thread.
> > For 26 byte transmission at 115200 baud and my configured serial
> > settings, minimum time from write-to-receive ought to be ~2256 us.
> > I've reviewed from the start of transmission (rt_16550_write calls
> > around lines 7888 X2_6/
> > 6229 X3_1) at a surface level. Both traces show the first interrupt
> > following rt_16550_write 2322 us from trace freeze, so I don't see a
> > meaningful delay in overall message transmission time.
> >
> > In 2.6, I count a total of 28 rt_16550_interrupts, which corresponds
> > well to the number of single-character reads output by my test
> > program. These were generated at appropriate intervals of ~86 (2322/27)
> us intervals.
> >
> > In 3.1, I count a total of 16 rt_16550_interrupts, which I'm having
> > difficulty making sense of. UART interrupts are not arriving at the
> > expected rate but instead in less frequent batches in roughly 4 character-
> time intervals.
> > The behavior seems like the FIFO depth of the UART is still 4
> > characters deep despite having specified a FIFO depth 1 in
> > rtser_config and having read back the configured depth for confirmation.
>
> That is pointing to the driver, and you should be able to validate actual
> against desired registers settings. Already tried to instrument
> (printk...) the driver(s) along the evaluation of RTSER_SET_FIFO_DEPTH [1]
> and other manipulations of FCR [2]?
>
> Jan
>
> [1]
> https://source.denx.de/Xenomai/xenomai/-
> /blob/stable/v3.1.x/kernel/drivers/serial/16550A.c#L344
> [2]
> https://source.denx.de/Xenomai/xenomai/-
> /blob/stable/v3.1.x/kernel/drivers/serial/16550A.c#L748
>
> --
> Siemens AG, T RDA IOT
> Corporate Competence Center Embedded Linux

Thank you for the helpful suggestions Jan, I finally got back into the issue
and have it resolved. Our hardware provides UARTs via a Fintek F81866A
Super IO chip that has some extended configuration registers outside the
scope of the 16550 driver. A kernel patch from October 27th, 2016
to the 8250_fintek driver initialize the UART's FIFO Select Registers to
have a FIFO threshold multiplier (RXFTHR_MODE) of 4x the threshold set by
the standard FIFO Control Register in the 16550 driver [1]. Our image loads
the 8250 driver at boot and unloads it upon application execution. As a
result, the extended configuration settings persist in our F81866A and
cause the unexpected interrupt behavior witnessed.

I've confirmed that setting RXFTHR_MODE to a multiplier of 1x
generates single character interrupts in our 64b/X3.1/U20.04/L5.4.77
image just like our 32b/X2.6/U14.04/L3.16.7 image. We will make a
change in our application to ensure proper UART configuration for this
device going forward. Included is a link to the commit and sample program
output showing the change to RXFTHR_MODE prior to task execution
for reference.

-Alan

[1] https://github.com/torvalds/linux/commit/c2236facaec9e4bdd3b350a6a54d29440a234a04

3.1 Output:
  Init UART 1 FIFO_CTRL = 23
  Set UART 1 FIFO_CTRL = 3
  main : read-config written
  main : read-config gotten
  main : write-task created
  main : read-task created
  main : starting write-task
  main : starting read-task

  Built for Xenomai 3.1
  Write task sends 26 chars every 1.00 s
  Printing on message size modulus of 26
  Baud Rate = 115200
  Fifo_depth written = 0, fifo_depth received = 0
  event timeout written = 0, event timeout received = 0
  rx.events=1  | rx.rx_pending=1 | r_t=1620155694902635954
  Count=  26 bins=0 26 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
  rx.events=1  | rx.rx_pending=1 | r_t=1620155695902633523
  Count=  52 bins=0 52 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0


PRIVACY NOTICE: The information contained in this e-mail, including any attachments, is confidential and intended only for the named recipient(s). Unauthorized use, disclosure, forwarding, or copying is strictly prohibited and may be unlawful. If you are not the intended recipient, please delete the e-mail and any attachments and notify us immediately by return e-mail.

Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1

[Jan Kiszka]

On 04.05.21 22:40, Alan Gaglio wrote:
>> -----Original Message-----
>> From: Jan Kiszka <jan.kiszka@siemens.com>
>> Sent: Friday, April 23, 2021 1:52 AM
>> To: Alan Gaglio <AGaglio@jerviswebb.com>; xenomai@xenomai.org
>> Subject: Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1
>>
>> On 22.04.21 20:52, Alan Gaglio wrote:
>>>> From: Jan Kiszka <jan.kiszka@siemens.com>
>>>> Sent: Wednesday, April 21, 2021 3:00 AM
>>>> To: Alan Gaglio <AGaglio@jerviswebb.com>; xenomai@xenomai.org
>>>> Subject: Re: RTSerial Difference in Behavior Between 2.6.4 & 3.1
>>>>
>>>> On 20.04.21 16:45, Alan Gaglio via Xenomai wrote:
>>>>> I am in the process of upgrading from 32-bit/Xenomai 2.6.4/Ubuntu
>>>>> 14.04.4/ Linux 3.16.7 to 64-bit/Xenomai 3.1/Ubuntu 20.04.1/Linux
>>>>> 5.4.77 and I'm experiencing an rtserial event difference in behavior.
>>>>> Our application depends on single-byte interrupts from rtserial
>>>>> ports, which we're not seeing despite having configured rtserial
>>>>> ports the same between our 2 different image configurations that run
>>>>> on the same
>>>> x86 hardware.
>>>>> Attached is a modified cross-link.c example that highlights this
>>>>> difference in behavior. Also included is relevant detail for each
>>>>> target, build, and sample program output.
>>>>>
>>>>> My modified cross-link.c transmits 26 characters every 1 second and
>>>>> prints the number of RX_PEND events along with reception bins every
>>>>> 26 characters read by the receive thread. Reception bins show the
>>>>> number of bytes read per RX_PEND event [0-16,17+]. The total number
>>>>> of bytes processed equals the sum of all bins multiplied by the
>>>>> quantity they represent. For example, these snipped outputs (from
>>>>> the below greater
>>>>> details) were taken following a total of 208 bytes transmitted. In
>>>>> 2.6.4 we have 208 events * 1 byte = 208 bytes and in 3.1 we have
>>>>> 48 events * 4 bytes + 8 events * 2 bytes = 208 bytes. We
>>>>> expect/desire the second bin to be exclusively non-zero (2.6.4
>>>>> output), indicating an RX_PEND event for each byte that arrives on the
>> serial port.
>>>>>
>>>>> 2.6.4 Output:
>>>>> rx.events=1  | rx.rx_pending=1 | r_t=1618404168709819446 Count= 208
>>>>> bins=0 208 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
>>>>> 3.1 Output:
>>>>> rx.events=1  | rx.rx_pending=2 | r_t=1618406767806828954 Count=  56
>>>>> bins=0 0 8 0 48 0 0 0 0 0 0 0 0 0 0 0 0 0
>>>>>
>>>>> I'm not sure where to take the next level of troubleshooting and am
>>>>> happy to provide additional detail, run tests, etc. The attached
>>>>> cross-link includes some preprocessor defines to modify program
>>>>> behaviors that I can explain if helpful. Details shown below are
>>>>> also attached with line wrapping removed for reference.
>>>>>
>>>>
>>>> Didn't dig through all the detailed information you provided yet, but
>>>> the first questions that come up for me would be
>>>>
>>>>  - do interrupts for the UART arrive at the expected rate, or are they
>>>>    already delayed?
>>>>
>>>>  - already tried to collect a system trace (ftrace event tracing) to
>>>>    gain an overview of what the application does when and what happens
>>>>    Xenomai-wise in the core (context switch, interrupts, etc.)?
>>>>
>>>> If interpreting the trace is tricky, share it. Also taking tracing on
>>>> both 2.6 and
>>>> 3.1 setups can help to find differences.
>>>>
>>>> Jan
>>>>
>>>> --
>>>> Siemens AG, T RDA IOT
>>>> Corporate Competence Center Embedded Linux
>>>
>>> Interpretation support is appreciated, attached are traces from both
>>> setups frozen following reception of the first 26 characters by the receive
>> thread.
>>> For 26 byte transmission at 115200 baud and my configured serial
>>> settings, minimum time from write-to-receive ought to be ~2256 us.
>>> I've reviewed from the start of transmission (rt_16550_write calls
>>> around lines 7888 X2_6/
>>> 6229 X3_1) at a surface level. Both traces show the first interrupt
>>> following rt_16550_write 2322 us from trace freeze, so I don't see a
>>> meaningful delay in overall message transmission time.
>>>
>>> In 2.6, I count a total of 28 rt_16550_interrupts, which corresponds
>>> well to the number of single-character reads output by my test
>>> program. These were generated at appropriate intervals of ~86 (2322/27)
>> us intervals.
>>>
>>> In 3.1, I count a total of 16 rt_16550_interrupts, which I'm having
>>> difficulty making sense of. UART interrupts are not arriving at the
>>> expected rate but instead in less frequent batches in roughly 4 character-
>> time intervals.
>>> The behavior seems like the FIFO depth of the UART is still 4
>>> characters deep despite having specified a FIFO depth 1 in
>>> rtser_config and having read back the configured depth for confirmation.
>>
>> That is pointing to the driver, and you should be able to validate actual
>> against desired registers settings. Already tried to instrument
>> (printk...) the driver(s) along the evaluation of RTSER_SET_FIFO_DEPTH [1]
>> and other manipulations of FCR [2]?
>>
>> Jan
>>
>> [1]
>> https://source.denx.de/Xenomai/xenomai/-
>> /blob/stable/v3.1.x/kernel/drivers/serial/16550A.c#L344
>> [2]
>> https://source.denx.de/Xenomai/xenomai/-
>> /blob/stable/v3.1.x/kernel/drivers/serial/16550A.c#L748
>>
>> --
>> Siemens AG, T RDA IOT
>> Corporate Competence Center Embedded Linux
> 
> Thank you for the helpful suggestions Jan, I finally got back into the issue
> and have it resolved. Our hardware provides UARTs via a Fintek F81866A
> Super IO chip that has some extended configuration registers outside the
> scope of the 16550 driver. A kernel patch from October 27th, 2016
> to the 8250_fintek driver initialize the UART's FIFO Select Registers to
> have a FIFO threshold multiplier (RXFTHR_MODE) of 4x the threshold set by
> the standard FIFO Control Register in the 16550 driver [1]. Our image loads
> the 8250 driver at boot and unloads it upon application execution. As a
> result, the extended configuration settings persist in our F81866A and
> cause the unexpected interrupt behavior witnessed.
> 
> I've confirmed that setting RXFTHR_MODE to a multiplier of 1x
> generates single character interrupts in our 64b/X3.1/U20.04/L5.4.77
> image just like our 32b/X2.6/U14.04/L3.16.7 image. We will make a
> change in our application to ensure proper UART configuration for this
> device going forward. Included is a link to the commit and sample program
> output showing the change to RXFTHR_MODE prior to task execution
> for reference.
> 

OK, great to hear you solved it! If there is anything that could also be
done in the rt_16550A driver, please share a patch or suggest a pattern.

Jan

-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux