El Capitan recording sync issue

[Wouter1]

This is a follow-up to #18

Apple has changed something in the USB core to fix this issue.

They reported back

We believe this issue has been addressed in the OS X El Capitan 10.11 release. Please test with this release, and update this report with your results.

Engineering has determined that your bug report (19352753) is a duplicate of another issue (21376752) and will be closed.

We may have to check if this change has consequences.

[Wouter1]

Nov 28 10:17:36 wouters-MBP kernel[0]: UsbInputRing::notifyWrap 6038360778661
Nov 28 10:17:36 wouters-MBP kernel[0]: +convertInputSamples firstSampleFrame=12038, numSampleFrames=250 curr=18450 avail= 18450
Nov 28 10:17:36 wouters-MBP kernel[0]: EMUUSBAudioEngine::convertInputSamples READ HICKUP
Nov 28 10:17:36 wouters-MBP kernel[0]: +convertInputSamples firstSampleFrame=0, numSampleFrames=3220 curr=18450 avail= 18450
Nov 28 10:17:36 wouters-MBP kernel[0]: EMUUSBAudioEngine::convertInputSamples err reading ring: e00002e7

It seems the first read correctly did not snoop off data, as in the 2nd call there is still 18450 bytes = 3075 frames available.e However osx asks for 3220 , 145 more than available.

[Wouter1]

Printing more data

Nov 28 10:47:34 wouters-MBP kernel[0]: USB timer started
Nov 28 10:47:34 wouters-MBP kernel[0]: RingBufferDefault<USBInputRing>::push warning. Ignoring overrun
Nov 28 10:47:34 wouters-MBP kernel[0]: UsbInputRing::notifyWrap 7835766793489
Nov 28 10:47:34 wouters-MBP kernel[0]: +convertInputSamples firstSampleFrame=12142, numSampleFrames=146 curr=18450 avail= 18450 estCur=3971
Nov 28 10:47:34 wouters-MBP kernel[0]: EMUUSBAudioEngine::convertInputSamples READ HICKUP
Nov 28 10:47:34 wouters-MBP kernel[0]: +convertInputSamples firstSampleFrame=0, numSampleFrames=3950 curr=18450 avail= 18450 estCur=3974
Nov 28 10:47:34 wouters-MBP kernel[0]: EMUUSBAudioEngine::convertInputSamples err reading ring: e00002e7

So we estimate we have 3974 frames and OSX correctly is asking for 3950 frames. Somehow the expected does not match up.

BUT, this message comes before the latest processing. i need to move that message to a letter point to make correct judgment.

[Wouter1]

moved the message to after usbInputStream.update()

Nov 28 11:52:48 wouters-MBP kernel[0]: USB timer started
Nov 28 11:52:48 wouters-MBP kernel[0]: RingBufferDefault<USBInputRing>::push warning. Ignoring overrun
Nov 28 11:52:48 wouters-MBP kernel[0]: UsbInputRing::notifyWrap 9230700110816
Nov 28 11:52:48 wouters-MBP kernel[0]: +convertInputSamples firstSampleFrame=12042, numSampleFrames=246 curr=18450 avail= 18450 estCur=3872
Nov 28 11:52:48 wouters-MBP kernel[0]: EMUUSBAudioEngine::convertInputSamples READ HICKUP
Nov 28 11:52:48 wouters-MBP kernel[0]: +convertInputSamples firstSampleFrame=0, numSampleFrames=3850 curr=18450 avail= 18450 estCur=3873
Nov 28 11:52:48 wouters-MBP kernel[0]: EMUUSBAudioEngine::convertInputSamples err reading ring: e00002e7

the update call doesn't help. There is no data available.

[Wouter1]

The problem is aggravated by the data reception being blocked once the reading goes just in front of the write head. Then, the buffer appears to be full and we can't write the new data in.

[Wouter1]

Added this line

            debugIOLog("received %d %lld at %lld",size, pFrames[frameIndex].frTimeStamp, mach_absolute_time());

to gatherFromReadList(), just after the two push() calls.

