howto measure time_interval since physical plugin of a USB-gadget ?

=1) The situation: 1A) I make both a "DExt" and a "SDK" for still-imaging-USB-gadgets and MACOS>=14 ,iPADOS>=17

1B) One of the USB-gadgets needs warm_up after PlugIn (i.e End-User-App must know "now-TheMomentOfPlugIn" with precision ~1sec).

=2) The question is how to do "1B" rationally?

=3) My speculative guess: in BSD-descendant I expect existence (somewhere) of a "normal file" through "macports etc", which has normal "file creation time". Such a "file creation time" (accessible better via IORegistryEntry... at SDK-level; possibly via IOUSBHostInterface at DExt-level) is cognitive target of mine.

=4) Additional constraints: Technically absent. I freely modify code either DExt (descendant of IOUSBHostInterface) or SDK-level (IORegistryEntryGetRegistryEntryID, IORegistryEntry...)

Answered by DTS Engineer in 824715022

1B) One of the USB-gadgets needs warm_up after PlugIn (i.e End-User-App must know "now-TheMomentOfPlugIn" with precision ~1sec).

What's you're communication channel with your DEXT? This may not apply in your case, but if you're going through your own UserClient, then the simplest way to handle this is that your DEXT doesn't allow UserClient access until the device is "ready".

=3) My speculative guess: in BSD-descendant I expect existence (somewhere) of a "normal file" through "macports etc", which has normal "file creation time". Such a "file creation time" (accessible better via IORegistryEntry... at SDK-level; possibly via IOUSBHostInterface at DExt-level) is cognitive target of mine.

Nothing like this specifically exists. IOKit doesn't track this on it's own and we don't export a "general" device abstraction to the BSD layer.

=4) Additional constraints: Technically absent. I freely modify code either DExt (descendant of IOUSBHostInterface) or SDK-level (IORegistryEntryGetRegistryEntryID, IORegistryEntry...)

What I would actually do is have your DEXT export this data as a property, which you could then retrieve through the standard IOKit APIs. You could do that as a the date itself, but I would probably do something like an "IsReady" property. Just be aware that key name collisions are entirely possible, so I would use a key name like "<bundle id> IsReady" JUST to be sure I never got a collision.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

1B) One of the USB-gadgets needs warm_up after PlugIn (i.e End-User-App must know "now-TheMomentOfPlugIn" with precision ~1sec).

What's you're communication channel with your DEXT? This may not apply in your case, but if you're going through your own UserClient, then the simplest way to handle this is that your DEXT doesn't allow UserClient access until the device is "ready".

=3) My speculative guess: in BSD-descendant I expect existence (somewhere) of a "normal file" through "macports etc", which has normal "file creation time". Such a "file creation time" (accessible better via IORegistryEntry... at SDK-level; possibly via IOUSBHostInterface at DExt-level) is cognitive target of mine.

Nothing like this specifically exists. IOKit doesn't track this on it's own and we don't export a "general" device abstraction to the BSD layer.

=4) Additional constraints: Technically absent. I freely modify code either DExt (descendant of IOUSBHostInterface) or SDK-level (IORegistryEntryGetRegistryEntryID, IORegistryEntry...)

What I would actually do is have your DEXT export this data as a property, which you could then retrieve through the standard IOKit APIs. You could do that as a the date itself, but I would probably do something like an "IsReady" property. Just be aware that key name collisions are entirely possible, so I would use a key name like "<bundle id> IsReady" JUST to be sure I never got a collision.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Thanks a lot... though... _"What's you're communication channel with your DEXT" "What I would actually do is have your DEXT export this data as a property"

=1) Of course, as any normal programmer, I start any my SW-project from code to save/archive/trace any occasionally required DExt's/UserClient's-datas/events at any moment as properties/keys "[] MyKey=my_value" in Windows-INI-file-format:)

=2) MACOSX14 calls my DExt when I plug one of VID_????,PID_???? (declared in info.plist)

=2a) I easily trace <un>plug events through my short INI-files (and duplicate those via unified Swift's log)

=2b) correct handling of plug/unplug in MAC needs just recording/archiving single value ~"TimeStamp>0" for connected gadget.

=2c) As/if I have my paranoid doubts then I easily & programmatically enumerate relevant system <un>plug-logs (during recent 2..4 hours) via unified Swift log ".system" .

