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.
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
tab of the HLK Studio.
Expand the test result of interest and locate the failing
Right click on
, and then select
from the context menu. You should see an
file in the list. Select
to open the file location in Windows Explorer. Copy the .etl file for the next step.
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
option and click
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
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
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
which you can largely ignore. The
provider will contain the lowest level details and specific notifications and message payloads.
In this example, the
USB Type-C UCSI Power Role Swap
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 “
” command, but we can inspect the actual command in the third line to confirm that it is indeed command
, which we see in Table A-1 of the UCSI specification is the
command. The second line in this snippet reports that
“Power role change to
The value of 0x1 represents an internal enumeration value in the UcmCx driver which maps
power role, and
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
). The final line of this snippet is confirmation that the UCSI driver believes that the
) 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
) command. Here’s what we find:
We have command
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,
. These correspond to the
Connector Partner Flags
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
Connector Partner Type
Battery Charging Status
fields of Table 4-45.
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.