First published on MSDN on Aug 03, 2017
Authored by Philip Froese [MSFT]
Newly added in the RS3 preview builds of the HLK, the USB Type-C HLK tests for UCM and UCSI will automatically capture debug traces from the relevant driver(s) during the test.
Note:
if you are used to manually capturing the driver traces, that method should no longer be used during HLK testing. Only one trace session can be active simultaneously, so enabling a separate trace will preclude the HLK from capturing meaningful diagnostic data. This applies only to the UCSI specific tests in the HLK.
Locating the Log File
-
After running the USB Type-C HLK test(s) of interest, switch to the
Results
tab of the HLK Studio.
-
Expand the test result of interest and locate the failing
Run Test
-
Right click on
Run Test
, and then select
Additional Files
from the context menu. You should see an
.etl
file in the list. Select
Show All
to open the file location in Windows Explorer. Copy the .etl file for the next step.
Parsing the Log File using TraceView
For more information and detailed instructions about using
TraceView
to view existing ETL logs, see
Displaying a Trace Log with a PDB File
.
-
Start
TraceView
, you will find it in the WDK under the
.\Tools\<Architecture>
-
Select the
Options
menu and
Configure Symbols
. Enter the following into the
Symbols Path
field to direct
TraceView
to the Microsoft public symbol server, and click
OK
.
SRV*https://msdl.microsoft.com/download/symbols
-
Select the
File
menu, and
Open Existing Log File
.
-
Enter the log file path and name into the
Log File Name
box, or navigate to the log file with the button to the right.
-
On the next menu, select the
Auto
option and click
OK
.
-
It may take several seconds for the symbols to be retrieved and the trace parsed, but once that completes, you should see an output like the following. In this example, for clarity only the
Name
,
System Time
and
Message
columns are displayed. You can change the columns by right clicking on any column header and selecting from the context menu.
Reading the Trace
The driver traces contain a lot of low-level details which will not all be relevant to your investigation and may be difficult to make sense of. However, as the example below will attempt to show, with a few tips and tricks, knowledge of the UCSI specification, and some experience, they can be valuable debugging tools.
A few tips before we get to the example:
-
When starting to investigate a failure, use the HLK test log to understand the high-level flow of the test, what action failed and the nature of the failure.
-
Use the timestamps in the test log and in the driver trace to correlate what the test was doing with the events in the driver. This can help you isolate the area of interest to a few dozen lines of what may be a very large trace file.
-
Familiarize yourself with the UCSI command codes (Table A-1) and command data payloads (Section 4) defined in the UCSI specification as this information will be necessary to decode portions of the driver traces.
-
The UCSI Compliance Tests, which use the testucsi driver enable several extraneous providers for which there are no symbols. You can ignore events from
Unknown Provider
in those traces. These events are mostly useful for debugging the test code itself and may be removed from the HLK in the future.
-
In the Ucm and Ucsi Role Swap Test traces, you will see events from
UcmCx
and the
PolicyManager
which you can largely ignore. The
UcmUcsi
provider will contain the lowest level details and specific notifications and message payloads.
Example
In this example, the
USB Type-C UCSI Power Role Swap
Test
has failed with the following sequence in the HLK test log:
This trace is telling us that the connector was initially a power provider. The test then sent the Set Power Direction Role command, and re-checked the port status at which point the port was still a power provider. Let’s look at the driver trace.
First, we’ll copy UcsiRoleSwapTrace.etl from the HLK results temporary location, and open it with TraceView. The timestamp in the test log for the SetPdr command is 8:39:13:382, so we’ll start there in the driver trace and look forwards for the Set Power Direction Role command. We find it recorded in the trace with a timestamp 12 ms later:
In this case, the UCSI test interface accessed by the HLK test records that this is a “
SetPowerRole
” command, but we can inspect the actual command in the third line to confirm that it is indeed command
0xB
, which we see in Table A-1 of the UCSI specification is the
SET_PDR
command. The second line in this snippet reports that
“Power role change to
0x1
was requested.”
The value of 0x1 represents an internal enumeration value in the UcmCx driver which maps
0x1
to the
Sink
power role, and
0x2
to the
Source
power role. (Please note, this does not match the Power Direction Role value specified in Table 4.24 of the UCSI specification). So, now we have confirmed that we see the correct SET_PDR command being successfully sent to the UCSI device to switch the connector to the consumer role.
Next, since this was an asynchronous command, let’s look for the completion. We find it approximately 200ms later in the trace:
Here we see a notification with only bit 32 of the CCI set which per Table 3-2 of the specification is the
Command Completed Indicator
. We see that printed in the next line, which also confirms that this was command
0xB
(
SET_PDR
). The final line of this snippet is confirmation that the UCSI driver believes that the
SET_PDR
to role
0x1
(
consumer
) is completed successfully.
Going back to the HLK log, we see that at 8:39:13.890, the test logs that the connector is still in the provider mode and fails. This means that the test must have queried the connector status before this point, so we can go to this timestamp in the log and work backwards looking for a
GET_CONNECTOR_STATUS
(
0x12
) command. Here’s what we find:
We have command
0x12
completing successfully with a data payload of 9 bytes based on the CCI. See Table 3-2 of the UCSI spec to parse the specific fields in the CCI. Reviewing section 4.5.18 of UCSI for the Get Connector Status data payload, we see that it is indeed 72 bits (or 9 bytes) long. Now for the tricky part, what was the connector status? Unfortunately, this is a place where the clarity of the log file is lacking and you will just have to follow these rules to interpret the connector status result:
-
Third from the bottom is a blank log line. This indicates that none of the Connector Status Change bits were set. If they were, this log line would contain the string names of each set Connector Status Change bits (see Table 4-46 in the specification).
-
Second from the bottom, we have three named fields,
Connect
,
PartnerFlags
and
RDO
. These correspond to the
Connect Status
,
Connector Partner Flags
, and
Request Data Object
fields in Table 4-45 of the spec respectively.
-
The last row of the above snippet is four single digit hexadecimal numbers. Unfortunately, these are not explicitly named in the log, but they correspond, in order, to the
Power Operation Mode
,
Power Direction
,
Connector Partner Type
, and
Battery Charging Status
fields of Table 4-45.
-
If the
Provider Capabilities Limited Reason
field is set, the reason will be printed as a string-name in this line as well. In our example, it is not set.
In this example, we see that the connector is reporting a connection, it is in PD power mode, it is operating as a provider, and the partner is a UFP and operating in an alternate mode in addition to USB.
This example is somewhat trivial: we went through a failure in the HLK log and simply checked that each step was completed in the driver as expected, and confirmed that the connector status did indeed report an unexpected power direction. At this point we would need to work with the firmware engineers for this UCSI implementation to understand why the SET_PDR command completed successfully but the role did not change.