On Wed, Feb 12, 2014 at 02:49:16PM +0100, Sven Van Caekenberghe wrote: Hi,

Sorry, but the details matter a lot:

Which image version, vm version, os ?

You can use the System Reporter tool for this.

Image ----- /home/ich/Downloads/ss7-tests.image Pharo2.0 Latest update: #20615 Virtual Machine --------------- /home/ich/source/smalltalk/pharo/blessed/results/pharo NBCoInterpreter NativeBoost-CogPlugin-GuillermoPolito.19 uuid: acc98e51-2fba-4841-a965-2975997bba66 Jan 14 2014 NBCogit NativeBoost-CogPlugin-GuillermoPolito.19 uuid: acc98e51-2fba-4841-a965-2975997bba66 Jan 14 2014 git://gitorious.org/cogvm/blessed.git Commit: a94316242b01bb112550c3ea20a85ae0ae3e3678 Date: 2013-11-21 15:50:24 +0100 By: Holger Hans Peter Freyther <holger@moiji-mobile.com> Unix built on Jan 14 2014 12:35:18 Compiler: 4.8.2 VMMaker versionString git://gitorious.org/cogvm/blessed.git Commit: a94316242b01bb112550c3ea20a85ae0ae3e3678 Date: 2013-11-21 15:50:24 +0100 By: Holger Hans Peter Freyther <holger@moiji-mobile.com> NBCoInterpreter NativeBoost-CogPlugin-GuillermoPolito.19 uuid: acc98e51-2fba-4841-a965-2975997bba66 Jan 14 2014 NBCogit NativeBoost-CogPlugin-GuillermoPolito.19 uuid: acc98e51-2fba-4841-a965-2975997bba66 Jan 14 2014 The VM has my SCTP support added to it and the last upstream commit was: 3d9341c3ef68118f438ff649b343d2fe77952477. The issue happens with the pharo VM binary I downloaded as well. $ ./pharo -version 3.9-7 #1 Wed Mar 13 18:22:44 CET 2013 gcc 4.4.3 NBCoInterpreter NativeBoost-CogPlugin-EstebanLorenzano.18 uuid: a53445f9-c0c0-4015-97a3-be7db8d9ed6b Mar 13 2013 NBCogit NativeBoost-CogPlugin-EstebanLorenzano.18 uuid: a53445f9-c0c0-4015-97a3-be7db8d9ed6b Mar 13 2013 git://gitorious.org/cogvm/blessed.git Commit: 412abef33cbed05cf1d75329e451d71c0c6aa5a7 Date: 2013-03-13 17:48:50 +0100 By: Esteban Lorenzano <estebanlm@gmail.com> Jenkins build #14535 Linux linux-ubuntu-10 2.6.32-38-server #83-Ubuntu SMP Wed Jan 4 11:26:59 UTC 2012 x86_64 GNU/Linux plugin path: /home/ich/source/smalltalk/pharo/Pharo-2.0/ [default: /home/ich/source/smalltalk/pharo/Pharo-2.0/]

Does this happen with a virgin image ? Probably not, what code did you load ?