You get shiploads of data, the logger will stop logging after 500 of these messages and continue only 1 second later. But it gives some idea. I reduced the rate to 48k. All packets checked contain 288 bytes.

This is what you get

(short snip of few lines from the log)

Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803103629575 at 10803120376150
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803104110105 at 10803120380106
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803104584740 at 10803120384026
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803105114234 at 10803120387692
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803105554831 at 10803120391526
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803106030469 at 10803120395354
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803106622813 at 10803120399013
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803107113557 at 10803120402956
Nov 28 12:19:01 wouters-MBP kernel[0]: received 288 10803107544230 at 10803120406863

[Wouter1]

The time stamps are approximately ns.

[Wouter1]

The vertical jumps are coincident with thewarning way-out ring wrap position

They have a size 10803216202639-10803184419046 = 31ms. This is way large.

[Wouter1]

A plot of the difference between two subseuqnetial reported received-usb-iframe times

[Wouter1]

We are receiving 2 packets per millisecond, each 288 bytes = 24 quad samples (we seem to be working with 4 channels anyway, even if I sample just stereo). That seems correct.

[Wouter1]

And this is the time between the processringmoment of the packet and the previous packet.

[Wouter1]

The lower range is in the order of 3000 to 4000 ns, The high ones 31ms. There are typically 63 points in the low area, 1 high, and then 63 low. This matches the data rate: 24*64 = 1536 samples per USB frame list is 32ms.

[Wouter1]

Maybe the frame list info is not updated before the readCompleted call as it should? We can check by investigating what happens if we call usbInputStream.update(); from convertInputSamples

[Wouter1]

To test this, add extra (bool log) parameter to GatherInpuptSamples. false if called from readCompleted, true if from update.

[Wouter1]

Confirmed, this is the problem. We do not see any partially received USB frames anymore. We only can see the USB data when a FULL frame has arrived and this can give a lag of up to 64*288 bytes. Either something was changed in how to request their immediate update, or their immediate update is reported differently back to us.

[Wouter1]

from this reply from Fernando Urbina (from Apple I think)

http://lists.apple.com/archives/usb/2013/Oct/msg00001.html

Does the usb controller write its data to the buffer I provide via DMA? Or could there also be some delay on when the size information and or data actually arrives in the packet compared to when the frame rolls to the next? Thanks.

Yes, the data is DMA'd directly to the memory from the buffer you provided (for low latency). However, the frActCount, frStatus, and frTimeStamp are updated later on, at filter interrupt time, when we get the completion interrupt. The DMA will happen anytime within the 1ms window of a USB frame. The completion interrupt will happen at the end of that millisecond frame. I believe that the frame number will also be updated at the end of the frame as well. I would surprise me if the data was not there. It would not be too surprising that the framelist might not be there yet.

[Wouter1]

I AM requesting once per millisecond updates for the pipe Read (last argument, readFrameList). Did their signalling (frStatus) change?

[Wouter1]

Status of first frame is always 1819044212=0x6C6C6974 ('lit' I guess), indicating in-progress. Actual bytes always 0.

[Wouter1]

Tried replacing update frequency every ms by 2 (every 2 ms).

[Wouter1]

Makes no difference.

[Wouter1]

Trying to figure out what might be going on in kernel using the open source code again...

http://www.opensource.apple.com/source/IOUSBFamily/IOUSBFamily-630.4.5/IOUSBFamily/Classes/IOUSBPipe.cpp

    err = _controller->IsocIO(buffer, frameStart, numFrames, pFrames, _address, &_endpoint, completion, updateFrequency);

But I get no code for IOUSBController...

Looking at older versions now.. 440.4ok 540.4 ok 560.4 ok. I will use 560.4 for now. Not so nice, looking at the numbers this might be quite old.

[Wouter1]

I have done this before, even before I was on GIT. But then the function was in IOController. It's not anymore.

It seems it's here now

http://www.opensource.apple.com/source/IOUSBFamily/IOUSBFamily-560.4.2/IOUSBFamily/Classes/IOUSBController_Pipes.cpp

