From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mx0a-0031df01.pphosted.com (mx0a-0031df01.pphosted.com [205.220.168.131]) by mx.groups.io with SMTP id smtpd.web11.49100.1670337062049935503 for ; Tue, 06 Dec 2022 06:31:02 -0800 Authentication-Results: mx.groups.io; dkim=pass header.i=@quicinc.com header.s=qcppdkim1 header.b=SmCOOX/j; spf=permerror, err=parse error for token &{10 18 %{ir}.%{v}.%{d}.spf.has.pphosted.com}: invalid domain name (domain: quicinc.com, ip: 205.220.168.131, mailfrom: quic_rcran@quicinc.com) Received: from pps.filterd (m0279865.ppops.net [127.0.0.1]) by mx0a-0031df01.pphosted.com (8.17.1.19/8.17.1.19) with ESMTP id 2B69SpPq024836; Tue, 6 Dec 2022 14:30:55 GMT DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=quicinc.com; h=from : to : cc : subject : date : message-id : in-reply-to : references : mime-version : content-transfer-encoding : content-type; s=qcppdkim1; bh=eu/vfU/5dlz+ReRr8dbiPySdZEuRxrM4fC8uCGYZ8iQ=; b=SmCOOX/jy1o8IeKJ8gVBRLM0PqeMr5xJg1wdhW9/um3uVll1PXIlHSPzTPmwV8tecr1W QvZezh7VTE+IMIpbQpFpmHCCPzIB7IzV9+/dasiEuDva9JjGfaXo1qUXHbd5P3+GSSPs yLrt3+/uEXfz2NYHxeEzKMOPIodDNR0Tvuql75S6C+65rHC6IM4kDfRNn4r5ssR6C+tG OlYKmfdn7d8bQqYDCkXal7sRUlO8QS0P+YNWTJFO2D+QC9Xw0I/vEjJak2Etrs5830NO n22msYxRZAMC46wMGntFtNJiL0RyTSUNqFFA5Trn01osxjqjikJTr69nxl+RnFBXFprl +Q== Received: from nalasppmta04.qualcomm.com (Global_NAT1.qualcomm.com [129.46.96.20]) by mx0a-0031df01.pphosted.com (PPS) with ESMTPS id 3m9xkc9gm0-1 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT); Tue, 06 Dec 2022 14:30:55 +0000 Received: from nalasex01a.na.qualcomm.com (nalasex01a.na.qualcomm.com [10.47.209.196]) by NALASPPMTA04.qualcomm.com (8.17.1.5/8.17.1.5) with ESMTPS id 2B6EUs12009680 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT); Tue, 6 Dec 2022 14:30:54 GMT Received: from linbox.qualcomm.com (10.80.80.8) by nalasex01a.na.qualcomm.com (10.47.209.196) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.2.986.36; Tue, 6 Dec 2022 06:30:53 -0800 From: "Rebecca Cran" To: , Liming Gao , Ray Ni , J Wang , Hao Wu CC: Rebecca Cran Subject: [PATCH v2 1/1] MdeModulePkg: Put USB DEBUGs that occur for bulk timeouts under VERBOSE Date: Tue, 6 Dec 2022 07:30:39 -0700 Message-ID: <20221206143039.278566-2-rebecca@quicinc.com> X-Mailer: git-send-email 2.30.2 In-Reply-To: <20221206143039.278566-1-rebecca@quicinc.com> References: <20221206143039.278566-1-rebecca@quicinc.com> MIME-Version: 1.0 X-Originating-IP: [10.80.80.8] X-ClientProxiedBy: nasanex01b.na.qualcomm.com (10.46.141.250) To nalasex01a.na.qualcomm.com (10.47.209.196) X-QCInternal: smtphost X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=5800 signatures=585085 X-Proofpoint-ORIG-GUID: 8bE-dv3c5DL16VQ0GSwTX9vKDMhyuIuC X-Proofpoint-GUID: 8bE-dv3c5DL16VQ0GSwTX9vKDMhyuIuC X-Proofpoint-Virus-Version: vendor=baseguard engine=ICAP:2.0.205,Aquarius:18.0.923,Hydra:6.0.545,FMLib:17.11.122.1 definitions=2022-12-06_10,2022-12-06_01,2022-06-22_01 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 mlxlogscore=999 mlxscore=0 lowpriorityscore=0 bulkscore=0 phishscore=0 priorityscore=1501 impostorscore=0 clxscore=1015 adultscore=0 spamscore=0 suspectscore=0 malwarescore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2210170000 definitions=main-2212060119 Content-Transfer-Encoding: 8bit Content-Type: text/plain 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 --- 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