Re: [PATCH] MdeModulePkg SerialDxe: Process timeout consistently in SerialRead

[Laszlo Ersek <lersek@redhat.com>]

Hi Star,

On 08/04/17 10:29, Star Zeng wrote:
> https://lists.01.org/pipermail/edk2-devel/2017-July/012385.html
> reported the timeout processing in SerialRead is not consistent.
>
> Since SerialPortPoll only checks the status of serial port and
> returns immediately, and SerialPortRead does not really implement
> a time out mechanism and will always wait for enough input,
> it will cause below results:
> 1. If there is no serial input at all, this interface will return
> timeout immediately without any waiting;
> 2. If there is A characters in serial port FIFO, and caller requires
> A+1 characters, it will wait until a new input is coming and timeout
> will not really occur.
>
> This patch is to update SerialRead() to check SerialPortPoll() and
> read data through SerialPortRead() one byte by one byte, and check
> timeout against mSerialIoMode.Timeout if no input.
>
> Cc: Heyi Guo <heyi.guo@linaro.org>
> Cc: Ruiyu Ni <ruiyu.ni@intel.com>
> Cc: Laszlo Ersek <lersek@redhat.com>
> Contributed-under: TianoCore Contribution Agreement 1.0
> Signed-off-by: Star Zeng <star.zeng@intel.com>
> ---
>  MdeModulePkg/Universal/SerialDxe/SerialIo.c | 18 ++++++++++++++++--
>  1 file changed, 16 insertions(+), 2 deletions(-)
>
> diff --git a/MdeModulePkg/Universal/SerialDxe/SerialIo.c b/MdeModulePkg/Universal/SerialDxe/SerialIo.c
> index d2383e56dd8f..43d33dba0c2a 100644
> --- a/MdeModulePkg/Universal/SerialDxe/SerialIo.c
> +++ b/MdeModulePkg/Universal/SerialDxe/SerialIo.c
> @@ -465,11 +465,25 @@ SerialRead (
>    )
>  {
>    UINTN Count;
> +  UINTN TimeOut;
>
>    Count = 0;
>
> -  if (SerialPortPoll ()) {
> -    Count = SerialPortRead (Buffer, *BufferSize);
> +  while (Count < *BufferSize) {
> +    TimeOut = 0;
> +    while (TimeOut < mSerialIoMode.Timeout) {
> +      if (SerialPortPoll ()) {
> +        break;
> +      }
> +      gBS->Stall (10);
> +      TimeOut += 10;
> +    }
> +    if (TimeOut >= mSerialIoMode.Timeout) {
> +      break;
> +    }
> +    SerialPortRead (Buffer, 1);
> +    Count++;
> +    Buffer = (VOID *) ((UINT8 *) Buffer + 1);
>    }
>
>    if (Count != *BufferSize) {
>

This patch breaks the ArmVirtQemu platform's boot process -- it seems to
fall into an infinite loop. I guess the above loop(s) never complete?

If I revert this patch on top of current master (af0364f01e8c,
"Nt32/PlatformBootManagerLib: Enable STD_ERROR on all consoles",
2017-08-14), then ArmVirtQemu boots fine.

I found this commit with bisection:

> 4cf3f37c87ba1f9d58072444bd735e40e4779e70 is the first bad commit
> commit 4cf3f37c87ba1f9d58072444bd735e40e4779e70
> Author: Star Zeng <star.zeng@intel.com>
> Date:   Tue Jul 18 16:32:16 2017 +0800
>
>     MdeModulePkg SerialDxe: Process timeout consistently in SerialRead
>
>     https://lists.01.org/pipermail/edk2-devel/2017-July/012385.html
>     reported the timeout processing in SerialRead is not consistent.
>
>     Since SerialPortPoll only checks the status of serial port and
>     returns immediately, and SerialPortRead does not really implement
>     a time out mechanism and will always wait for enough input,
>     it will cause below results:
>     1. If there is no serial input at all, this interface will return
>     timeout immediately without any waiting;
>     2. If there is A characters in serial port FIFO, and caller requires
>     A+1 characters, it will wait until a new input is coming and timeout
>     will not really occur.
>
>     This patch is to update SerialRead() to check SerialPortPoll() and
>     read data through SerialPortRead() one byte by one byte, and check
>     timeout against mSerialIoMode.Timeout if no input.
>
>     Cc: Heyi Guo <heyi.guo@linaro.org>
>     Cc: Ruiyu Ni <ruiyu.ni@intel.com>
>     Cc: Laszlo Ersek <lersek@redhat.com>
>     Contributed-under: TianoCore Contribution Agreement 1.0
>     Signed-off-by: Star Zeng <star.zeng@intel.com>
>     Reviewed-by: Ruiyu Ni <ruiyu.ni@intel.com>
>
> :040000 040000 aaa8b75d378ec613b828db938c36a16723583906 d034044918d7f5b8d30783e0a9eccdf3cf21e5c5 M      MdeModulePkg

Bisection log:

> git bisect start
> # bad: [af0364f01e8cac95afad01437f13beef90f6640b] Nt32/PlatformBootManagerLib: Enable STD_ERROR on all consoles
> git bisect bad af0364f01e8cac95afad01437f13beef90f6640b
> # good: [c325e41585e374d40fb36b434e61a1ab0fca5b1c] MdeModulePkg: Fix coding style issues
> git bisect good c325e41585e374d40fb36b434e61a1ab0fca5b1c
> # good: [636cda51903b4b28e1c9b099c4f22a84e61b09da] OvmfPkg/OvmfPkg.fdf.inc: extract VARS_LIVE_SIZE and VARS_SPARE_SIZE macros
> git bisect good 636cda51903b4b28e1c9b099c4f22a84e61b09da
> # good: [997b2c543751cb4a3473270c1a7016ade311f01b] BaseTools/GenCrc32: Fix a bug to hand empty file for decode
> git bisect good 997b2c543751cb4a3473270c1a7016ade311f01b
> # good: [f1658838c267723139711c0b15d98a74980ae4c5] OvmfPkg/IoMmuDxe: abort harder on memory encryption mask failures
> git bisect good f1658838c267723139711c0b15d98a74980ae4c5
> # bad: [9458afa33728e64049d465f052b2c5c3ca3e881c] IntelFrameworkModulePkg: Fix Xcode 9 Beta treating 32-bit left shift as undefined
> git bisect bad 9458afa33728e64049d465f052b2c5c3ca3e881c
> # good: [6e414300b5f19d3045a0d21ad90ac2fe965478a5] EmbeddedPkg/AndroidFastboot: split android boot header
> git bisect good 6e414300b5f19d3045a0d21ad90ac2fe965478a5
> # bad: [416d48f755518fd1d202b97be2e9944df6e8f0d4] ShellPkg/drivers: Show Image Name in non-SFO mode
> git bisect bad 416d48f755518fd1d202b97be2e9944df6e8f0d4
> # bad: [2913ebb2b550f50a14f105e26995dd095e627ba4] NetworkPkg/HttpBootDxe: Refine the coding style.
> git bisect bad 2913ebb2b550f50a14f105e26995dd095e627ba4
> # bad: [9e2a8e928995c3b1bb664b73fd59785055c6b5f6] OvmfPkg/AcpiPlatformDxe: short-circuit the transfer of an empty S3_CONTEXT
> git bisect bad 9e2a8e928995c3b1bb664b73fd59785055c6b5f6
> # bad: [4cf3f37c87ba1f9d58072444bd735e40e4779e70] MdeModulePkg SerialDxe: Process timeout consistently in SerialRead
> git bisect bad 4cf3f37c87ba1f9d58072444bd735e40e4779e70
> # first bad commit: [4cf3f37c87ba1f9d58072444bd735e40e4779e70] MdeModulePkg SerialDxe: Process timeout consistently in SerialRead

In retrospect, I see that you asked me for feedback in the original
discussion, at the following URL:

  https://lists.01.org/pipermail/edk2-devel/2017-July/012406.html

Unfortunately, this was on July 18th, and I was on vacation then. (I
think I configured my email account to send an automated out-of-office
reply.)

Looking at the patch now, one idea I have is to keep the time running
across all bytes read; that is, use mSerialIoMode.Timeout as a global
timeout for the entire SerialRead() call.

Unfortunately, the UEFI-2.7 spec defines the "SERIAL_IO_MODE.Timeout"
field, and the Timeout parameter of
EFI_SERIAL_IO_PROTOCOL.SetAttributes(), inconsistently with each other.
First it says (about the field):

  Timeout  If applicable, the number of microseconds to wait before
           timing out a Read or Write operation.

(This is compatible with my idea.)

But then it says (in the general description, and about the
SetAttributes() parameter):

  The default attributes for all UART-style serial device interfaces
  are: [...] a 1,000,000 microsecond timeout *per character* [...]

  Timeout  The requested time out *for a single character* in
           microseconds. This timeout applies to both the transmit and
           receive side of the interface. A Timeout value of 0 will use
           the device's default time out value.

(Emphases mine.)

... I added some debug messages to the loops, and the first invocation
of the function seems to hang with the following parameters:

> SerialRead: BufferSize=1 mSerialIoMode.Timeout=1000000

That is, the caller wants to read a single character (which is not
arriving). The timeout is the default 1 second. However, the wait takes
much-much longer than 1 second (it appears to be infinite). It seems
that gBS->Stall(10) takes much longer than 10 microseconds. According to
the UEFI spec,

  The Stall() function stalls execution on the processor for at least
  the requested number of microseconds. [...]

So Stall() is allowed to wait longer (possibly a lot longer) -- I guess
it depends on some timer's resolution.

I have another idea related to this -- let me research it a bit later. I
might post some patches.

Thanks
Laszlo