-----Original Message-----
From: devel@edk2.groups.io <devel@edk2.groups.io> On Behalf Of Wu, Hao
A
Sent: Wednesday, December 7, 2022 9:08 AM
To: Rebecca Cran <rebecca@...>; devel@edk2.groups.io; Gao,
Liming <gaoliming@...>; Ni, Ray <ray.ni@...>; Wang,
Jian J <jian.j.wang@...>
Subject: Re: [edk2-devel] [PATCH v2 1/1] MdeModulePkg: Put USB DEBUGs
that occur for bulk timeouts under VERBOSE

Reviewed-by: Hao A Wu <hao.a.wu@...>
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@...>
Sent: Tuesday, December 6, 2022 10:31 PM
To: devel@edk2.groups.io; Gao, Liming <gaoliming@...>; Ni,
Ray <ray.ni@...>; Wang, Jian J <jian.j.wang@...>; Wu, Hao A
<hao.a.wu@...>
Cc: Rebecca Cran <rebecca@...>
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@...>
---
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

-----Original Message-----
From: Rebecca Cran <rebecca@...>
Sent: Tuesday, December 6, 2022 10:31 PM
To: devel@edk2.groups.io; Gao, Liming <gaoliming@...>; Ni,
Ray <ray.ni@...>; Wang, Jian J <jian.j.wang@...>; Wu, Hao A
<hao.a.wu@...>
Cc: Rebecca Cran <rebecca@...>
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@...>
---
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