Anyone else seen crashes like these ?
Hi, I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles. For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly). Here is a crash dump from today (fresh image/vm from WE, nothing special loaded). Related to scheduling ? Event handling ?
On Mon, Nov 12, 2018 at 2:37 PM Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
Hi, I switched to an macOS at the beginning of October and since I often have this kind of behavior.
-- Cyril Ferlicot https://ferlicot.fr
You didnât say it, but I think implied that this is new to P7? I donât get it on P6, and havenât noticed it in earlier P7 images. But havenât extensively used a newer P7 image. Tim Sent from my iPhone
On 12 Nov 2018, at 21:47, Cyril Ferlicot <cyril.ferlicot@gmail.com> wrote:
On Mon, Nov 12, 2018 at 2:37 PM Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
Hi,
I switched to an macOS at the beginning of October and since I often have this kind of behavior.
-- Cyril Ferlicot https://ferlicot.fr
On Mon, 12 Nov 2018 at 21:37, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
Just to confirm, you mean your laptop sleep/wake cycle. On my Window 10 laptop I do the same quite often with no problems.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
In trying to understand the last few moments, is the recent primitives list strongly ordered in time?... Most recent primitives signal nowTick primSignal:atUTCMicroseconds: wait millisecondClockValue @ actualScreenSize Starting at #actualScreenSize, instrumenting the code by adding... Transcript crShow: thisContext sender printString. indicates the following call chain... DisplayScreen-class>>actualScreenSize MorphicUIManager>>checkForNewDisplaySize DisplayScreen class>>checkForNewScreenSize WorldState>>doOneCycleNowFor: WorldState>>doOneCycleFor: WorldMorph>>doOneCycle WorldMorph class>>doOneCycle MorphicUIManager>>spawnNewProcess In detail from a static analysis of the code... > WorldState>>doOneCycleNowFor: > DisplayScreen class>>checkForNewScreenSize > MorphicUIManager>>checkForNewDisplaySize > DisplayScreen-class>>actualScreenSize PRIMITIVE < MorphicUIManager>>checkForNewDisplaySize < DisplayScreen class>>checkForNewScreenSize < WorldState>>doOneCycleNowFor < WorldState>>doOneCycleFor: < WorldMorph>>doOneCycle < WorldMorph class>>doOneCycle < MorphicUIManager>>spawnNewProcess
WorldMorph class>>doOneCycle > WorldMorph>>doOneCycle > WorldState>>doOneCycleNowFor: > WorldState>>interCyclePause: > Time>>millisecondClockValue PRIMITIVE < WorldState>>interCyclePause: > Delay>>schedule > DelaySemaphoreScheduler>>schedule: > Semaphore>>wait PRIMITIVE "readyToSchedule variable" > Semaphore>>signal PRIMITIVE "timingSemaphore variable" NOT RECORDED
maybe context change causes this to be recorded later in "Most recent primitives" > DelayMicrosecondTicker>>waitForUserSignalled:orExpired: waking up from Semaphore>>wait the primSignal:atUTCMicroseconds: PRIMITIVE immediately before the #wait seems to have been logged now in "Most recent primitives" > DelaySemaphoreScheduler>>scheduleAtTimingPriority > Semaphore>>signal PRIMITIVE "readyToSchedule variable" seems to have not been recorded in "Most recent primitives" > DelayBasicScheduler>>scheduleAtTimingPriority < DelaySemaphoreScheduler>>scheduleAtTimingPriority < DelayBasicScheduler>>runBackendLoopAtTimingPriority > DelayMicrosecondTicker>>nowTick PRIMITIVE > Delay>>timingPrioritySignalExpired > Semaphore>>signal PRIMITIVE "delaySemaphore variable" CRASH Smalltalk stack dump: 0x7ffee21d7138 M Delay>timingPrioritySignalExpired 0x113e3b138: a(n) Delay 0x7ffee21d7170 M [] in DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x11453b8c0: a(n) DelaySemaphoreScheduler 0x1169f51c8 s BlockClosure>ensure: 0x1169f5828 s DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x1169f5c38 s [] in DelaySemaphoreScheduler(DelayBasicScheduler)>startTimerEventLoopPriority: 0x1169fae10 s [] in BlockClosure>newProcess The only reason I can think that last semaphore call would be a problem is if variable delaySemaphore was not a Semaphore, but the C stack backtrace doesn't look like it crashes in the Semaphore handling. Its perhaps co-incidental with delay scheduling code is invoked fairly often, that its the current process when this crash occurs. To hep isolate the failure point, I would considering copying #nowTIck to a multiple series like... #nowTick1 #nowTick2 #nowTick3 etc so that all of the sender sites can be made distinct. And maybe the same for #signal senders within the delay scheduling code. One side-curiousity is I can't see where the primitive #@ is being called from. Does it indicate some loop as its trying to determine To me the "vmIOProcessEvents" in the C backtrace with a fairly deep stack into the AppKit framework indicates its related to event handling. cheers -ben
I meant to also post a link showing the pattern of the recent primitives... https://docs.google.com/spreadsheets/d/1QzY8iL_3kvHJg1xMg1yvCFzDpQf3Tl9zuVkz... On Tue, 13 Nov 2018 at 00:50, Ben Coman <btc@openinworld.com> wrote:
On Mon, 12 Nov 2018 at 21:37, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
Just to confirm, you mean your laptop sleep/wake cycle. On my Window 10 laptop I do the same quite often with no problems.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
In trying to understand the last few moments, is the recent primitives list strongly ordered in time?... Most recent primitives signal nowTick primSignal:atUTCMicroseconds: wait millisecondClockValue @ actualScreenSize
Starting at #actualScreenSize, instrumenting the code by adding... Transcript crShow: thisContext sender printString. indicates the following call chain... DisplayScreen-class>>actualScreenSize MorphicUIManager>>checkForNewDisplaySize DisplayScreen class>>checkForNewScreenSize WorldState>>doOneCycleNowFor: WorldState>>doOneCycleFor: WorldMorph>>doOneCycle WorldMorph class>>doOneCycle MorphicUIManager>>spawnNewProcess
In detail from a static analysis of the code... > WorldState>>doOneCycleNowFor: > DisplayScreen class>>checkForNewScreenSize > MorphicUIManager>>checkForNewDisplaySize > DisplayScreen-class>>actualScreenSize PRIMITIVE < MorphicUIManager>>checkForNewDisplaySize < DisplayScreen class>>checkForNewScreenSize < WorldState>>doOneCycleNowFor < WorldState>>doOneCycleFor: < WorldMorph>>doOneCycle < WorldMorph class>>doOneCycle < MorphicUIManager>>spawnNewProcess
WorldMorph class>>doOneCycle > WorldMorph>>doOneCycle > WorldState>>doOneCycleNowFor: > WorldState>>interCyclePause: > Time>>millisecondClockValue PRIMITIVE < WorldState>>interCyclePause: > Delay>>schedule > DelaySemaphoreScheduler>>schedule: > Semaphore>>wait PRIMITIVE "readyToSchedule variable" > Semaphore>>signal PRIMITIVE "timingSemaphore variable" NOT RECORDED
maybe context change causes this to be recorded later in "Most recent primitives" > DelayMicrosecondTicker>>waitForUserSignalled:orExpired: waking up from Semaphore>>wait the primSignal:atUTCMicroseconds: PRIMITIVE immediately before the #wait seems to have been logged now in "Most recent primitives" > DelaySemaphoreScheduler>>scheduleAtTimingPriority > Semaphore>>signal PRIMITIVE "readyToSchedule variable" seems to have not been recorded in "Most recent primitives" > DelayBasicScheduler>>scheduleAtTimingPriority < DelaySemaphoreScheduler>>scheduleAtTimingPriority < DelayBasicScheduler>>runBackendLoopAtTimingPriority > DelayMicrosecondTicker>>nowTick PRIMITIVE > Delay>>timingPrioritySignalExpired > Semaphore>>signal PRIMITIVE "delaySemaphore variable" CRASH
Smalltalk stack dump: 0x7ffee21d7138 M Delay>timingPrioritySignalExpired 0x113e3b138: a(n) Delay 0x7ffee21d7170 M [] in DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x11453b8c0: a(n) DelaySemaphoreScheduler 0x1169f51c8 s BlockClosure>ensure: 0x1169f5828 s DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x1169f5c38 s [] in DelaySemaphoreScheduler(DelayBasicScheduler)>startTimerEventLoopPriority: 0x1169fae10 s [] in BlockClosure>newProcess
The only reason I can think that last semaphore call would be a problem is if variable delaySemaphore was not a Semaphore, but the C stack backtrace doesn't look like it crashes in the Semaphore handling. Its perhaps co-incidental with delay scheduling code is invoked fairly often, that its the current process when this crash occurs.
To hep isolate the failure point, I would considering copying #nowTIck to a multiple series like... #nowTick1 #nowTick2 #nowTick3 etc so that all of the sender sites can be made distinct. And maybe the same for #signal senders within the delay scheduling code.
One side-curiousity is I can't see where the primitive #@ is being called from. Does it indicate some loop as its trying to determine
To me the "vmIOProcessEvents" in the C backtrace with a fairly deep stack into the AppKit framework indicates its related to event handling.
cheers -ben
Yes I mean laptop sleep/wake. Thanks for looking into this. But I think the first step is to see if this is repeatable for someone else. It is probably some graphics primitive rather than scheduling (I am guessing here). I just got it again: VM: 201806281256 https://github.com/OpenSmalltalk/opensmalltalk-vm.git Date: Thu Jun 28 14:56:30 2018 CommitHash: a8a1dc1 Plugins: 201806281256 https://github.com/OpenSmalltalk/opensmalltalk-vm.git C stack backtrace & registers: rax 0x00000001136aa000 rbx 0x0000000129e014e0 rcx 0x0000000000000020 rdx 0x0000000000000ca0 rdi 0x00000001136abb20 rsi 0x00000001136abb20 rbp 0x00007ffeea3f98b0 rsp 0x00007ffeea3f98b0 r8 0x0000000000000006 r9 0x0000000000000006 r10 0x00000000000010bc r11 0xffffffffe98a8b20 r12 0x000000000000047f r13 0x0000000000002800 r14 0x00000001136aa000 r15 0x0000000000000000 rip 0x00007fff6e752e4d 0 libsystem_platform.dylib 0x00007fff6e752e4d _platform_memmove$VARIANT$Haswell + 365 1 Pharo 0x00000001058574f0 reportStackState + 952 2 Pharo 0x0000000105857837 sigsegv + 176 3 libsystem_platform.dylib 0x00007fff6e755b3d _sigtramp + 29 4 ??? 0x0000000000000000 0x0 + 0 5 AppleIntelKBLGraphicsGLDriver 0x00007fff39b6164f glrUpdateTexture + 8979 6 libGPUSupportMercury.dylib 0x00007fff5ce6f79d gpusLoadCurrentTextures + 591 7 AppleIntelKBLGraphicsGLDriver 0x00007fff39b50711 updateDispatch + 663 8 GLEngine 0x00007fff4b5d5078 gleDoDrawDispatchCore + 629 9 GLEngine 0x00007fff4b579369 glDrawArraysInstanced_STD_Exec + 264 10 GLEngine 0x00007fff4b57925a glDrawArrays_UnpackThread + 40 11 GLEngine 0x00007fff4b5d0ce1 gleCmdProcessor + 77 12 libdispatch.dylib 0x00007fff6e51ddcf _dispatch_client_callout + 8 13 libdispatch.dylib 0x00007fff6e529a2c _dispatch_lane_barrier_sync_invoke_and_complete + 60 14 GLEngine 0x00007fff4b527b85 glFlush_ExecThread + 15 15 Pharo 0x0000000105851b09 -[sqSqueakOSXOpenGLView drawRect:flush:] + 301 16 Pharo 0x00000001058519d6 -[sqSqueakOSXOpenGLView drawRect:] + 43 17 AppKit 0x00007fff3ea0a755 _NSViewDrawRect + 66 18 AppKit 0x00007fff3e9f5552 -[NSView _drawRect:clip:] + 1745 19 AppKit 0x00007fff3e9f43f3 -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:] + 1400 20 AppKit 0x00007fff3e9f48b9 -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:] + 2622 21 AppKit 0x00007fff3e9f24f8 -[NSView _recursiveDisplayRectIfNeededIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:topView:] + 938 22 AppKit 0x00007fff3e9f2128 -[NSThemeFrame _recursiveDisplayRectIfNeededIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:topView:] + 65 23 AppKit 0x00007fff3e9efa5a -[NSView _oldDisplayRectIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:] + 1887 24 AppKit 0x00007fff3e9ef099 -[NSView _displayRectIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:] + 253 25 AppKit 0x00007fff3e9ebc86 -[NSView displayIfNeeded] + 1300 26 AppKit 0x00007fff3e9e8a20 -[NSWindow displayIfNeeded] + 283 27 AppKit 0x00007fff3e9e885f __NSWindowGetDisplayCycleObserverForDisplay_block_invoke + 722 28 AppKit 0x00007fff3e9e3966 NSDisplayCycleObserverInvoke + 170 29 AppKit 0x00007fff3e9e34db NSDisplayCycleFlush + 1073 30 QuartzCore 0x00007fff4c3321b3 _ZN2CA11Transaction19run_commit_handlersE18CATransactionPhase + 49 31 QuartzCore 0x00007fff4c331b7a _ZN2CA11Transaction6commitEv + 186 32 AppKit 0x00007fff3e9e2e41 __65+[CATransaction(NSCATransaction) NS_setFlushesWithDisplayRefresh]_block_invoke + 274 33 CoreFoundation 0x00007fff413e86ad __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__ + 23 34 CoreFoundation 0x00007fff413e85e2 __CFRunLoopDoObservers + 452 35 CoreFoundation 0x00007fff4138a109 __CFRunLoopRun + 1166 36 CoreFoundation 0x00007fff41389a28 CFRunLoopRunSpecific + 463 37 Foundation 0x00007fff436f03ba -[NSRunLoop(NSRunLoop) runMode:beforeDate:] + 280 38 Pharo 0x0000000105858297 -[sqSqueakMainApplication(events) pumpRunLoop] + 103 39 Pharo 0x000000010584c2bd -[sqSqueakOSXApplication(events) pumpRunLoop] + 43 40 Pharo 0x0000000105855628 vmIOProcessEvents + 255 41 Pharo 0x00000001058556a7 ioProcessEvents + 56 42 Pharo 0x00000001057e15ba checkForEventsMayContextSwitch + 760 43 Pharo 0x00000001057e54ca ceStackOverflow + 110 44 ??? 0x000000010c73c5b3 0x0 + 4503881139 45 Pharo 0x00000001057d0d41 interpret + 631 46 Pharo 0x0000000105858c65 -[sqSqueakMainApplication runSqueak] + 393 47 Foundation 0x00007fff437fbc73 __NSFirePerformWithOrder + 381 48 CoreFoundation 0x00007fff413e86ad __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__ + 23 49 CoreFoundation 0x00007fff413e85e2 __CFRunLoopDoObservers + 452 50 CoreFoundation 0x00007fff4138a109 __CFRunLoopRun + 1166 51 CoreFoundation 0x00007fff41389a28 CFRunLoopRunSpecific + 463 52 HIToolbox 0x00007fff40622b35 RunCurrentEventLoopInMode + 293 53 HIToolbox 0x00007fff40622774 ReceiveNextEventCommon + 371 54 HIToolbox 0x00007fff406225e8 _BlockUntilNextEventMatchingListInModeWithFilter + 64 55 AppKit 0x00007fff3e8deeb7 _DPSNextEvent + 997 56 AppKit 0x00007fff3e8ddc56 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 1362 57 AppKit 0x00007fff3e8d7cb9 -[NSApplication run] + 699 58 AppKit 0x00007fff3e8c73f7 NSApplicationMain + 780 59 libdyld.dylib 0x00007fff6e56c08d start + 1 Smalltalk stack dump: 0x7ffeea425ef8 M Array(SequenceableCollection)>do: 0x10cde3bb8: a(n) Array 0x7ffeea425f48 M WorldState>displayWorld:submorphs: 0x10d8049d8: a(n) WorldState 0x7ffeea425f88 M WorldMorph>displayWorld 0x10d7f9bb8: a(n) WorldMorph 0x7ffeea425fc0 M [] in WorldState>displayWorldSafely: 0x10d8049d8: a(n) WorldState 0x7ffeea425ff0 M BlockClosure>on:do: 0x10cd95ef8: a(n) BlockClosure 0x7ffeea426030 M BlockClosure>ifError: 0x10cd95ef8: a(n) BlockClosure 0x7ffeea426068 M WorldState>displayWorldSafely: 0x10d8049d8: a(n) WorldState 0x7ffeea4260a0 M WorldState>doOneCycleNowFor: 0x10d8049d8: a(n) WorldState 0x7ffeea4260d8 M WorldState>doOneCycleFor: 0x10d8049d8: a(n) WorldState 0x7ffeea426110 M WorldMorph>doOneCycle 0x10d7f9bb8: a(n) WorldMorph 0x7ffeea426140 M WorldMorph class>doOneCycle 0x10d7f30c8: a(n) WorldMorph class 0x7ffeea426170 M [] in MorphicUIManager>spawnNewProcess 0x10df481b0: a(n) MorphicUIManager 0x10df48298 s [] in BlockClosure>newProcess Most recent primitives basicAt: basicAt: basicAt: **StackOverflow** basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: @ @ @ @ @ @ bitAnd: basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: @ @ copyBits @ @ @ @ @ truncated truncated @ truncated truncated @ @ @ bitAnd: @ @ = copyBits fractionPart truncated fractionPart truncated drawLoopX:Y: copyBits @ @ @ @ @ **StackOverflow** basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: @ @ @ @ @ @ @ @ @ @ @ @ @ @ truncated truncated truncated truncated @ @ @ @ @ @ @ @ @ @ @ @ @ @ **StackOverflow** **StackOverflow** **StackOverflow** @ @ @ @ @ @ @ @ @ **StackOverflow** basicAt: basicAt: basicAt: **StackOverflow** basicAt: basicAt: basicAt: @ @ @ @ @ @ @ @ @ @ **StackOverflow** truncated truncated truncated truncated @ @ **StackOverflow** @ @ truncated truncated truncated truncated @ @ @ @ @ @ @ @ @ @ @ @ @ @ @ stringHash:initialHash: @ @ @ @ @ @ bitAnd: truncated fractionPart truncated truncated **StackOverflow** **StackOverflow** **StackOverflow** copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated **StackOverflow** copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated **StackOverflow** copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated **StackOverflow** copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: truncated fractionPart truncated truncated copyBitsColor:alpha:gammaTable:ungammaTable: @ @ @ @ @ @ basicAt: basicAt: basicAt: basicAt: basicAt: basicAt: @ @ @ @ @ @ @ copyBits @ @ @ @ primShowRectLeft:right:top:bottom: stack page bytes 4096 available headroom 1480 minimum unused headroom 624 (Segmentation fault) ./pharo-ui: line 11: 68918 Abort trap: 6 "$DIR"/"pharo-vm/Pharo.app/Contents/MacOS/Pharo" "$@"
On 12 Nov 2018, at 17:50, Ben Coman <btc@openinworld.com> wrote:
On Mon, 12 Nov 2018 at 21:37, Sven Van Caekenberghe <sven@stfx.eu> wrote: Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
Just to confirm, you mean your laptop sleep/wake cycle. On my Window 10 laptop I do the same quite often with no problems.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
In trying to understand the last few moments, is the recent primitives list strongly ordered in time?... Most recent primitives signal nowTick primSignal:atUTCMicroseconds: wait millisecondClockValue @ actualScreenSize
Starting at #actualScreenSize, instrumenting the code by adding... Transcript crShow: thisContext sender printString. indicates the following call chain... DisplayScreen-class>>actualScreenSize MorphicUIManager>>checkForNewDisplaySize DisplayScreen class>>checkForNewScreenSize WorldState>>doOneCycleNowFor: WorldState>>doOneCycleFor: WorldMorph>>doOneCycle WorldMorph class>>doOneCycle MorphicUIManager>>spawnNewProcess
In detail from a static analysis of the code... > WorldState>>doOneCycleNowFor: > DisplayScreen class>>checkForNewScreenSize > MorphicUIManager>>checkForNewDisplaySize > DisplayScreen-class>>actualScreenSize PRIMITIVE < MorphicUIManager>>checkForNewDisplaySize < DisplayScreen class>>checkForNewScreenSize < WorldState>>doOneCycleNowFor < WorldState>>doOneCycleFor: < WorldMorph>>doOneCycle < WorldMorph class>>doOneCycle < MorphicUIManager>>spawnNewProcess
WorldMorph class>>doOneCycle > WorldMorph>>doOneCycle > WorldState>>doOneCycleNowFor: > WorldState>>interCyclePause: > Time>>millisecondClockValue PRIMITIVE < WorldState>>interCyclePause: > Delay>>schedule > DelaySemaphoreScheduler>>schedule: > Semaphore>>wait PRIMITIVE "readyToSchedule variable" > Semaphore>>signal PRIMITIVE "timingSemaphore variable" NOT RECORDED maybe context change causes this to be recorded later in "Most recent primitives" > DelayMicrosecondTicker>>waitForUserSignalled:orExpired: waking up from Semaphore>>wait the primSignal:atUTCMicroseconds: PRIMITIVE immediately before the #wait seems to have been logged now in "Most recent primitives" > DelaySemaphoreScheduler>>scheduleAtTimingPriority > Semaphore>>signal PRIMITIVE "readyToSchedule variable" seems to have not been recorded in "Most recent primitives" > DelayBasicScheduler>>scheduleAtTimingPriority < DelaySemaphoreScheduler>>scheduleAtTimingPriority < DelayBasicScheduler>>runBackendLoopAtTimingPriority > DelayMicrosecondTicker>>nowTick PRIMITIVE > Delay>>timingPrioritySignalExpired > Semaphore>>signal PRIMITIVE "delaySemaphore variable" CRASH
Smalltalk stack dump: 0x7ffee21d7138 M Delay>timingPrioritySignalExpired 0x113e3b138: a(n) Delay 0x7ffee21d7170 M [] in DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x11453b8c0: a(n) DelaySemaphoreScheduler 0x1169f51c8 s BlockClosure>ensure: 0x1169f5828 s DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x1169f5c38 s [] in DelaySemaphoreScheduler(DelayBasicScheduler)>startTimerEventLoopPriority: 0x1169fae10 s [] in BlockClosure>newProcess
The only reason I can think that last semaphore call would be a problem is if variable delaySemaphore was not a Semaphore, but the C stack backtrace doesn't look like it crashes in the Semaphore handling. Its perhaps co-incidental with delay scheduling code is invoked fairly often, that its the current process when this crash occurs.
To hep isolate the failure point, I would considering copying #nowTIck to a multiple series like... #nowTick1 #nowTick2 #nowTick3 etc so that all of the sender sites can be made distinct. And maybe the same for #signal senders within the delay scheduling code.
One side-curiousity is I can't see where the primitive #@ is being called from. Does it indicate some loop as its trying to determine
To me the "vmIOProcessEvents" in the C backtrace with a fairly deep stack into the AppKit framework indicates its related to event handling.
cheers -ben
On Tue, 13 Nov 2018 at 02:18, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Yes I mean laptop sleep/wake. Thanks for looking into this. But I think the first step is to see if this is repeatable for someone else. It is probably some graphics primitive rather than scheduling (I am guessing here).
Seems so. Different Smalltalk stack. Very similar C backtrace. I've compared the two here... https://docs.google.com/spreadsheets/d/1pa8Ehwp9b0cW7NaSlElqvPQ5lzSbieike_h4... cheers -ben
Hi Ben, On Mon, Nov 12, 2018 at 8:51 AM Ben Coman <btc@openinworld.com> wrote:
On Mon, 12 Nov 2018 at 21:37, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
Just to confirm, you mean your laptop sleep/wake cycle. On my Window 10 laptop I do the same quite often with no problems.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
In trying to understand the last few moments, is the recent primitives list strongly ordered in time?... Most recent primitives signal nowTick primSignal:atUTCMicroseconds: wait millisecondClockValue @ actualScreenSize
Yes, it's a log of the most recent 256 named primitives. Note that they're irrelevant in this case. The crash is always rooted in vmIOProcessEvents. i.e. the VM is responding to some input event, and it calls pumpRunLoop to do (Objective-C) [NSRunLoop mainRunLoop] runMode:NSDefaultRunLoopMode beforeDate:[NSDate distantPast], which in Smalltalk would be written NSRunLoop mainRunLoop runMode: NSDefaultRunLoopMode beforeDate: NSDate distantPast. And somewhere within this a display update occurs which crashes, presumably because we're using stale data that should have been invalidated oil sleep and refreshed on wake.
Starting at #actualScreenSize, instrumenting the code by adding... Transcript crShow: thisContext sender printString. indicates the following call chain... DisplayScreen-class>>actualScreenSize MorphicUIManager>>checkForNewDisplaySize DisplayScreen class>>checkForNewScreenSize WorldState>>doOneCycleNowFor: WorldState>>doOneCycleFor: WorldMorph>>doOneCycle WorldMorph class>>doOneCycle MorphicUIManager>>spawnNewProcess
In detail from a static analysis of the code... > WorldState>>doOneCycleNowFor: > DisplayScreen class>>checkForNewScreenSize > MorphicUIManager>>checkForNewDisplaySize > DisplayScreen-class>>actualScreenSize PRIMITIVE < MorphicUIManager>>checkForNewDisplaySize < DisplayScreen class>>checkForNewScreenSize < WorldState>>doOneCycleNowFor < WorldState>>doOneCycleFor: < WorldMorph>>doOneCycle < WorldMorph class>>doOneCycle < MorphicUIManager>>spawnNewProcess
WorldMorph class>>doOneCycle > WorldMorph>>doOneCycle > WorldState>>doOneCycleNowFor: > WorldState>>interCyclePause: > Time>>millisecondClockValue PRIMITIVE < WorldState>>interCyclePause: > Delay>>schedule > DelaySemaphoreScheduler>>schedule: > Semaphore>>wait PRIMITIVE "readyToSchedule variable" > Semaphore>>signal PRIMITIVE "timingSemaphore variable" NOT RECORDED
maybe context change causes this to be recorded later in "Most recent primitives" > DelayMicrosecondTicker>>waitForUserSignalled:orExpired: waking up from Semaphore>>wait the primSignal:atUTCMicroseconds: PRIMITIVE immediately before the #wait seems to have been logged now in "Most recent primitives" > DelaySemaphoreScheduler>>scheduleAtTimingPriority > Semaphore>>signal PRIMITIVE "readyToSchedule variable" seems to have not been recorded in "Most recent primitives" > DelayBasicScheduler>>scheduleAtTimingPriority < DelaySemaphoreScheduler>>scheduleAtTimingPriority < DelayBasicScheduler>>runBackendLoopAtTimingPriority > DelayMicrosecondTicker>>nowTick PRIMITIVE > Delay>>timingPrioritySignalExpired > Semaphore>>signal PRIMITIVE "delaySemaphore variable" CRASH
Smalltalk stack dump: 0x7ffee21d7138 M Delay>timingPrioritySignalExpired 0x113e3b138: a(n) Delay 0x7ffee21d7170 M [] in DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x11453b8c0: a(n) DelaySemaphoreScheduler 0x1169f51c8 s BlockClosure>ensure: 0x1169f5828 s DelaySemaphoreScheduler(DelayBasicScheduler)>runBackendLoopAtTimingPriority 0x1169f5c38 s [] in DelaySemaphoreScheduler(DelayBasicScheduler)>startTimerEventLoopPriority: 0x1169fae10 s [] in BlockClosure>newProcess
The only reason I can think that last semaphore call would be a problem is if variable delaySemaphore was not a Semaphore, but the C stack backtrace doesn't look like it crashes in the Semaphore handling. Its perhaps co-incidental with delay scheduling code is invoked fairly often, that its the current process when this crash occurs.
To hep isolate the failure point, I would considering copying #nowTIck to a multiple series like... #nowTick1 #nowTick2 #nowTick3 etc so that all of the sender sites can be made distinct. And maybe the same for #signal senders within the delay scheduling code.
One side-curiousity is I can't see where the primitive #@ is being called from. Does it indicate some loop as its trying to determine
To me the "vmIOProcessEvents" in the C backtrace with a fairly deep stack into the AppKit framework indicates its related to event handling.
cheers -ben
-- _,,,^..^,,,_ best, Eliot
Hi Sven, On Mon, Nov 12, 2018 at 5:37 AM Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I run Pharo 7 64-bit on a macOS laptop, where the images are kept running across sleep/wake cycles.
For many weeks, it often happens that an image crashes before/after such a sleep/wakeup (not all the time, just regularly).
Here is a crash dump from today (fresh image/vm from WE, nothing special loaded).
Related to scheduling ? Event handling ?
The stack trace points to OpenGL rendering: 2 Pharo sigsegv + 155 3 libsystem_platform.dylib _sigtramp + 29 4 ??? 0x0 + 0 5 AppleIntelKBLGraphicsGLDriver glrUpdateTexture + 8979 6 libGPUSupportMercury.dylib gpusLoadCurrentTextures + 591 7 AppleIntelKBLGraphicsGLDriver updateDispatch + 663 8 GLEngine gleDoDrawDispatchCore + 629 9 GLEngine glDrawArraysInstanced_STD_Exec + 264 10 GLEngine glDrawArrays_UnpackThread + 40 11 GLEngine gleCmdProcessor + 77 12 libdispatch.dylib _dispatch_client_callout + 8 13 libdispatch.dylib _dispatch_lane_barrier_sync_invoke_and_complete + 60 14 GLEngine glFlush_ExecThread + 15 15 Pharo -[sqSqueakOSXOpenGLView drawRect:flush:] + 301 16 Pharo -[sqSqueakOSXOpenGLView drawRect:] + 43 17 AppKit _NSViewDrawRect + 66 18 AppKit -[NSView _drawRect:clip:] + 1745 19 AppKit -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:] + 1400 20 AppKit -[NSView _recursiveDisplayAllDirtyWithLockFocus:visRect:] + 2622 21 AppKit -[NSView _recursiveDisplayRectIfNeededIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:topView:] + 938 22 AppKit -[NSThemeFrame _recursiveDisplayRectIfNeededIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:topView:] + 65 23 AppKit -[NSView _oldDisplayRectIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:] + 1887 24 AppKit -[NSView _displayRectIgnoringOpacity:isVisibleRect:rectIsVisibleRectForView:] + 253 25 AppKit -[NSView displayIfNeeded] + 1300 26 AppKit -[NSWindow displayIfNeeded] + 283 27 AppKit __NSWindowGetDisplayCycleObserverForDisplay_block_invoke + 722 28 AppKit NSDisplayCycleObserverInvoke + 170 29 AppKit NSDisplayCycleFlush + 1073 30 QuartzCore _ZN2CA11Transaction19run_commit_handlersE18CATransactionPhase + 49 31 QuartzCore _ZN2CA11Transaction6commitEv + 186 32 AppKit __65+[CATransaction(NSCATransaction) NS_setFlushesWithDisplayRefresh]_block_invoke + 274 33 CoreFoundation __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__ + 23 34 CoreFoundation __CFRunLoopDoObservers + 452 35 CoreFoundation __CFRunLoopRun + 1166 36 CoreFoundation CFRunLoopRunSpecific + 463 37 Foundation -[NSRunLoop(NSRunLoop) runMode:beforeDate:] + 280 38 Pharo -[sqSqueakMainApplication(events) pumpRunLoop] + 103 39 Pharo -[sqSqueakOSXApplication(events) pumpRunLoop] + 43 40 Pharo vmIOProcessEvents + 255 and this is core VM code, so likely an pensmalltalk-vm macOS platform bug, hence best discussed on vm-dev. Can you describe exactly the steps you take to reproduce the crash? _,,,^..^,,,_ best, Eliot
participants (5)
-
Ben Coman -
Cyril Ferlicot -
Eliot Miranda -
Sven Van Caekenberghe -
Tim Mackinnon