= 3) iPADOS16,17 seemingy has the "physical architectural problem<s>"

= 3a) doesn't call any entry-point in my DExt when I connect relevant VID_????,PID_???? _(unless my UserClient was started manually in advance and is still alive)

= 3b) system log is simply not available programmatically.

= 3c) btw my UserClient's logs from older processID _(from previous sessions) also aren't available (though this is insignificant as I have INI-files to archive/trace logs)

= 4) The fundamental question is that I don't see "any physical/theoretical opportunity to know about <un>plug in iPADOS16/17 _(unless my UserClient is explictly and manually started by the user).

But users normally perer plugin a gadget and then start UserClient in iPAD...

Thanks a lot... though... _"What's you're communication channel with your DEXT" "What I would actually do is have your DEXT export this data as a property"

=1) Of course, as any normal programmer, I start any my SW-project from code to save/archive/trace any occasionally required DExt's/UserClient's-datas/events at any moment as properties/keys "[] MyKey=my_value" in Windows-INI-file-format:)

So, let me start with the basic point here:

=2) MACOSX14 calls my DExt when I plug one of VID_????,PID_???? (declared in info.plist)

The behavior here is actually identical on macOS and iOS. That is, when any device IOKit matching occurs which, in the case of a DEXT, means that your DEXT is eventually loaded and begins executing. Note that DEXT loading is in fact just a specific variation on the IOKit matching process, with the difference being that the IOKit driver your DEXT matching dictionary specified was designed to use the DEXT specific keys to match and interact with your out of kernel DEXT.

Critically, the functionality you're describing here:

=1) Of course, as any normal programmer, I start any my SW-project from code to save/archive/trace any occasionally required DExt's/UserClient's-datas/events at any moment as properties/keys "[] MyKey=my_value" in Windows-INI-file-format:)

Is ONLY occurring because you have an active macOS process which monitored and connected to your DEXT, logged activity from it. The system did not launch that process "on it's own" and if it wasn't running, your DEXT couldn't log. In other words, your ability to log/know information about your DEXT depends on an external user process running which collects the data.

That dynamic is EXACTLY the same on iPadOS. The difference on iPadOS is simply that it provides fewer options for launching code and doesn't provide any option for unbounded execution.

That leads to here:

= 4) The fundamental question is that I don't see "any physical/theoretical opportunity to know about <un>plug in iPADOS16/17 _(unless my UserClient is explictly and manually started by the user). But users normally perer plugin a gadget and then start UserClient in iPAD...

What are you actually trying to learn understand here? If this is about testing and development, then the simplest solution is to bypass the problem and simply test with your app running.

Similarly, this isn't really an issue in development:

= 3b) system log is simply not available programmatically.

...as you can always extract the log through other means (see here) to look at the full log data.

However, if this is about a shipping product then I need a clear picture of what you're actually trying to do and why. In more concrete terms, why are you concerned about your accessory being plugged/unplugged if the user never interacted with your accessory because they never launched your app?

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

= 1) Dear Kevin, after my brief re-check it looks your following statement is 100% wrong in practice: "he behavior here is actually identical on macOS and iOS. That is, when any device IOKit matching occurs which, in the case of a DEXT, means that your DEXT is eventually loaded and begins executing. Note that DEXT loading is in fact just a specific variation on the IOKit matching process, with the difference being that the IOKit driver your DEXT matching dictionary specified was designed to use the DEXT specific keys to match and interact with your out of kernel DEXT."

= 2) In fact

= 2a) In fact the code DExt.cpp:

#define Log(fmt, ...) os_log( OS_LOG_DEFAULT, "RyDD - " fmt "\n", ##__VA_ARGS__ )
bool DExt::init(void) { ....  Log( "init() - Succeed." ); return true; }
kern_return_t DExt::Start_Impl( IOService *AProvider ) { ...  Log( "Start() - Succeed" ); return kIOReturnSuccess; }

= 2b) In fact the console's output (without any active of my process !; fillter "RyDD" ); MAC BOOK M3; MAC OS 14; after power on and plug/unplug a gadget (my DExt is activated)

