Re: [PATCH v2 1/1] MdeModulePkg: Put USB DEBUGs that occur for bulk timeouts under VERBOSE

["Wu, Hao A" <hao.a.wu@intel.com>]

Reviewed-by: Hao A Wu <hao.a.wu@intel.com>
Will wait a couple of days before merging to see if comments from other reviewers.

Best Regards,
Hao Wu

> -----Original Message-----
> From: Rebecca Cran <rebecca@quicinc.com>
> Sent: Tuesday, December 6, 2022 10:31 PM
> To: devel@edk2.groups.io; Gao, Liming <gaoliming@byosoft.com.cn>; Ni,
> Ray <ray.ni@intel.com>; Wang, Jian J <jian.j.wang@intel.com>; Wu, Hao A
> <hao.a.wu@intel.com>
> Cc: Rebecca Cran <rebecca@quicinc.com>
> Subject: [PATCH v2 1/1] MdeModulePkg: Put USB DEBUGs that occur for bulk
> timeouts under VERBOSE
> 
> With the pending commit of UsbNetworkPkg, it will become common for
> UsbBulkTransfer calls to timeout, given that the drivers are called from
> MnpSystemPoll every MNP_SYS_POLL_INTERVAL milliseconds: the drivers
> check for network packets by calling UsbBulkTransfer with a timeout of
> 1ms.
> 
> Avoid console spam by moving DEBUG messages that occur each time a bulk
> transfer request times out from DEBUG_ERROR to DEBUG_VERBOSE, for
> both
> EHCI and XHCI drivers.
> 
> Signed-off-by: Rebecca Cran <rebecca@quicinc.com>
> ---
>  MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c      | 9 ++++++++-
>  MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c | 2 +-
>  MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c      | 9 ++++++++-
>  MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c | 6 +++---
>  4 files changed, 20 insertions(+), 6 deletions(-)
> 
> diff --git a/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> b/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> index 0b7270f4e930..e903593b0198 100644
> --- a/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> +++ b/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> @@ -848,6 +848,7 @@ EhcBulkTransfer (
>    URB          *Urb;
>    EFI_TPL      OldTpl;
>    EFI_STATUS   Status;
> +  UINTN        DebugErrorLevel;
> 
>    //
>    // Validate the parameters
> @@ -932,7 +933,13 @@ EhcBulkTransfer (
>    gBS->RestoreTPL (OldTpl);
> 
>    if (EFI_ERROR (Status)) {
> -    DEBUG ((DEBUG_ERROR, "EhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
> +    if (Status == EFI_TIMEOUT) {
> +      DebugErrorLevel = DEBUG_VERBOSE;
> +    } else {
> +      DebugErrorLevel = DEBUG_ERROR;
> +    }
> +
> +    DEBUG ((DebugErrorLevel, "EhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
>    }
> 
>    return Status;
> diff --git a/MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c
> b/MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c
> index 5da26afbe120..6967aabceb78 100644
> --- a/MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c
> +++ b/MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c
> @@ -702,7 +702,7 @@ EhcExecTransfer (
>    }
> 
>    if (!Finished) {
> -    DEBUG ((DEBUG_ERROR, "EhcExecTransfer: transfer not finished
> in %dms\n", (UINT32)TimeOut));
> +    DEBUG ((DEBUG_VERBOSE, "EhcExecTransfer: transfer not finished
> in %dms\n", (UINT32)TimeOut));
>      EhcDumpQh (Urb->Qh, NULL, FALSE);
> 
>      Status = EFI_TIMEOUT;
> diff --git a/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
> b/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
> index c05431ff30ec..15fb49f28fa0 100644
> --- a/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
> +++ b/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
> @@ -1242,6 +1242,7 @@ XhcBulkTransfer (
>    UINT8              SlotId;
>    EFI_STATUS         Status;
>    EFI_TPL            OldTpl;
> +  UINTN              DebugErrorLevel;
> 
>    //
>    // Validate the parameters
> @@ -1304,7 +1305,13 @@ XhcBulkTransfer (
> 
>  ON_EXIT:
>    if (EFI_ERROR (Status)) {
> -    DEBUG ((DEBUG_ERROR, "XhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
> +    if (Status == EFI_TIMEOUT) {
> +      DebugErrorLevel = DEBUG_VERBOSE;
> +    } else {
> +      DebugErrorLevel = DEBUG_ERROR;
> +    }
> +
> +    DEBUG ((DebugErrorLevel, "XhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
>    }
> 
>    gBS->RestoreTPL (OldTpl);
> diff --git a/MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c
> b/MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c
> index 13b0400e83d7..13247f7b0dfc 100644
> --- a/MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c
> +++ b/MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c
> @@ -734,7 +734,7 @@ XhcDequeueTrbFromEndpoint (
>    Dci = XhcEndpointToDci (Urb->Ep.EpAddr, (UINT8)(Urb->Ep.Direction));
>    ASSERT (Dci < 32);
> 
> -  DEBUG ((DEBUG_INFO, "Stop Slot = %x,Dci = %x\n", SlotId, Dci));
> +  DEBUG ((DEBUG_VERBOSE, "Stop Slot = %x,Dci = %x\n", SlotId, Dci));
> 
>    //
>    // 1) Send Stop endpoint command to stop xHC from executing of the TDs
> on the endpoint
> @@ -3376,7 +3376,7 @@ XhcStopEndpoint (
>    EVT_TRB_COMMAND_COMPLETION  *EvtTrb;
>    CMD_TRB_STOP_ENDPOINT       CmdTrbStopED;
> 
> -  DEBUG ((DEBUG_INFO, "XhcStopEndpoint: Slot = 0x%x, Dci = 0x%x\n",
> SlotId, Dci));
> +  DEBUG ((DEBUG_VERBOSE, "XhcStopEndpoint: Slot = 0x%x, Dci = 0x%x\n",
> SlotId, Dci));
> 
>    //
>    // When XhcCheckUrbResult waits for the Stop_Endpoint completion, it
> also checks
> @@ -3497,7 +3497,7 @@ XhcSetTrDequeuePointer (
>    CMD_SET_TR_DEQ_POINTER      CmdSetTRDeq;
>    EFI_PHYSICAL_ADDRESS        PhyAddr;
> 
> -  DEBUG ((DEBUG_INFO, "XhcSetTrDequeuePointer: Slot = 0x%x, Dci = 0x%x,
> Urb = 0x%x\n", SlotId, Dci, Urb));
> +  DEBUG ((DEBUG_VERBOSE, "XhcSetTrDequeuePointer: Slot = 0x%x, Dci =
> 0x%x, Urb = 0x%x\n", SlotId, Dci, Urb));
> 
>    //
>    // Send stop endpoint command to transit Endpoint from running to stop
> state
> --
> 2.30.2