[Vm-dev] start up performance regression on Mac OS X

Sat Oct 13 02:38:35 UTC 2018

Hi John,

On Fri, Oct 12, 2018 at 1:46 PM John McIntosh <
johnmci at smalltalkconsulting.com> wrote:

> Ok, well this code comes from the original implementation in 2010.
>
> What it is doing is priming the sound system, by starting up the sound
> api, feeding it silence, then stopping it.
> It was written so that the sound plugin was ready to go when someone used
> the soundPlugin.
> A 500 ms pause on just the first use of sound drove certain musically
> inclined folks crazy.  As you saw "appalling startup performance"
>

Actually I think this is Apple's regression and Apple's bug.  I see a
similar performance regression in Safari.  Open a new tab.  Do a search in
the URL fields.  First, one sees the meatball cursor.  Subsequently one
cannot click any of the links for several seconds.  This is on
Safari Version 12.0 (13606.2.11), macOS High Sierra Version 10.13.6.  Does
anyone else see this or is my system in some strange state?

What could be change by someone with the will to write a bit of code, (then
> test) is to fork off the sound setup message by sending then  "
> setupSoundLogic" (or maybe separate out the logic after the creation of
> the soundInterfaceLogic) on a worker thread, then have a guard mutex on
> the accessor soundInterfaceLogic (just add a explicit soundInterfaceLogic
> accessor to sqSqueakOSXApplication) so that a call to the OSX soundPlugin
> like soundInit can not complete until we have fully created the
> sqSqueakSoundCoreAudio instance.   Perhaps the use of  @synchronized(soundInterfaceLogic)
> {}
>
> This all assumes use of any platform API can be done on a worker thread
> versus the main thread.
>
>
> On Thu, Oct 11, 2018 at 9:41 PM, Eliot Miranda <eliot.miranda at gmail.com>
> wrote:
>
>>
>> Hi All,
>>
>>     it seems due to this code:
>>
>> frame #29: 0x0015358c Squeak`-[sqSqueakOSXApplication
>> setupSoundLogic](self=0x02408810, _cmd="setupSoundLogic") + 412 at
>> sqSqueakOSXApplication.m:152
>>    149 snd_Start(2644, 22050, 1, 0);
>>    150 char silence[10576];
>>    151 bzero(&silence, sizeof(silence));
>> -> 152 snd_PlaySamplesFromAtLength(2644,(usqInt * ) &silence,0);
>>    153 [self.soundInterfaceLogic snd_Stop_Force];
>>    154 }
>>    155
>>
>> who wrote it?  Surely there's a better way of ensuring the sound system
>> is in a silent way...
>>
>> On Thu, Oct 11, 2018 at 9:36 PM Eliot Miranda <eliot.miranda at gmail.com>
>> wrote:
>>
>>> Hi All,
>>>
>>>     in building new VMs today I see appalling startup performance on Mac
>>> OS X.  It seems to be related to event setup and/or sound initialization.
>>> I ran under a debugger and interrupted while the system was (slowly)
>>> launching and both times I saw a similar stack; see below.  So the system
>>> looks to be caught in some kind of initialization loop:
>>>
>>>     frame #7: 0x9331ff16
>>> CoreAudio`HALC_ShellSimpleProxyList::Reconcile(bool, bool) + 646
>>>     frame #8: 0x9331f569 CoreAudio`HALC_ShellPlugIn::ConnectToServer() +
>>> 153
>>>     frame #9: 0x9338904e
>>> CoreAudio`HAL_HardwarePlugIn_InitializeWithObjectID(AudioHardwarePlugInInterface**,
>>> unsigned long) + 78
>>>     frame #10: 0x9331d818 CoreAudio`HALPlugIn::Initialize() + 48
>>>     frame #11: 0x9331c3a0
>>> CoreAudio`HALPlugInManagement::CreateHALPlugIn(HALCFPlugIn const*) + 2048
>>>     frame #12: 0x9331ac08 CoreAudio`HALPlugInManagement::Initialize() +
>>> 552
>>>     frame #13: 0x93317070 CoreAudio`HALSystem::CheckOutInstance() + 190
>>>     frame #14: 0x9331e4bb CoreAudio`AudioObjectGetPropertyData + 81
>>>     frame #15: 0x92643947 AudioToolbox`AQMEIO_HAL::Init() + 201
>>>     frame #16: 0x92643132
>>> AudioToolbox`AQMEIOManager::_FindIOUnit(__CFString const*) + 110
>>>     frame #17: 0x92642f23 AudioToolbox`AQMEDevice::InitPhase2(__CFString
>>> const*) + 239
>>>     frame #18: 0x92642e2e AudioToolbox`AQMixEngine_Single::InitPhase2()
>>> + 24
>>>     frame #19: 0x92642a34
>>> AudioToolbox`AQIONodeManager::_FindAQIONode(bool, __CFString const*) + 154
>>>     frame #20: 0x926426a9
>>> AudioToolbox`AudioQueueObject::DoIONodeConnect(bool) + 963
>>>     frame #21: 0x92715bfe
>>> AudioToolbox`AudioQueueObject::GetIONodeConnection_Init(long&) + 40
>>>     frame #22: 0x9270b7c6
>>> AudioToolbox`AudioQueueObject::GetConverterConnection_Init(long&) + 20
>>>     frame #23: 0x9265a77b
>>> AudioToolbox`AudioQueueObject::AcquirePlayResources() + 215
>>>     frame #24: 0x92709095 AudioToolbox`AudioQueueObject::Prime(unsigned
>>> long, unsigned long&) + 345
>>>     frame #25: 0x9265a571 AudioToolbox`AQServer_Prime + 95
>>>     frame #26: 0x9265a43d AudioToolbox`AudioQueuePrime + 364
>>>     frame #27: 0x0021c841 Squeak`-[sqSqueakSoundCoreAudio
>>> snd_PlaySamplesFromAtLength:arrayIndex:startIndex:](self=0x0262e990,
>>> _cmd="snd_PlaySamplesFromAtLength:arrayIndex:startIndex:", frameCount=2644,
>>> arrayIndex="", startIndex=0) + 481 at sqSqueakSoundCoreAudio.m:319
>>>     frame #28: 0x0021ed8d
>>> Squeak`snd_PlaySamplesFromAtLength(frameCount=2644, arrayIndex=0xbfffb588,
>>> startIndex=0) + 125 at sqSqueakSoundCoreAudioAPI.m:62
>>>     frame #29: 0x0015358c Squeak`-[sqSqueakOSXApplication
>>> setupSoundLogic](self=0x02408810, _cmd="setupSoundLogic") + 412 at
>>> sqSqueakOSXApplication.m:152
>>>     frame #30: 0x0016b5c9 Squeak`-[sqSqueakMainApplication
>>> runSqueak](self=0x02408810, _cmd="runSqueak") + 617 at
>>> sqSqueakMainApplication.m:198
>>>     frame #31: 0x95216299 Foundation`__NSFirePerformWithOrder + 432
>>>     frame #32: 0x9379a496
>>> CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__
>>> + 22
>>>     frame #33: 0x9379a3b2 CoreFoundation`__CFRunLoopDoObservers + 498
>>>     frame #34: 0x9377d7fd CoreFoundation`__CFRunLoopRun + 1661
>>>     frame #35: 0x9377ce51 CoreFoundation`CFRunLoopRunSpecific + 641
>>>     frame #36: 0x9377cbba CoreFoundation`CFRunLoopRunInMode + 122
>>>     frame #37: 0x92d7a37b HIToolbox`RunCurrentEventLoopInMode + 321
>>>     frame #38: 0x92d79f5f HIToolbox`ReceiveNextEventCommon + 454
>>>     frame #39: 0x92d79d7b
>>> HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71
>>>     frame #40: 0x9137ab2d AppKit`_DPSNextEvent + 2101
>>>     frame #41: 0x91aece90 AppKit`-[NSApplication(NSEvent)
>>> _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 2859
>>>     frame #42: 0x91aec35d AppKit`-[NSApplication(NSEvent)
>>> nextEventMatchingMask:untilDate:inMode:dequeue:] + 134
>>>     frame #43: 0x9136fa7d AppKit`-[NSApplication run] + 763
>>>     frame #44: 0x91341b3a AppKit`NSApplicationMain + 1228
>>>     frame #45: 0x0016558b Squeak`main(argc=2, argv=0xbffff624,
>>> envp=0xbffff630) + 91 at main.m:52
>>>     frame #46: 0xa728f611 libdyld.dylib`start + 1
>>>
>>>
>>> I changed sqSqueakOSXApplication.m in August, but only to add some
>>> option processing.  Anyone have any ideas?
>>>
>>> --
>>> _,,,^..^,,,_
>>> best, Eliot
>>>
>>
>>
>> --
>> _,,,^..^,,,_
>> best, Eliot
>>
>>
>
>
> --
> ===========================================================================
> John M. McIntosh. Corporate Smalltalk Consulting Ltd
> https://www.linkedin.com/in/smalltalk
> ===========================================================================
>

-- 
_,,,^..^,,,_
best, Eliot
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20181012/f90e9184/attachment.html>