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

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

[Rebecca Cran]

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      | 2 +-
 MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c | 2 +-
 MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c      | 2 +-
 MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c | 6 +++---
 4 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c b/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
index 0b7270f4e930..4f1d990c8bf1 100644
--- a/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
+++ b/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
@@ -932,7 +932,7 @@ EhcBulkTransfer (
   gBS->RestoreTPL (OldTpl);
 
   if (EFI_ERROR (Status)) {
-    DEBUG ((DEBUG_ERROR, "EhcBulkTransfer: error - %r, transfer - %x\n", Status, *TransferResult));
+    DEBUG ((DEBUG_VERBOSE, "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..e0347970c9ad 100644
--- a/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
+++ b/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
@@ -1304,7 +1304,7 @@ XhcBulkTransfer (
 
 ON_EXIT:
   if (EFI_ERROR (Status)) {
-    DEBUG ((DEBUG_ERROR, "XhcBulkTransfer: error - %r, transfer - %x\n", Status, *TransferResult));
+    DEBUG ((DEBUG_VERBOSE, "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

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

[Wu, Hao A]

Sorry for a question.

For the changes in EhcBulkTransfer() and XhcBulkTransfer(), is it feasible
to distinguish timeout cases with other error cases and only adjust
timeout related messages to VERBOSE level?

Best Regards,
Hao Wu

> -----Original Message-----
> From: Rebecca Cran <rebecca@quicinc.com>
> Sent: Friday, December 2, 2022 5:00 AM
> To: devel@edk2.groups.io; Wang, Jian J <jian.j.wang@intel.com>; Gao, Liming
> <gaoliming@byosoft.com.cn>; Wu, Hao A <hao.a.wu@intel.com>; Ni, Ray
> <ray.ni@intel.com>
> Cc: Rebecca Cran <rebecca@quicinc.com>
> Subject: [PATCH 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      | 2 +-
>  MdeModulePkg/Bus/Pci/EhciDxe/EhciSched.c | 2 +-
>  MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c      | 2 +-
>  MdeModulePkg/Bus/Pci/XhciDxe/XhciSched.c | 6 +++---
>  4 files changed, 6 insertions(+), 6 deletions(-)
> 
> diff --git a/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> b/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> index 0b7270f4e930..4f1d990c8bf1 100644
> --- a/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> +++ b/MdeModulePkg/Bus/Pci/EhciDxe/Ehci.c
> @@ -932,7 +932,7 @@ EhcBulkTransfer (
>    gBS->RestoreTPL (OldTpl);
> 
>    if (EFI_ERROR (Status)) {
> -    DEBUG ((DEBUG_ERROR, "EhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
> +    DEBUG ((DEBUG_VERBOSE, "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..e0347970c9ad 100644
> --- a/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
> +++ b/MdeModulePkg/Bus/Pci/XhciDxe/Xhci.c
> @@ -1304,7 +1304,7 @@ XhcBulkTransfer (
> 
>  ON_EXIT:
>    if (EFI_ERROR (Status)) {
> -    DEBUG ((DEBUG_ERROR, "XhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
> +    DEBUG ((DEBUG_VERBOSE, "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

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

[Rebecca Cran]

On 12/1/22 18:26, Wu, Hao A wrote:
> Sorry for a question.
> 
> For the changes in EhcBulkTransfer() and XhcBulkTransfer(), is it feasible
> to distinguish timeout cases with other error cases and only adjust
> timeout related messages to VERBOSE level?


No problem!
Something like this?

   if (EFI_ERROR (Status)) {
     if (Status == EFI_TIMEOUT) {
       DebugErrorLevel = DEBUG_VERBOSE;
     } else {
       DebugErrorLevel = DEBUG_ERROR;
     }

     DEBUG ((DebugErrorLevel, "XhcBulkTransfer: error - %r, transfer - 
%x\n", Status, *TransferResult));
   }

I'll send out a v2 patch.

-- 
Rebecca Cran

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

[Wu, Hao A]

> -----Original Message-----
> From: devel@edk2.groups.io <devel@edk2.groups.io> On Behalf Of Rebecca
> Cran
> Sent: Friday, December 2, 2022 11:38 PM
> To: Wu, Hao A <hao.a.wu@intel.com>; devel@edk2.groups.io; Wang, Jian J
> <jian.j.wang@intel.com>; Gao, Liming <gaoliming@byosoft.com.cn>; Ni, Ray
> <ray.ni@intel.com>
> Subject: Re: [edk2-devel] [PATCH 1/1] MdeModulePkg: Put USB DEBUGs that
> occur for bulk timeouts under VERBOSE
> 
> On 12/1/22 18:26, Wu, Hao A wrote:
> > Sorry for a question.
> >
> > For the changes in EhcBulkTransfer() and XhcBulkTransfer(), is it
> > feasible to distinguish timeout cases with other error cases and only
> > adjust timeout related messages to VERBOSE level?
> 
> 
> No problem!
> Something like this?
> 
>    if (EFI_ERROR (Status)) {
>      if (Status == EFI_TIMEOUT) {
>        DebugErrorLevel = DEBUG_VERBOSE;
>      } else {
>        DebugErrorLevel = DEBUG_ERROR;
>      }
> 
>      DEBUG ((DebugErrorLevel, "XhcBulkTransfer: error - %r, transfer - %x\n",
> Status, *TransferResult));
>    }
> 
> I'll send out a v2 patch.


Yes, thanks a lot.

One thing I noticed that on https://github.com/tianocore/edk2/pull/3705, 'DebugErrorLevel' is defined as a UINT32,
I think for macro DEBUG (which eventually uses function DebugPrint) takes UINTN as the input parameter.
Could you help to check on that?

Best Regards,
Hao Wu


> 
> --
> Rebecca Cran
> 
> 
> 
>