start up performance regression on Mac OS X

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

start up performance regression on Mac OS X

Eliot Miranda-2
 
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
Reply | Threaded
Open this post in threaded view
|

Re: start up performance regression on Mac OS X

Eliot Miranda-2
 
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 <[hidden email]> 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
Reply | Threaded
Open this post in threaded view
|

Re: start up performance regression on Mac OS X

johnmci
 
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"


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 <[hidden email]> 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 <[hidden email]> 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
===========================================================================
Reply | Threaded
Open this post in threaded view
|

Re: start up performance regression on Mac OS X

Eliot Miranda-2
 
Hi John,

On Fri, Oct 12, 2018 at 1:46 PM John McIntosh <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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
Reply | Threaded
Open this post in threaded view
|

Re: start up performance regression on Mac OS X

Eliot Miranda-2
 


On Fri, Oct 12, 2018 at 7:38 PM Eliot Miranda <[hidden email]> wrote:
Hi John,

On Fri, Oct 12, 2018 at 1:46 PM John McIntosh <[hidden email]> 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?

Indeed, fixed by a reboot.  This is some weird state the sound system gets into when switching between an Apple cinema display, some bluetooth headphones/microphones and AirPlay.  Sorry about the noice.

So John, if I understand correctly the code in the VM does actually cause a 0.5 second startup delay.  That's, um, undesirable, to say the least.  I agree that we should fix this but is the complexity you outline below necessary?  Isn't there some kind of sound reset call in the API?
 


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 <[hidden email]> 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 <[hidden email]> 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


--
_,,,^..^,,,_
best, Eliot