[Wouter1]

You get into

command->SetUpdateFrequency(updateFrequency);
command->SetLowLatency(true);
err = _commandGate->runAction(DoIsocTransfer, command);

[Wouter1]

IOCommandGate

http://www.opensource.apple.com/source/xnu/xnu-2782.40.9/iokit/Kernel/IOCommandGate.cpp

They have completely different version numbers than IOUSBFamily, I assume we again have the latest.

[Wouter1]

the runAction is just calling DoIsocTransfer(command)

[Wouter1]

The UpdateFrequency is passed into a call to USBTrace. Otherwise I don't see it used.

USBTracepoints is here

opensource.apple.com/source/IOUSBFamily/IOUSBFamily-516.4.1/IOUSBFamily/Headers/USBTracepoints.h

#define USBTrace(USBClass, code, a, b, c, d) {                                                      \
            if (gUSBStackDebugFlags & kUSBEnableTracePointsMask) {                                  \
                IOTimeStampConstant( USB_TRACE(USBClass, code, DBG_FUNC_NONE), a, b, c, d );        \
            }                                                                                       \
        }

where

#define USB_TRACE(USBClass, code, funcQualifier)    ( ( ( DBG_IOKIT & 0xFF ) << 24) | ( ( DBG_IOUSB & 0xFF ) << 16 ) | ( ( USBClass & 0x3F ) << 10 ) | ( ( code & 0xFF ) << 2 ) | ( funcQualifier & 0x3 ) )

[Wouter1]

USBTracePoints only for debugging, not for actually executing.

[Wouter1]

The IOUSBController#DoIsocTransfer above also calls controller->IsocTransaction(command). There it forwards again into UIMCreateIsochTransfer(command)

That function forwards the command into AppleUSBOHCI_UIM.cpp UIMCreateIsochTransfer(....)

http://opensource.apple.com/source/IOUSBFamily/IOUSBFamily-560.4.2/AppleUSBOHCI/Classes/AppleUSBOHCI_UIM.cpp

It looks like this is where finally something starts crunching

[Wouter1]

That's some pretty ugly function. 400 lines, 50 variables...

I suppose this is test whether the update of our info should be done

        if ( (curFrameInTD > 7) || needNewITD || (lowLatency && useUpdateFrequency && (curFrameInTD >= updateFrequency)) ) 

curFrameInTD looks like a microframe counter.

They are cleaning the frStatus as expected.

But they are never setting it.

[Wouter1]

I don't see yet where their interrupts are being handled, and if that's where our callback is supposed to happen to set the frStatus.

[Wouter1]

If I run exactly the same driver in Mavericks, I get this output

Nov 29 14:24:27 vlieland kernel[0]: update!  curr framelist=56
Nov 29 14:24:27 vlieland kernel[0]: frame 0:292 bytes. status=-536870169
Nov 29 14:24:27 vlieland kernel[0]: received 288 212563683427 at 212563785609
Nov 29 14:24:27 vlieland kernel[0]: received 288 212563684853 at 212563787868

so in mavericks, the extra data IS coming in. In Capitan we always get framelist=0 and 0 bytes like

Nov 29 14:24:27 vlieland kernel[0]: update!  curr framelist=0
Nov 29 14:24:27 vlieland kernel[0]: frame 0:0 bytes. status=1819044212

[Wouter1]

I tried again what I did 2 days ago

Just as a shot in the dark I ignored OSX's start position and just deliver bytes as available. Then it all works perfect, at least for 10 seconds for the left channel at 96k (not longer tested).

It does not work anymore. Seems it was just a hick. Very puzzling. Again one of these inconsistencies in behaviour.

[Wouter1]

Filed bug report 23682041 with apple. Maybe they can tell what's the difference in the USB drivers.

usb low latency isochronous asynchronous transfer not working as expected

w pasman29-Nov-2015 03:18 PM

