Mailing Lists: Apple Mailing Lists
Image of Mac OS face in stamp
Re: Replacement for IOUSBFamily log?
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: Replacement for IOUSBFamily log?


(Sorry for the formatting but the list server barfs on emails > 24K, so my pretty RTF email got bounced):

It is indeed unfortunate that the logging version is not available.  Since the sources are also not open-sourced either, then you are in a lot of hurt if you want to get insight into what’s going on inside the USB stack.  As you’ve mentioned, dtrace is an option and I’ll give you a couple of probe points that you can use.  The kernel tracepoint tool for USB, usbtracer, also will work.  This tool was released via the Debug IOUSBFamily package.  Here’s what you can do: (BTW, I’m doing this on Yosemite 10.10.1):

1.  Download the last available Debug kit from the Developer website.  I find the one for 10.9.4 at: (You have to be logged into the developer portal for this to work, I believe):

2.  Mount the “-log” disk image and extract the files with the following command (cd to a temporary directory):

$ sudo pax -r -v -z -f /Volumes/IOUSBFamily-683.4.0-log/IOUSBFamily-683.4.0-log/IOUSBFamily-683.4.0-log.pkg/Contents/Archive.pax.gz

3.  Look into the DevTools/Hardware folder that is extracted.  You’ll find the USB there, which is still handy even if you don’t get the logging.  This build runs fine on Yosemite.

4.  Run the tool ‘usbtracer’ in the Resources folder of the USB

Nano:/DevTools/Hardware/USB sudo ./usbtracer
usbtracer version:  "680.4.1"
09:28:39 [80395557500][         0 us] -> XHCI::Begin Primary Interrupt  (0xffffff81a06d3000)
09:28:39 [80395557501][         1 us]    XHCI::Primary Interrupt        (0xffffff81a06d3000) isInactive: 0, _controllerAvailable: 0
09:28:39 [80395557508][         7 us]    XHCI::Primary Interrupt        (0xffffff81a06d3000) interrupt pending: true MFINDEX:0x0000127f
09:28:39 [80395557514][         6 us]    XHCI::Primary Interrupt        (0xffffff81a06d3000) IMOD:0x000000a0  IMAN: 0x00000002
09:28:39 [80395557515][         1 us] -> XHCI::Begin FilterEventRing    (0xffffff81a06d3000) ---> IRQ[0]

This will give you a LOT of information and it will sometimes have undecoded trace points (because we are using the 10.9.4 version of the tool under 10.10.1), which won’t be very helpful:

09:29:59 [80475899630][        12 us] <- F-0x052d|00|044  ffffff81a06d3000                 0                 0                 0  0x             246   0

But it can also give you information like what type of control request was issued:

09:30:01 [80476970379][         0 us] -> Controller::Control Start      (0xffffff81a06d3000) Bus: 0x40, Address: 28, Endpoint: 0, (in)  bmRequestType: 0x80, bRequest: 0x06, wValue: 0x0100, wIndex: 0x0000, wLength: 0x0012 (GET_DESCRIPTOR (Device))

and the actual data from that request:

09:30:01 [80476971504][         3 us]    Controller::Packet Handler     (0x0000000000000000) Bus: 0x40, Address: 28, Endpoint: 0, (in)  length: 18, data: 0x1201000200000008 0x6d0418c504420102

The tools is VERY verbose but *could* be helpful. It also does not require any special version of the USB stack — works with what ships.  The downside is that the tool won’t decode any new tracepoints that have been added.