I don't know. There is my code in the backtrace and it is available in the OsmoCore/OsmoLogging package. The code is doing: runTimers [quit] whileFalse: [| now | "Remember the last delay so we can interrupt it on image resume." lastDelay := Delay forSeconds: 1. lastDelay wait. lastDelay := nil. now := DateAndTime now. OsmoDispatcher dispatchBlock: [self fireTimers: now]] fireTimers: now "Now execute the timers. One way or another this is crazy. If we have a long blocking application or a deadlock the timer queue will get stuck. But if we run this in a new process a later process might be run before this process, changing the order of the timers." "Only this process will remove items, this is why we can check isEmpty without having the lock" self halt. [queue isEmpty or: [queue first timeout > now]] whileFalse: [| each | each := sem critical: [queue removeFirst]. each isCanceled ifFalse: [[each fire] on: Error do: [:e | e logException: 'Execution of timer failed: ' , e messageText area: #timer]]] The entire process list is below. My assumption is that the >>fireTimers: method is actually being executed. The best thing I found was to use SIGUSR1 to sample which processes run. My assumption is that this process runs before DateAndTime has been re-initialized by the SmalltalkImage. All Smalltalk process stacks (active first): Process 0x7890adb8 priority 70 0xbf9a2d78 M Fraction>reduced 0x7ac6cb4c: a(n) Fraction 0xbf9a2d90 M SmallInteger>/ 0x1903d=51230 0xbf9a2dac M DateAndTime>julianDayOffset 0x7ac6ca1c: a(n) DateAndTime 0xbf9a2dc8 M DateAndTime>julianDayNumber 0x7ac6ca1c: a(n) DateAndTime 0xbf9a2df0 M DateAndTime>< 0x7890ac98: a(n) DateAndTime 0xbf9a2e0c M DateAndTime(Magnitude)>> 0x7ac6ca1c: a(n) DateAndTime 0xbf9a2e2c M TimerScheduler>fireTimers: 0x77fdb260: a(n) TimerScheduler 0xbf9a2e54 I [] in TimerScheduler>runTimers 0x77fdb260: a(n) TimerScheduler 0xbf9a2e70 M BlockClosure>on:do: 0x7890acac: a(n) BlockClosure 0xbf9a2e94 M [] in Dispatcher>dispatch 0x77fdb018: a(n) Dispatcher 0xbf9a2eb4 M BlockClosure>ensure: 0x7890ae38: a(n) BlockClosure 0xbf9a2ee0 I [] in Dispatcher>dispatch 0x77fdb018: a(n) Dispatcher 0xbf9a2f00 I [] in BlockClosure>newProcess 0x7890acd4: a(n) BlockClosure Process 0x7890ac70 priority 80 0xbf9a0ea8 M Delay class>handleTimerEvent 0x772edfd8: a(n) Delay class 0xbf9a0ec0 M Delay class>runTimerEventLoop 0x772edfd8: a(n) Delay class 0xbf9a0ee0 I [] in Delay class>startTimerEventLoop 0x772edfd8: a(n) Delay class 0xbf9a0f00 I [] in BlockClosure>newProcess 0x7890ab94: a(n) BlockClosure Process 0x77fdb1f8 priority 70 0xbf9a3f00 I Dispatcher>dispatch 0x77fdb018: a(n) Dispatcher 0x77fe04a8 s [] in Dispatcher>initialize 0x77fdb198 s [] in BlockClosure>newProcess Process 0x78b8242c priority 60 0xbf9a7ec0 I SmalltalkImage>lowSpaceWatcher 0x775fe6e4: a(n) SmalltalkImage 0xbf9a7ee0 I [] in SmalltalkImage>installLowSpaceWatcher 0x775fe6e4: a(n) SmalltalkImage 0xbf9a7f00 I [] in BlockClosure>newProcess 0x78b82350: a(n) BlockClosure processes at priority 60 Process 0x78b82180 priority 60 0xbf9a6e94 M InputEventFetcher>waitForInput 0x772cb574: a(n) InputEventFetcher 0xbf9a6ec0 I InputEventFetcher>eventLoop 0x772cb574: a(n) InputEventFetcher 0xbf9a6ee0 I [] in InputEventFetcher>installEventLoop 0x772cb574: a(n) InputEventFetcher 0xbf9a6f00 I [] in BlockClosure>newProcess 0x78b820a4: a(n) BlockClosure processes at priority 50 Process 0x78b83a54 priority 50 0xbf9a8ec0 I WeakArray class>finalizationProcess 0x772eb9ec: a(n) WeakArray class 0xbf9a8ee0 I [] in WeakArray class>restartFinalizationProcess 0x772eb9ec: a(n) WeakArray class 0xbf9a8f00 I [] in BlockClosure>newProcess 0x78b83978: a(n) BlockClosure processes at priority 40 Process 0x78508aa4 priority 40 0xbf99ce4c M [] in Delay>wait 0x78c395c8: a(n) Delay 0xbf99ce6c M BlockClosure>ifCurtailed: 0x78c3964c: a(n) BlockClosure 0xbf99ce88 M Delay>wait 0x78c395c8: a(n) Delay 0xbf99cea8 M WorldState>interCyclePause: 0x77127638: a(n) WorldState 0xbf99cec4 M WorldState>doOneCycleFor: 0x77127638: a(n) WorldState 0xbf99cee0 M PasteUpMorph>doOneCycle 0x77118168: a(n) PasteUpMorph 0xbf99cf00 I [] in MorphicUIManager>spawnNewProcess 0x7712ba74: a(n) MorphicUIManager 0x78508a44 s [] in BlockClosure>newProcess Process 0x7850a38c priority 40 0xbf9a1ea0 M [] in Delay>wait 0x78c32294: a(n) Delay 0xbf9a1ec0 M BlockClosure>ifCurtailed: 0x78c32318: a(n) BlockClosure 0xbf9a1edc M Delay>wait 0x78c32294: a(n) Delay 0xbf9a1f00 I TimerScheduler>runTimers 0x77fdb260: a(n) TimerScheduler 0x7857b890 s [] in TimerScheduler>startLoop 0x7850a32c s [] in BlockClosure>newProcess Process 0x784e0010 priority 40 0xbf9a4e98 M [] in Delay>wait 0x784dfeac: a(n) Delay 0xbf9a4eb8 M BlockClosure>ifCurtailed: 0x7890afd8: a(n) BlockClosure 0xbf9a4edc I Delay>wait 0x784dfeac: a(n) Delay 0xbf9a4f00 I [] in ProcessBrowser>startAutoUpdate 0x784bf424: a(n) ProcessBrowser 0x784dffb0 s [] in BlockClosure>newProcess processes at priority 10 Process 0x78b825f8 priority 10 0xbf99dec0 M ProcessorScheduler class>idleProcess 0x772eb7dc: a(n) ProcessorScheduler class 0xbf99dee0 I [] in ProcessorScheduler class>startUp 0x772eb7dc: a(n) ProcessorScheduler class 0xbf99df00 I [] in BlockClosure>newProcess 0x78b8251c: a(n) BlockClosure