Summary:
I have written a kernel driver for OSX that connects a USB audio device (https://github.com/Wouter1/EMU-driver)

It works fine in Mavericks. As usually for audio over USB, it relies on low latency refresh of the received USB frames.

When I run exactly the same driver in El Capitan, all the data comes in at the correct rate; however the low latency refresh of the received USB frames (every millisecond) just does not happen. Fields like frStatus are set only after the entire frame (32ms typically) has arrived.

Steps to Reproduce:
Install driver in el capitan as instructed on git. Turn on EMU. Set EMU0404 to 96kHz sampling with the control panel (or any other rate). Use audacity to sample a stereo sample.

Expected Results:
correct sampled sound in El Capitan, just as in Mavericks.

Actual Results:
noise. Errors from the driver. Caused by USB data not coming in in time.
I can provide a small mod for the driver so that you can see also that the status of the frames remains 

Version:
El Capitan 10.11.1 

It works fine with latest Mavericks.

Notes:

Configuration:
Macbook pro 15 inch late 2013. 2.3G intel i7. 16GB DDR3. GT750M. EMU 0404. Dell 4K 30" screen on thunderbolt, working also as USB hub for the EMU, keyboard and mouse. Connecting EMU directly to MBP on the other USB slot makes no difference for the issue.

Attachments:

[Wouter1]

It seems the only problem is the improper low latency behaviour of the USB stack.

If we set the driver to keep a HUGE distance from the head, it might just work fine.

288*64=18432bytes=3072 stereosamples=32ms.

If you set the latency to 35ms it might just work.

[Wouter1]

Yes workaround seems to work for 96k. It's flimsy but better than nothing.

Working settings: 35ms latency for driver. 5ms for audacity.

[Wouter1]

Check 48k ok

Check 44k1 ok

[Wouter1]

I just saw that if you go to the about this mac/ system report and then select USB, you get to see the actual driver being used.

In El Capitan we have AppleUSBXHCILPTH

This is new compared to Mavericks.

[Wouter1]

posted reminder on apple bug report radar 23682041 and asked if they can at least confirm the issue

[Wouter1]

There's lots of discussions here on how to fix USB issues in El Capitan. Not sure if it's only for hackintoshes but there might be something useful

http://www.tonymacx86.com/el-capitan-desktop-support/174002-osx-el-capitan-tips-fixing-intel-usb.html

http://www.tonymacx86.com/el-capitan-laptop-support/173616-guide-10-11-usb-changes-solutions.html

[Wouter1]

Apple apparently had this text about 10.11 on their webpages

http://developer.apple.com/library/prerelease/mac/releasenotes/Darwin/RN_USB/Articles/10_11Changes.html

The page has been unreachable for some time but it appears back up

OS X v10.11 Changes

This article describes changes to USB in OS X v10.11.

 *  The USB stack is completely redesigned to increase stability and performance compared to Mac OS 10.10. Applications and third-party drivers for vendor-specific USB devices built with 10.10 SDK require no modification.
 *   Applications that use IOUSBLib APIs should continue to work with no modification. IOKit drivers that use IOUSBDevice and IOUSBInterface APIs should continue to load and be functional with no regressions.
 *   If you are developing a new IOKit driver that uses IOKIT USB APIs, please refer to the OS X v10.11 SDK for new API and classes such as IOUSBHostDevice and IOUSBHostInterface. New applications developed using the OS X v10.11 SDK should continue to use the IOUSBLib APIs.
 *   Different classes of USB devices should not exhibit any regression in functionality compared to the OS X v10.10 release.

[Wouter1]

I found some info in the IOUSHBhostPipe.h file in XCode 7

All old IOUSBHostPipe.h code is in there but commented out. It also mentions "Replacement: io"

[Wouter1]

Many names changed, I take a quick-guess approach for now

IOUSBHostController now seems to be named AppleUSBHostController IOUSBLowLatencyIsocCompletion now seems IOUSBHostIsochronousCompletion IOUSBPipe now seems IOUSBHostPipe etc etc

Some calls also changed. Most importantly so far is IOUSBPipe.Write that was renamed to IOUSBHostPipe.io and takes different order of parameters. I hope the parameters themselves will still work.

[Wouter1]

The IOUSBHostDevice.h contains instructins on how to replace GetStringDescriptor like this

    // virtual IOReturn GetStringDescriptor(UInt8 index, char* buf, int maxLen, UInt16 lang = 0x409) __attribute__((deprecated));
    // Replacement: getStringDescriptor(index, languageID)
    // Use sys/utfconv.h to extract UTF strings from string descriptors:
    // char stringBuffer[256] = { 0 };
    // size_t utf8len = 0;
    // const StringDescriptor* stringDescriptor = getStringDescriptor(index);
    // if(   stringDescriptor != NULL
    //    && stringDescriptor->bLength > StandardUSB::kDescriptorSize)
    // {
    //     utf8_encodestr(reinterpret_cast<const u_int16_t*>(stringDescriptor->bString), stringDescriptor->bLength - kDescriptorSize,
    //                    reinterpret_cast<u_int8_t*>(stringBuffer), &utf8len, sizeof(stringBuffer), '/', UTF_LITTLE_ENDIAN);
    // }

[Wouter1]

Not clear how this is to be replaced IOReturn DeviceRequest(IOUSBDevRequest* request, IOUSBCompletion* completion = 0) );