As far as dtrace probes, you can get call stacks (and if you know the API you can even see the values of the parameters or the return value.  Here are some examples:

1.  To see all IOUSBDevice object calls:

sudo dtrace -n '*:*:*IOUSBDevice*:entry { stack(); }'

which will give you the kernel stack when the call was made, e.g.:

  6 298880 _ZN11IOUSBDevice11GetVendorIDEv:entry
              IOUSBFamily`IOUSBPipe::ControlRequest(IOUSBDevRequestDesc*, unsigned int, unsigned int, IOUSBCompletion*)+0x4f
              IOUSBFamily`IOUSBDevice::_DeviceRequestDescWithTimeout(OSObject*, void*, void*, void*, void*)+0xd9
              kernel`IOCommandGate::runAction(int (*)(OSObject*, void*, void*, void*, void*), void*, void*, void*, void*)+0x198
              IOUSBFamily`IOUSBDevice::DeviceRequest(IOUSBDevRequestDesc*, unsigned int, unsigned int, IOUSBCompletion*)+0x8e
              IOUSBFamily`IOUSBDeviceUserClientV2::DeviceRequestIn(unsigned char, unsigned char, unsigned short, unsigned short, unsigned long long, unsigned long long, unsigned int, unsigned int, IOUSBCompletion*)+0xf4
              IOUSBFamily`IOUSBDeviceUserClientV2::_DeviceRequestIn(IOUSBDeviceUserClientV2*, void*, IOExternalMethodArguments*)+0xec
              kernel`IOUserClient::externalMethod(unsigned int, IOExternalMethodArguments*, IOExternalMethodDispatch*, OSObject*, void*)+0x1cf

Using “ustack()”, will give you the user stack instead:

  6 298838 _ZN11IOUSBDevice29_DeviceRequestDescWithTimeoutEP8OSObjectPvS2_S2_S2_:entry
              IOUSBLib`IOUSBDeviceClass::DeviceRequestAsync(IOUSBDevRequestTO*, void (*)(void*, int, void*), void*)+0x16d
              IOUSBLib`IOUSBDeviceClass::deviceDeviceRequestAsync(void*, IOUSBDevRequest*, void (*)(void*, int, void*), void*)+0x58

2.  If you want to get the return value of a function, you can do it as follows.  We’ll use the IOUSBController.h API GetFrameNumber.

    virtual UInt64 		GetFrameNumber( void ) = 0;

We see that this is a abstract method implemented by the subclasses of IOUSBController (mainly the host controller drivers) and that it returns a UInt64, the frame number.  We can then create a dtrace probe that will display this value:

sudo dtrace -n '*:*:*GetFrameNumber*:return { stack(); printf("frameNumber = 0x%x", arg1);}'

which will then give you the following type of output:

  6 297844 _ZN12AppleUSBXHCI14GetFrameNumberEv:return
              AppleUSBAudio`AppleUSBAudioEngine::clipOutputSamples(void const*, void*, unsigned int, unsigned int, _IOAudioStreamFormat const*, IOAudioStream*)+0x4c
              IOAudioFamily`IOAudioStream::clipOutputSamples(unsigned int, unsigned int)+0xc8
              IOAudioFamily`IOAudioStream::processOutputSamples(IOAudioClientBuffer*, unsigned int, unsigned int, bool)+0x5b7
              IOAudioFamily`IOAudioEngineUserClient::performClientOutput(unsigned int, unsigned int, IOAudioClientBufferSet*, unsigned int, unsigned int)+0x24e
              IOAudioFamily`IOAudioEngineUserClient::performClientIO(unsigned int, unsigned int, bool, unsigned int, unsigned int, unsigned int)+0xf7
frameNumber = 0x4d9ceb8

Hopefully the above can give you a start on how to further debug your issues.  Another option, if applicable, is to use 10.9.4 and install the debug version of the IOUSBFamily.  I would download that package and keep it — you never know if it will suddenly disappear or not.


Nano Urbina
Build Slave
Razz Software

Do not post admin requests to the list. They will be ignored.
Usb mailing list      (email@hidden)
Help/Unsubscribe/Update your Subscription:

This email sent to email@hidden

 >Replacement for IOUSBFamily log? (From: Eric Gorouben <email@hidden>)

Visit the Apple Store online or at retail locations.

Contact Apple | Terms of Use | Privacy Policy

Copyright © 2011 Apple Inc. All rights reserved.