Published
Oct 12 2018 03:55 PM
7,612
Views
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.
For more information and detailed instructions about using TraceView to view existing ETL logs, see Displaying a Trace Log with a PDB File .
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:
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:
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.
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.