The comments in IOUSHHostDevide just say

 Replacment: deviceRequest(...)

However, all the new deviceRequest functions do not take a IOUSBDevRequest; additionally they take multiple parameters, eg a data pointer

[Wouter1]

Here's some other code that apparently was intended to patch the new IOUSBHostPipe to match better with the original IOUSBPipe

https://github.com/RehabMan/OS-X-BrcmPatchRAM/blob/master/BrcmPatchRAM/USBHostDeviceShim.cpp

[Wouter1]

Looks like there are two versions in that link:

pre-Capitan: https://github.com/RehabMan/OS-X-BrcmPatchRAM/blob/master/BrcmPatchRAM/USBDeviceShim.cpp

Capitan: https://github.com/RehabMan/OS-X-BrcmPatchRAM/blob/master/BrcmPatchRAM/USBHostDeviceShim.cpp

Then they determine at compile time what to use in USBDeviceShim.h

#ifndef TARGET_ELCAPITAN
    IOUSBDevice* m_pDevice;
#else
    IOUSBHostDevice* m_pDevice;  // 10.11+
#endif

[Wouter1]

And even though it does not patch the deviceRequest call, there at least is an example of how to use the new deviceRequest

IOReturn USBDeviceShim::getConfiguration(IOService* forClient, UInt8 *configNumber)
{
    uint8_t config  = 0;
    StandardUSB::DeviceRequest request;
    request.bmRequestType = makeDeviceRequestbmRequestType(kRequestDirectionIn, kRequestTypeStandard, kRequestRecipientDevice);
    request.bRequest      = kDeviceRequestGetConfiguration;
    request.wValue        = 0;
    request.wIndex        = 0;
    request.wLength       = sizeof(config);
    uint32_t bytesTransferred = 0;
    IOReturn result = m_pDevice->deviceRequest(forClient, request, &config, bytesTransferred, kUSBHostStandardRequestCompletionTimeout);
    *configNumber = config;
    return result;
}

[Wouter1]

Trying to figure out what the right way is to allocate a wrapper object. new? IOMalloc? OSTypeAlloc? With new I can init it right away but the OSTypeAlloc description suggests there may be problems with it.

[Wouter1]

The OSTypeAlloc refers to OSMetaClassBase. And the doc for that says

should not be subclassed by kernel extensions,
 nor should kernel extensions call its run-time type functions directly.

But the kext is actually using it?

[Wouter1]

https://developer.apple.com/library/mac/documentation/Kernel/Reference/OSObject_reference/ gives explanations.

[Wouter1]

Apparently new is just same as malloc in the kernel. This is what I need but I cant find details or examples yet

Many Libkern and I/O Kit classes define static instance-creation functions (beginning with the word "with") to make construction a one-step process for clients.