This post has been republished via RSS; it originally appeared at: Microsoft USB Blog articles.
First published on MSDN on Feb 10, 2010Updated 7/12/2011 with Windows 7 SP1 format data (in addition to RTM format data)
Hello, my name is Don Miller. I am a software developer on the Windows USB team but also I am the developer responsible for the Windows 1394 driver stack. In this blog post, I’m going to describe how to get debug trace messages from the Windows 7 1394OHCI.SYS driver. The Microsoft 1394OHCI.SYS driver is new for Windows 7 and uses WPP software tracing to log debug messages. For more information on the new Windows 7 1394OHCI.SYS driver please refer to the Windows 7 1394 stack whitepaper .
Enabling and viewing the 1394OHCI debug log can be helpful to Windows device driver developers who are writing 1394 client drivers using 1394OHCI.SYS as the bus driver for 1394 host controllers. 1394OHCI.SYS will emit various debug messages to its debug log and can be useful for checking for errors and other useful information. Below are instructions on how to know how to enable/disable 1394OHCI debug logging and instructions on how to view the log:
How to start/stop/view 1394OHCI logging:
========================================
1) Copy attached win7_1394ohcitrace_tool.zip to a local folder
2) Copy tracefmt.exe and tracelog.exe into same local directory or include on your path since 1394ohcitrace.cmd is dependent on these two tools. Tracefmt.exe and tracelog.exe are available in the Win7 WDK (
http://www.microsoft.com/downloads/details.aspx?FamilyID=2105564e-1a9a-4bf4-8d74-ec5b52da3d00&displaylang=en
). Once Win7 WDK is installed, these two files will be in C:\WinDDK\7600.16385.0\tools\tracing\ directory.
3) Open a command window with local administrator credentials and unzip win7_1394ohcitrace_tool.zip
4) At command prompt, type below command to set the _TMF_FILES environment variable that 1394ohcitrace.cmd is dependent on:
set _TMF_FILES=<path to win7_1394ohci.tmf included in ZIP file>
5) Run 1394ohcitrace.cmd with below options:
1394ohcitrace start
1394ohcitrace stop
1394ohcitrace view
1394ohcitrace view_realtime
Below is a sample 1394OHCI debug log:
Below format is:
[CPUNumber]ProcessID.ThreadID::SystemTime – 1394OHCI specific debug string
.
.
.
[1]0000.0000::02/08/2010-14:50:09.046 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:50:09.046 - Successfully allocated isoch channel 0
[2]0ED8.0EDC::02/08/2010-14:50:09.046 - IsochAllocateBandwidth: Flags 0x0 MaxBytesPerFrameRequested 320 Speed 4 BandwidthUnitsRequired 0x0
[2]0ED8.0EDC::02/08/2010-14:50:09.046 - Successfully allocated 0x00000140 isoch bandwidth units
[2]0ED8.0EDC::02/08/2010-14:50:09.047 - IsochAllocateResources: Status STATUS_SUCCESS hResource 0x7AA58410
[2]0ED8.0EDC::02/08/2010-14:50:09.062 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f00800 0 tLabel 0x36
[2]0000.0000::02/08/2010-14:50:09.062 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x36 tCode 0x0 DestinationId 0xffc0
[2]0000.0000::02/08/2010-14:50:09.062 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:50:09.077 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F52F0 : 0xffff.f0f00800 0 tLabel 0x37
[2]04C4.04CC::02/08/2010-14:50:09.077 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x86FFF080 tLabel 0x37 tCode 0x0 DestinationId 0xffc0
[2]04C4.04CC::02/08/2010-14:50:09.077 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[0]0ED8.0EDC::02/08/2010-14:50:09.093 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f00814 0 tLabel 0x38
[2]0004.006C::02/08/2010-14:50:09.093 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x38 tCode 0x0 DestinationId 0xffc0
[2]0004.006C::02/08/2010-14:50:09.093 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:50:09.109 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F52F0 : 0xffff.f0f00814 0 tLabel 0x39
[3]0000.0000::02/08/2010-14:50:09.109 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x86FFF080 tLabel 0x39 tCode 0x0 DestinationId 0xffc0
[3]0000.0000::02/08/2010-14:50:09.109 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:50:09.124 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f00808 0 tLabel 0x3a
[1]0000.0000::02/08/2010-14:50:09.124 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x3a tCode 0x0 DestinationId 0xffc0
[1]0000.0000::02/08/2010-14:50:09.124 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:50:09.140 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F52F0 : 0xffff.f0f00808 0 tLabel 0x3b
[2]0E5C.0E60::02/08/2010-14:50:09.140 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x86FFF080 tLabel 0x3b tCode 0x0 DestinationId 0xffc0
[2]0E5C.0E60::02/08/2010-14:50:09.140 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:50:09.155 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f0080c 0 tLabel 0x3c
[2]0000.0000::02/08/2010-14:50:09.155 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x3c tCode 0x0 DestinationId 0xffc0
[2]0000.0000::02/08/2010-14:50:09.155 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[3]0ED8.0EDC::02/08/2010-14:50:09.171 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F52F0 : 0xffff.f0f0080c 0 tLabel 0x3d
[2]0000.0000::02/08/2010-14:50:09.171 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x86FFF080 tLabel 0x3d tCode 0x0 DestinationId 0xffc0
[2]0000.0000::02/08/2010-14:50:09.171 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[0]0ED8.0F28::02/08/2010-14:52:09.057 - DataDescriptor->nMaxBytesPerFrame == 0
[0]0ED8.0F28::02/08/2010-14:52:14.694 - pIsochRx->HandleIsochAttachBuffers Failed 0xc000000d(STATUS_INVALID_PARAMETER) <-------Invalid REQUEST_ISOCH_ATTACH_BUFFERS.pIsochDescriptor.nMaxBytesPerFrame passed in
[0]0ED8.0F28::02/08/2010-14:52:14.694 - IsochAttachBuffers: Status 0xc000000d(STATUS_INVALID_PARAMETER)
[1]0ED8.0EDC::02/08/2010-14:52:16.973 - IsochListen: hResource 0x7AA58410 fulFlags 0x0 IsStreaming 0
[1]0ED8.0EDC::02/08/2010-14:52:16.973 - Isoch descriptor must be attached before starting stream
[1]0ED8.0EDC::02/08/2010-14:52:16.973 - pIsochRx->HandleIsochListen Failed 0xc000009a(STATUS_INSUFFICIENT_RESOURCES)
[1]0ED8.0EDC::02/08/2010-14:52:16.991 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f00600 0 tLabel 0x3e
[2]0ED8.0F28::02/08/2010-14:52:16.991 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x3e tCode 0x0 DestinationId 0xffc0
[2]0ED8.0F28::02/08/2010-14:52:16.991 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0F28::02/08/2010-14:52:16.996 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x874F5E08 IoWorker 0x874F52F0 : 0xffff.f0f00604 0 tLabel 0x3f
[3]0000.0000::02/08/2010-14:52:16.996 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x874F5E08 tLabel 0x3f tCode 0x0 DestinationId 0xffc0
[3]0000.0000::02/08/2010-14:52:16.996 - Complete TxWorker 0x874F5E08 Status STATUS_SUCCESS RetryCount 0
[3]0000.0000::02/08/2010-14:52:17.341 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f00608 0 tLabel 0x0
[1]07D0.0CBC::02/08/2010-14:52:17.341 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x0 tCode 0x0 DestinationId 0xffc0
[1]07D0.0CBC::02/08/2010-14:52:17.341 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0F28::02/08/2010-14:52:17.360 - Set IoWorker 0x855BD4D0 CommandPointer 0xcfd1a751
[2]0ED8.0F28::02/08/2010-14:52:17.360 - IsochListen: hResource 0x7AA58410 fulFlags 0x0 IsStreaming 0
[1]07D0.0CBC::02/08/2010-14:52:17.365 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x874F5E08 IoWorker 0x874F52F0 : 0xffff.f0f0060c 0 tLabel 0x1
[0]0000.0000::02/08/2010-14:52:17.365 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x874F5E08 tLabel 0x1 tCode 0x0 DestinationId 0xffc0
[0]0000.0000::02/08/2010-14:52:17.365 - Complete TxWorker 0x874F5E08 Status STATUS_SUCCESS RetryCount 0
[0]0000.0000::02/08/2010-14:52:18.109 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F5268 : 0xffff.f0f00614 0 tLabel 0x2
[1]07D0.0CBC::02/08/2010-14:52:18.127 - (4) Matched IoWorker 0x874F5268 TxWorkerData 0x86FFF080 tLabel 0x2 tCode 0x0 DestinationId 0xffc0
[1]07D0.0CBC::02/08/2010-14:52:18.127 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
[2]0ED8.0EDC::02/08/2010-14:52:34.202 - IsochStop: hResource 0x7AA58410 IsStreaming 1
[1]0ED8.0EDC::02/08/2010-14:52:34.202 - IsochStop: hResource 0x7AA58410 IsStreaming 0
[1]0ED8.0EDC::02/08/2010-14:52:34.202 - IsochStop: stream already stopped
[1]0ED8.0EDC::02/08/2010-14:52:34.202 - (4.0.2) WdfChildDevice 0x7AAE1AA8 TxWorkerData 0x86FFF080 IoWorker 0x874F52F0 : 0xffff.f0f00614 0 tLabel 0x3
[3]0000.0000::02/08/2010-14:52:34.202 - (4) Matched IoWorker 0x874F52F0 TxWorkerData 0x86FFF080 tLabel 0x3 tCode 0x0 DestinationId 0xffc0
[3]0000.0000::02/08/2010-14:52:34.202 - Complete TxWorker 0x86FFF080 Status STATUS_SUCCESS RetryCount 0
.
.
.
The above 1394OHCI debug log shows a debug message that indicates an error related to a 1394 client driver that has passed in an invalid REQUEST_ISOCH_ATTACH_BUFFERS.pIsochDescriptor.nMaxBytesPerFrame value. When a 1394 client driver is having issues working with the 1394OHCI.SYS driver then by looking at the 1394OHCI debug log it could save you trouble-shooting time.
Note that Windows 7 also includes the legacy 1394 stack (Vista and before). The legacy 1394 stack does not use WPP tracing but relies on debug prints to a debugger window. Please refer to the below Microsoft KB articles for more information on how to enable legacy 1394 debug logging:
How to enable debug prints in IEEE 1394 drivers
How to enable verbose debug tracing in various drivers and subsystems
Thanks,
Don Miller
Microsoft 1394/USB Development
==============================