On Wed, Feb 12, 2014 at 03:31:56PM +0100, Sven Van Caekenberghe wrote:

Holger,

Dear Sven, thanks a lot for your answer.

...

The entire process list is below. My assumption is that the >>fireTimers: method is actually being executed. The best thing I found was to use SIGUSR1 to sample which processes run. My assumption is that this process runs before DateAndTime has been re-initialized by the SmalltalkImage.

Now, you do agree that you are doing tricky stuff, right ? You play with timers, timestamps and delays in a process that you expect to keep running over image save/resume ;-)

The timers work with absolute time and the code is working fine with GNU Smalltalk for years (with image save/resume). I think the only thing weird in Pharo is that (Delay forSeconds: 1) wait will wait forever on image resume but IIRC this is a known issue/feature.

I think a better approach would be to subscribe to image #shutDown: and #startUp: events (trace these selectors for examples). With these you can cleanly stop your process on image save and restart it when the image resumes. I think all long running processes work that way.

I have implemented your proposal and I think the problem will go away with that. To me this sounds a bit like a work-around. Do you agree? I think something like: [[DateAndTime now] repeat] fork could re-produce the issue. It can either get stuck inside the Delay created from within >>#now or in this mysterious loop that takes all the CPU and doesn't allow me to interact with the image anymore. It would be nice to fully understand why this process runs away and no other process will be scheduled. I don't know how the ProcessorScheduler works in Pharo and when/if a method is pre-empted. Is there any guarantee that the StartUpList will be executed before any other process will be scheduled? From quick browsing it seems that the SmalltalkImage code does not suspend all the other processes? kind regards holger