default	09:46:06.893553+0900	kernel	RyDD - init() - Succeed.
default	09:46:06.893573+0900	kernel	RyDD - Start() - Succeed
default	09:46:06.906789+0900	kernel	RyDD - init() - Succeed.
default	09:46:06.906810+0900	kernel	RyDD - Start() - Succeed```

= 2c) In fact the console's output in iPAD gen5,gen6 nothing (only system logs about USB gadget with certain PID/VID is connected)

= 3) Before talk about further topics we need establish and explain this fact.

clearance_addition to the topic "in fact 2a)": file DExt.iig

  class DExt: public IOUSBHostInterface { public: // IOUSBHostDevice|Interface
    virtual bool init(void) override;
    virtual kern_return_t Start( IOService *AProvider ) override;
   ....

= 2c) In fact the console's output in iPAD gen5,gen6 nothing (only system logs about USB gadget with certain PID/VID is connected)

= 3) Before talk about further topics we need establish and explain this fact.

We're talking about different details here. What I described is the dynamics of how DEXT loading occurs, which is basically identical between macOS and iOS. What you're looking at is what happens to be logged by either system. My own experience has been that the logging is fairly similar between the two system though, admittedly, it's been awhile since I specifically looked at this on iOS.

Looking at the iPadOS case in detail:

= 2c) In fact the console's output in iPAD gen5,gen6 nothing (only system logs about USB gadget with certain PID/VID is connected)

  • Checking the obvious, I assume you've enabled your DEXT in Settings.app? Note that I've seen cases where the setting doesn't show up properly in development builds and my experience has been that adding your own preference bundle (so your app always appears in settings) resolves the issue.

  • Just to clarify, are you sure your DEXT IS in fact loading? That is, is the issue here that you're missing log data or is it that your DEXT isn't loading at all? Is your app able to connect to it on iPadOS?

  • What does the full console log show? Does it show your DEXT being enabled when you enable it through settings? What kind of device is this and is it possible that some other driver (possibly the system default) has seized the device?

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Dear Kevin, after your message I repeated check 1 time in MAC and 3 times in iPAD. I see possible clue of the difference between MACBook and iPAD17.

MACBook

default	09:16:03.095874+0900	kernel	LQM-WIFI: (HighBand)  rxNotPrimary20s=0 ucodeLateDrop=0 rxInvalidUcodeLateWrongMACPHY=0 rxLate30us=0 rxLegacyFrmInvalid=0 txSifsErr=0 ooseqMacSusp=0
default	09:16:03.101392+0900	kernel	LQM-WIFI: Dynamic BW Stats: TxRTS [0,  0,  0,  0]   RxRTS [0,  0,  0,  0]   TxCTS [0,  0,  0,  0]   RxCTS [0,  0,  0,  0]
default	09:16:03.101408+0900	kernel	LQM-WIFI: Dynamic BW Stats: TxMPDU [0,  0,  0,  0]   RxMPDU [0,  0,  0,  0]
default	09:16:03.487406+0900	kernel	LQM-WIFI-CT: ofdmDesense=0 bphyDesense=0 reason=0x0
default	09:16:05.906054+0900	kernel	AppleUSB20HubPort@01143000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumerated 0x3488/0002/0100 (EzSensor XHD / 5) at 480 Mbps
default	09:16:05.909537+0900	kernel	EzSensor XHD@01143000: IOUSBHostDevice::setConfigurationGated: AppleUSBHostCompositeDevice selected configuration 1
default	09:16:05.917779+0900	kernel	Driver com.rayence.dextsample.driver has crashed 0 time(s)
default	09:16:05.917843+0900	kernel	DK: DExt-0x100000f10 waiting for server com.rayence.dextsample.driver-100000f10
default	09:16:05.919192+0900	kernelmanagerd	Found 1 dexts with bundle identifier com.rayence.dextsample.driver
default	09:16:05.919435+0900	kernelmanagerd	Using unique id 41cecb3133c7084f322eefd5b38f4fc3b3a7b52b7053d3746b2324423b9eab86 to pick dext matching bundle identifier com.rayence.dextsample.driver
default	09:16:05.920672+0900	kernelmanagerd	Picked matching dext for bundle identifier com.rayence.dextsample.driver: Dext com.rayence.dextsample.driver v1 in executable dext bundle com.rayence.dextsample.driver at /Library/SystemExtensions/CACFB48B-C6D6-46D2-8D74-5FA4C7802E4A/com.rayence.dextsample.driver.dext
default	09:16:05.921375+0900	kernelmanagerd	DextRecordTable read from plist: {

// — manual note: I have 2 ~identical <by the binaries> DExts in 2 SDK-sample bundles
// — com.rayence.dexta.driver - SDK-project#1
// — com.rayence.dextsample.driver - SDK-project#2
// — everything works without a conflicts or a quirk 
// — technically I don’t care which of my DExts initializes 1st, which 2nd in this workflow (as IOKITmatching always is logical)

com.rayence.dexta.driver: 
	MRS-> Optional(( path: /Library/SystemExtensions/304D47CF-904A-44D5-992C-332B013492D8/com.rayence.dexta.driver.dext; state: loaded )) 
history-> [
	( path: /Library/SystemExtensions/304D47CF-904A-44D5-992C-332B013492D8/com.rayence.dexta.driver.dext; state: loaded )
]
com.rayence.dextsample.driver: 
	MRS-> Optional(( path: /Library/SystemExtensions/CACFB48B-C6D6-46D2-8D74-5FA4C7802E4A/com.rayence.dextsample.driver.dext; state: loaded )) 
history-> [
	( path: /Library/SystemExtensions/CACFB48B-C6D6-46D2-8D74-5FA4C7802E4A/com.rayence.dextsample.driver.dext; state: loaded )
]
org.pqrs.Karabiner-DriverKit-VirtualHIDDevice: 
	MRS-> Optional(( path: /Library/SystemExtensions/59623BBE-793E-4E5C-B153-9DACFDA66EBC/org.pqrs.Karabiner-DriverKit-VirtualHIDDevice.dext; state: loaded )) 
history-> [
	( path: /Library/SystemExtensions/59623BBE-793E-4E5C-B153-9DACFDA66EBC/org.pqrs.Karabiner-DriverKit-VirtualHIDDevice.dext; state: loaded )
]
}
default	09:16:05.921588+0900	kernelmanagerd	Launching driver extension: Dext com.rayence.dextsample.driver v1 in executable dext bundle com.rayence.dextsample.driver at /Library/SystemExtensions/CACFB48B-C6D6-46D2-8D74-5FA4C7802E4A/com.rayence.dextsample.driver.dext
default	09:16:05.933078+0900	kernel	/Library/SystemExtensions/CACFB48B-C6D6-46D2-8D74-5FA4C7802E4A/com.rayence.dextsample.driver.dext/com.rayence.dextsample.driver[849] ==> com.apple.dext
default	09:16:05.933408+0900	kernelmanagerd	<OSLaunchdJob | handle=6B6CE5C2-010E-4309-9140-F7EE365E3D74>: submitAndStart completed, info=running, pid=849
default	09:16:05.933603+0900	kernelmanagerd	Received kext load notification: com.rayence.dextsample.driver
default	09:16:05.935569+0900	kernel	<private>
…
default	09:16:05.936737+0900	kernel	<private>
default	09:16:05.937925+0900	kernel	RyDD - init() - Succeed.
default	09:16:05.937949+0900	kernel	RyDD - Start() - Succeed
default	09:16:05.937967+0900	kernel	DK: 
…   

Log of a "smooth run" of iPAD17 in the next message.

Log in iPAD17 (section A)

DExt's entry points are called in this sample within <1sec after plugin (1 or 3 times). 2 of 3 times those are called >5 sec later. Here are messages "change handling USB2<=>USB3" (the gadget is actually USB2)

efault	09:42:58.561261+0900	kernel	IOAccessoryManagerUSBC::setLDCMPin(): ldcmPin: 2 [Trace]
default	09:42:58.561335+0900	kernel	IOAccessoryManagerUSBC::setLDCMPin(): ldcmPin: 2 [Trace]
default	09:42:58.561851+0900	kernel	IOPort::setLDCMState(): [Port-USB-C@1] setLDCMState: 3 [Measure]
default	09:42:58.683860+0900	kernel	wlan0:com.apple.p2p: reportDataPathEvents[6702]: WiFi default	09:42:58.747963+0900	kernel	IOPortTransportState::handleStateChange(): [Port-USB-C@1: USB3] Handling state change...
default	09:42:58.748028+0900	kernel	IOServiceNotificationManager::sendMessages(): [Port-USB-C@1/USB3] Sending 2 message(s)... (m_propertyChanged: YES)
default	09:42:58.748210+0900	kernel	IOPortTransportState::handleStateChange(): [Port-USB-C@1: USB2] Handling state change...
default	09:42:58.748275+0900	kernel	IOServiceNotificationManager::sendMessages(): [Port-USB-C@1/USB2] Sending 1 message(s)... (m_propertyChanged: NO)
default	09:42:58.748367+0900	kernel	IOAccessoryTRM::_processNotifications(): Processing notifications...
default	09:42:58.748836+0900	kernel	IOAccessoryPowerSource::createPowerSourceItemsInternal(): id:0x100000797, owner=<private> tag=<private> itemSet=0x0 removeTagSet=0x0...
default	09:42:59.653465+0900	kernel	IOPortTransportState::registerService(): [Port-USB-C@1: USB2] Registering service USB2@(null)... (transportType: 2, provider: Port-USB-C@1)
default	09:42:59.653496+0900	kernel	IOPortTransportState::setNominalSignalingFrequencies(): [Port-USB-C@1: USB2] Setting nominal signaling frequencies... (nominalSignalingFrequenciesHz: YES, nominalSignalingFrequenciesHz.count: 3)
default	09:42:59.653729+0900	kernel	IOServiceNotificationManager::sendMessages(): [Port-USB-C@1] Sending 2 message(s)... (m_propertyChanged: YES)
default	09:42:59.816095+0900	kernel	IOPortTransportState::setNominalSignalingFrequencies(): [Port-USB-C@1: USB2] Setting nominal signaling frequencies... (nominalSignalingFrequenciesHz: YES, nominalSignalingFrequenciesHz.count: 1)
default	09:42:59.822846+0900	kernel	usb-drd0-port-hs@00100000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumerated 0x3488/0002/0100 (EzSensor XHD / 1) at 480 Mbps
default	09:42:59.822981+0900	kernel	IOPortTransportState::handleMetadataChanges(): [Port-USB-C@1: USB2] Handling metadata changes... (shouldReregisterService: NO)
default	09:42:59.823014+0900	kernel	IOPortTransportState::_updatePreDefinedMetadataProperties(): [Port-USB-C@1: USB2] Updating pre-defined metadata properties...
default	09:42:59.823106+0900	kernel	IOServiceNotificationManager::handleServiceReregistration(): [Port-USB-C@1/USB2] Re-registering service...
default	09:42:59.823152+0900	kernel	IOPortTransportState::registerService(): [Port-USB-C@1: USB2] Registering service USB2@(null)... (transportType: 2, provider: Port-USB-C@1)
default	09:42:59.823194+0900	kernel	IOPortTransportState::setHash(): [Port-USB-C@1: USB2] hash: YES
default	09:42:59.823661+0900	kernel	ACM: logRecord: acc-cache-check: unexpired record found: tm=1739493764 hash(32)=<8f5d391e3e776d68942e0bd0f157f256c0a55b61e3999a4324197b39d62ed982> data(4)=<02000000> group(16)=<b93f9cddbcce4141a11f8a22ba3f7290>.
default	09:42:59.823755+0900	kernel	IOPortTransportState::_updateHashStatus_block_invoke(): [Port-USB-C@1: USB2] m_hashStatus: 0 -> 3 [Not Set -> Cached]
default	09:42:59.823868+0900	kernel	ACM: logRecord: acc-cache-add: replacing existing record: tm=1739493764 hash(32)=<8f5d391e3e776d68942e0bd0f157f256c0a55b61e3999a4324197b39d62ed982> data(4)=<02000000> group(16)=<b93f9cddbcce4141a11f8a22ba3f7290>.
default	09:42:59.823904+0900	kernel	ACM: logRecord: acc-cache-add: adding record: tm=1739493780 hash(32)=<8f5d391e3e776d68942e0bd0f157f256c0a55b61e3999a4324197b39d62ed982> data(4)=<02000000> group(16)=<42f12b200cf1442b84aad85be16fce1d>.
default	09:42:59.824063+0900	kernel	ACMTRM-S: setData: saving *acc-cache* (dataLen=5384) in 3 seconds (fullSync: NO -> NO).
default	09:42:59.824166+0900	kernel	ACM: logRecord: acc-cache-check: unexpired record found: tm=1739493780 hash(32)=<8f5d391e3e776d68942e0bd0f157f256c0a55b61e3999a4324197b39d62ed982> data(4)=<02000000> group(16)=<42f12b200cf1442b84aad85be16fce1d>.
default	09:42:59.824256+0900	kernel	IOPortTransportState::_updateTRMState(): [Port-USB-C@1: USB2] Updating TRM state...
default	09:42:59.824287+0900	kernel	IOPortTransportStateUSB::calculateAuthorizationState(): [Port-USB-C@1: USB2] Calculating authorization state...
default	09:42:59.824316+0900	kernel	IOPortTransportState::calculateAuthorizationState(): [Port-USB-C@1: USB2] Calculating authorization state...
default	09:42:59.824369+0900	kernel	IOPortTransportState::calculateAuthorizationState_block_invoke(): [Port-USB-C@1: USB2] *** UNRT ***
default	09:42:59.824516+0900	kernel	IOServiceNotificationManager::sendMessages(): [Port-USB-C@1/USB2] Sending 2 message(s)... (m_propertyChanged: YES)
default	09:42:59.824706+0900	kernel	AppleNotificationQueue::processNotifications(): Processing 1 notification(s)...
default	09:42:59.824755+0900	kernel	AppleNotificationQueue::_handleNotifications(): Handling notifications...
default	09:42:59.827337+0900	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Client <private> is requesting 500mA wake and 0mA sleep for port 0
default	09:42:59.827435+0900	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Client <private> port 0 has EDT current overrides of 1500mA wake and 1500mA sleep
default	09:42:59.827474+0900	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Granting 500mA wake and 0mA sleep based on override for port 0
default	09:42:59.827514+0900	kernel	EzSensor XHD@00100000: IOUSBHostDevice::setConfigurationGated: AppleUSBHostCompositeDevice selected configuration 1
default	09:42:59.837877+0900	kernel	Driver com.rayence.dextsample.driver has crashed 4 time(s)
default	09:42:59.837935+0900	kernel	DK: DExt-0x100000e30 waiting for server com.rayence.dextsample.driver-100000e30
default	09:42:59.859193+0900	kernel	/private/var/db/driverkitd/SystemExtensions/9F631B30-94C9-49DE-8BB5-04D342370774/com.rayence.dextsample.driver.dext/com.rayence.dextsample.driver[481] ==> com.apple.dext
default	09:42:59.868133+0900	kernel	DK: com.rayence.dextsample.driver[481] has team identifier PZEDDMJXDA
default	09:42:59.868340+0900	kernel	<private>
…
default	09:42:59.869858+0900	kernel	<private>
default	09:42:59.870840+0900	kernel	RyDD - init() - Succeed.
default	09:42:59.870851+0900	kernel	RyDD - Start() - Succeed

The note to previous "long log": "RyDD - init() - Succeed." appeared

<1 sec after physical plugin 1 time of 3

~10 sec after physical plugin 1 time of 3

~5 sec after physical plugin 1 time of 3

I shall confirm that (from the point of view of SW-logs):

  • MACOSX14 and iPADOS17 behave quite similar;
  • my previous experiment (wich shows those 're different) was "technical mistake";
  • manual start of my sample UserClient isn't "necessary in fact" in iPAD17 to trigger the invocation of "RyDD - init() -" of "activated DExt";
  • I shall note that "manual start of my sample UserClient avoids occasional huge delays with the invocation"; but this likely is HW-issue.

= Hence <in theory> (this could be "best possible answer" at this moment): I could keep timestamp of "RyDD - init() -" in my "Dext_Vars" and then pass it later to UserClient.

--- addition question ---

If such a subject could be treated as an "off-topic against the theme in starting message" then please ignore the following

I also shall appreciate if you may occasionally provide "extended comment" about: what could be done to investigate possible cause<s> of SW|HW-delays between physical plugin and invocation of "RyDD - init() -" in iPADgen5 M1 OS16, iPADgen6 M2 OS17 ?

--- end of addition question ---

First off, a quick disclaimer. I have not spent a great deal of time closely looking at these issues, my recommendations here are based on how I would generally approach the issue not any specific/detailed answer.

Getting into the specifics:

I also shall appreciate if you may occasionally provide "extended comment" about: what could be done to investigate possible cause<s> of SW|HW-delays between physical plugin and invocation of "RyDD - init() -" in iPADgen5 M1 OS16, iPADgen6 M2 OS17 ?

The first thing to look at here is making sure you understand the details of exactly what's going on and that you're looking at a "real" problem. For example (and I have not tested this), I think it's very likely that if you plug in a bus powered accessory into a sleeping iPad, then that could delay accessory initialization. There's not particular mystery there- the device is a low power state and that's delayed detection. The behavior here may also vary based on configuration like the locked accessory access setting.

In addition, it's VERY easy to accidentally introduce significant external configuration differences without realizing you'd done so. For example, I wouldn't be surprised if a "basic" comparison between a MacMini and iPad Pro showed the MacMini bring the accessory "up" significantly faster. That's because the iPad Pro's flow looked something like:

  1. Plug in device and determine whether to initialize the port as Thunderbolt or USB.

  2. Initialize the base USB implementation.

  3. Determine whether the iPad should come in device or host mode.

  4. Initialize the iPad as the USB Host Controller.

  5. Connect the configure the device.

...but the MacMini actually STARTED at #5 because the keyboard and mouse you were using to control the computer had already taken care of 1 - 4 before the test even started. I used Thunderbolt/USB-C here, but exactly the same process happens on lightning.

This dynamic also mean that I think you could induce an increased delay on iPad OS if you timed things "correctly" when rapidly plugging/unplugging the accessory. The flow above has to start over again for every plug event, but it can't start until the previous session finishes.

Digging into things further, this message pointed at yet another factor:

default	09:42:58.561335+0900	kernel	IOAccessoryManagerUSBC::setLDCMPin(): ldcmPin: 2 [Trace]

The "LD" there stands for "Liquid Detection", meaning the system that tries to detect liquid and shut the port down to prevent port damage.

All of these delays are hard to quantify, but their obviously not "zero".

With all that background context, the first question you need to ask here is are you investigating this as a hardware problem or a software problem. This is well outside my area of expertise, but it's certainly possible for hardware level issues like wiring, plug, or electrical issues to create these kinds of delays. However, that's a completely different class of investigation and testing than this forum can help with.

However, on the software side the question you need to answer isn't "are there delays" but is actually the more specific "are there that I can do anything about"?

For that question, what I would actually do is connect the iPad to a powered USB hub, then do all of my plug testing through that powered USB hub and not directly through the iPad port. That means you're always starting at #5 above and should remove most of the uncontrollable factor's I listed above. I also think you'll find that the variable delays largely disappear, particularly the very large delays multi-second delays.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Accepted Answer

Dear Kevin, thank you!
This topic was caused by my experiment, that under the same work-flow the same USB2 gadgets (which FWs follows basic of SDKs CypEZFX2,CypEZFX3, AnDevBlackFn; follws closely enough, as far as I may "kenne maine Pappenheimers"...).

  • in Windows,Android,MACOSX behave as expecting;
  • in tested iPADgen5,gen6 have large delay between physical plugin and invocation of DExt's entry-points

Then I wrongly supposed that iPadOS16,17 needs to run UserClientBundle to trigger invocation of DExt's entry-points. Thanks to your clearance, the issue is "resolved" from the SW-point-of-view. From this point of view, iPadOS16,17 seemingly behavs completely|quite similar to MACOSX.

-- here is the summary to close this topic as "answered" --

"best answer_approach" is "timestamp of one of the two DExt's entry-points" (both entry-points are ~equivalent here):

  class DExt: public IOUSBHostInterface { public: //  -- file DExt.iig;  IOUSBHostDevice wasn't tested within this scope
    virtual bool init(void) override;
    virtual kern_return_t Start( IOService *AProvider ) override;
... };

= Stipulation 1) This is answer for ~timeflow:

  • MAC/iPAD power_on
  • 1st plugin of the gadget
  • 1st-invocation of the enty-point<s>
  • 1st start of respective UserClentBundle.

This fixes the principal issue, when right_minded_user plugs warmup_need_gadget before start respective UserClientBundle.

= Stipulation 2) An instance of the "class DExt:" could be destroyed/re-created many times (either by unplug or by kill/termination of respective UserClentBundle).

= Stipulation 3) To fix timeflows with "Stipulation 2", UserClentBundle|EndUserApp should count:

  • it's own terminations
  • disconnection_events from it's own DExt.

= Stipulation 4) As an (plain) alternative for MACOSX only, EndUserApp might just enumerate|parse system_logs.

howto measure time_interval since physical plugin of a USB-gadget ?
 
 
Q