[Vm-dev] Oddd image lock-up on Unix

Mon Apr 2 22:04:05 UTC 2007

2007/4/2, Andreas Raab <andreas.raab at gmx.de>:
>
> Hi Guys -
>
> We just had a very strange image lockup on our server. After a variety
> of attempts to connect to the image we finally fired up gdb and had the
> image do a printAllStacks. The dump is attached below, what is
> interesting is that it appears as if the Delay mutex was entered but not
> left successfully, e.g.,
>
> Process
> -1737213740 Semaphore>critical:
> -1755652204 Delay class>timerInterruptWatcher
> -1755651864 [] in Delay class>startTimerInterruptWatcher

All these active Semaphore>#critical: look awfully familiar. I've seen
this happening on a connection pool in a server application. It would
run for months and then suddenly Semaphore>#critical: wouldn't exit
anymore.

That's either a 3.6 or 3.7 VM, don't remember exactly anymore.

Philippe

> Process
> -1737212772 Semaphore>critical:
> -1737212956 Delay>unschedule
> -1737226548 Semaphore>waitTimeoutMSecs:
>
> And from there things go downhill quickly. The one change that I did do
> in this image was to include Tim's "large delay fix" and I am wondering
> if that may be related to it?
>
> In any case, if anyone has ever seen something similar, I'd really
> appreciate finding out more about it. Seeing how it keeps things just
> entirely locked is quite disturbing.
>
> Cheers,
>    - Andreas
>
> The full dump:
>
> Process
> -1742550148 ProcessorScheduler class>idleProcess
> -1743108016 [] in ProcessorScheduler class>startUp
> -1743107924 [] in BlockContext>newProcess
>
> Process
> -1737212168 Semaphore>wait
> -1743080028 WeakArray class>finalizationProcess
> -1743080212 [] in WeakArray class>restartFinalizationProcess
> -1743080120 [] in BlockContext>newProcess
>
> Process
> -1737219904 Semaphore>critical:
> -1737219996 Delay>unschedule
> -1737229232 Semaphore>waitTimeoutMSecs:
> -1737229692 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737229784 Socket>waitForDataFor:
> -1737229600 [] in TMessageRelay>runReaderProcess
> -1737229876 BlockContext>on:do:
> -1738663052 TMessageRelay>runReaderProcess
> -1738658624 [] in Object>fork:at:
> -1738658532 [] in BlockContext>newProcess
>
> Process
> -1737218372 Semaphore>critical:
> -1737218580 Delay>schedule
> -1737218672 Delay class>timeoutSemaphore:afterMSecs:
> -1737218764 Semaphore>waitTimeoutMSecs:
> -1737219256 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737219348 Socket>waitForDataFor:
> -1737219132 [] in TMessageRelay>runReaderProcess
> -1737219440 BlockContext>on:do:
> -1742529444 TMessageRelay>runReaderProcess
> -1742525016 [] in Object>fork:at:
> -1742524924 [] in BlockContext>newProcess
>
> Process
> -1737217168 Semaphore>critical:
> -1737217376 Delay>schedule
> -1737217468 Delay class>timeoutSemaphore:afterMSecs:
> -1737217560 Semaphore>waitTimeoutMSecs:
> -1737218052 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737218144 Socket>waitForDataFor:
> -1737217928 [] in TMessageRelay>runReaderProcess
> -1737218236 BlockContext>on:do:
> -1742510448 TMessageRelay>runReaderProcess
> -1742506020 [] in Object>fork:at:
> -1742505928 [] in BlockContext>newProcess
>
> Process
> -1737215980 Semaphore>critical:
> -1737216188 Delay>schedule
> -1737216280 Delay class>timeoutSemaphore:afterMSecs:
> -1737216372 Semaphore>waitTimeoutMSecs:
> -1737216864 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737216956 Socket>waitForDataFor:
> -1737216740 [] in TMessageRelay>runReaderProcess
> -1737217048 BlockContext>on:do:
> -1742501032 TMessageRelay>runReaderProcess
> -1742496604 [] in Object>fork:at:
> -1742496512 [] in BlockContext>newProcess
>
> Process
> -1737215020 Semaphore>critical:
> -1737215112 Delay>schedule
> -1737215204 Delay>wait
> -1742522336 [] in TMediaControlEndpoint>runPinger
> -1742522612 BlockContext>repeat
> -1742522704 TMediaControlEndpoint>runPinger
> -1742522520 [] in TMediaControlEndpoint>startPinger
> -1742522796 BlockContext>on:do:
> -1742523112 [] in TMediaControlEndpoint>startPinger
> -1742522928 [] in BlockContext>newProcess
>
> Process
> -1737214400 Semaphore>critical:
> -1737214492 Delay>schedule
> -1737214584 Delay>wait
> -1742493924 [] in TMediaControlEndpoint>runPinger
> -1742494200 BlockContext>repeat
> -1742494292 TMediaControlEndpoint>runPinger
> -1742494108 [] in TMediaControlEndpoint>startPinger
> -1742494384 BlockContext>on:do:
> -1742494700 [] in TMediaControlEndpoint>startPinger
> -1742494516 [] in BlockContext>newProcess
>
> Process
> -1737213740 Semaphore>critical:
> -1755652204 Delay class>timerInterruptWatcher
> -1755651864 [] in Delay class>startTimerInterruptWatcher
> -1755651772 [] in BlockContext>newProcess
>
> Process
> -1737212772 Semaphore>critical:
> -1737212956 Delay>unschedule
> -1737226548 Semaphore>waitTimeoutMSecs:
> -1737227040 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737227132 Socket>waitForDataFor:
> -1737226916 [] in TMessageRelay>runReaderProcess
> -1737227224 BlockContext>on:do:
> -1738650508 TMessageRelay>runReaderProcess
> -1738650272 [] in Object>fork:at:
> -1738650180 [] in BlockContext>newProcess
>
> Process
> -1737212496 Semaphore>critical:
> -1737212680 Delay>unschedule
> -1737225588 Semaphore>waitTimeoutMSecs:
> -1737226080 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737226172 Socket>waitForDataFor:
> -1737225956 [] in TMessageRelay>runReaderProcess
> -1737226264 BlockContext>on:do:
> -1738361832 TMessageRelay>runReaderProcess
> -1738361596 [] in Object>fork:at:
> -1738361504 [] in BlockContext>newProcess
>
> Process
> -1737175104 Semaphore>critical:
> -1737175288 Delay>unschedule
> -1737266784 Semaphore>waitTimeoutMSecs:
> -1737266876 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737266968 Socket>waitForDataFor:
> -1737275344 Socket>receiveDataSignallingTimeout:into:startingAt:
> -1737275436 SocketStream>receiveData
> -1737275528 SocketStream>next
> -1737275620 XMLTokenizer>peek
> -1737275712 XMLTokenizer>nextWhitespace
> -1737276052 XMLTokenizer>nextEntity
> -1737276144 XMLDOMParser>nextEntity
> -1737276236 QServiceProviderV2>processRequest:
> -1737275952 [] in QServiceProviderV2>runServiceProcess
> -1737276328 BlockContext>on:do:
> -1743007756 QServiceProviderV2>runServiceProcess
> -1743044068 [] in Object>fork:at:
> -1743043976 [] in BlockContext>newProcess
>
> Process
> -1737173864 Semaphore>critical:
> -1737174000 Delay>schedule
> -1737174092 Delay>wait
> -1737174184 WorldState>interCyclePause:
> -1737174920 WorldState>doOneCycleFor:
> -1737175012 PasteUpMorph>doOneCycle
> -1738256796 [] in Project class>spawnNewProcess
> -1738256612 [] in BlockContext>newProcess
>
> Process
> -1737173496 Semaphore>critical:
> -1737173680 Delay>unschedule
> -1737288304 Semaphore>waitTimeoutMSecs:
> -1737288764 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737288856 Socket>waitForDataFor:
> -1737288672 [] in TMessageRelay>runReaderProcess
> -1737288948 BlockContext>on:do:
> -1742548340 TMessageRelay>runReaderProcess
> -1742543912 [] in Object>fork:at:
> -1742543820 [] in BlockContext>newProcess
>
> Process
> -1737173220 Semaphore>critical:
> -1737173404 Delay>unschedule
> -1737277292 Semaphore>waitTimeoutMSecs:
> -1737277752 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737277844 Socket>waitForDataFor:
> -1737277660 [] in TMessageRelay>runReaderProcess
> -1737277936 BlockContext>on:do:
> -1738378076 TMessageRelay>runReaderProcess
> -1738373648 [] in Object>fork:at:
> -1738373556 [] in BlockContext>newProcess
>
> Process
> -1737172944 Semaphore>critical:
> -1737173128 Delay>unschedule
> -1737231056 Semaphore>waitTimeoutMSecs:
> -1737231548 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737231640 Socket>waitForDataFor:
> -1737231424 [] in TMessageRelay>runReaderProcess
> -1737231732 BlockContext>on:do:
> -1742538860 TMessageRelay>runReaderProcess
> -1742534432 [] in Object>fork:at:
> -1742534340 [] in BlockContext>newProcess
>
> Process
> -1737172668 Semaphore>critical:
> -1737172852 Delay>unschedule
> -1737230128 Semaphore>waitTimeoutMSecs:
> -1737230620 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737230712 Socket>waitForDataFor:
> -1737230496 [] in TMessageRelay>runReaderProcess
> -1737230804 BlockContext>on:do:
> -1742519864 TMessageRelay>runReaderProcess
> -1742515436 [] in Object>fork:at:
> -1742515344 [] in BlockContext>newProcess
>
> Process
> -1737172392 Semaphore>critical:
> -1737172576 Delay>unschedule
> -1737279024 Semaphore>waitTimeoutMSecs:
> -1737279116 Socket>waitForConnectionFor:ifTimedOut:
> -1737279484 Socket>waitForConnectionFor:
> -1737279392 [] in Socket>waitForAcceptFor:
> -1737279588 BlockContext>on:do:
> -1737279696 Socket>waitForAcceptFor:
> -1743045624 TConnectionDispatcher>runServer
> -1743045808 [] in Object>fork:at:
> -1743045716 [] in BlockContext>newProcess
>
> Process
> -1737172116 Semaphore>critical:
> -1737172300 Delay>unschedule
> -1737311692 Semaphore>waitTimeoutMSecs:
> -1737312152 Socket>waitForDataFor:ifClosed:ifTimedOut:
> -1737312244 Socket>waitForDataFor:
> -1737312060 [] in TMessageRelay>runReaderProcess
> -1737312336 BlockContext>on:do:
> -1737314988 TMessageRelay>runReaderProcess
> -1737314752 [] in Object>fork:at:
> -1737314660 [] in BlockContext>newProcess
>
> Process
> -1737171840 Semaphore>critical:
> -1737172024 Delay>unschedule
> -1737302368 Semaphore>waitTimeoutMSecs:
> -1737302460 Socket>waitForConnectionFor:ifTimedOut:
> -1737302644 Socket>waitForConnectionFor:
> -1737302920 [] in Socket>waitForAcceptFor:
> -1737302736 BlockContext>on:do:
> -1737303012 Socket>waitForAcceptFor:
> -1737303196 [] in RFBServer>runLoop
> -1737303288 BlockContext>on:do:
> -1742896304 RFBServer>runLoop
> -1742896092 [] in RFBServer>start:
> -1742896000 [] in BlockContext>newProcess
>
> Process
> -1749883968 Semaphore>wait
> -1749884060 Python class>runCallbackProcess
> -1749884336 [] in Object>fork:at:
> -1749884152 [] in BlockContext>newProcess
>
> Process
> -1743109816 Semaphore>wait
> -1743109948 InputSensor>userInterruptWatcher
> -1743110152 [] in InputSensor>installInterruptWatcher
> -1743110040 [] in BlockContext>newProcess
>
> Process
> -1737224332 Semaphore>wait
> -1737224424 Delay>wait
> -1737224608 [] in EventSensor>eventTickler
> -1737224700 BlockContext>on:do:
> -1743109356 EventSensor>eventTickler
> -1743109632 [] in EventSensor>installEventTickler
> -1743109448 [] in BlockContext>newProcess
>
> Process
> -1743108200 Semaphore>wait
> -1743108444 SystemDictionary>lowSpaceWatcher
> -1743108628 [] in SystemDictionary>installLowSpaceWatcher
> -1743108352 [] in BlockContext>newProcess
>
> Process
> -1743103636 Semaphore>wait
> -1743103544 [] in UnixOSProcessAccessor>grimReaperProcess
> -1743103728 BlockContext>repeat
> -1743106440 [] in UnixOSProcessAccessor>grimReaperProcess
> -1743106348 [] in BlockContext>newProcess
>
> Process
> -1737181332 Semaphore>wait
> -1737181424 SharedQueue>next
> -1743047256 TSessionDispatcher>runLoggerProcess
> -1743047000 [] in Object>fork:at:
> -1743046908 [] in BlockContext>newProcess
>
> Process
> -1737453796 Semaphore>wait
> -1737453888 Delay>wait
> -1743007480 QServiceProviderV2>runUpdateProcess
> -1743043708 [] in Object>fork:at:
> -1743043524 [] in BlockContext>newProcess
>
> Process
> -1737287448 Semaphore>wait
> -1737287540 SharedQueue>next
> -1742549512 TMessageRouter>runEventLoop
> -1742549336 [] in Object>fork:at:
> -1742549244 [] in BlockContext>newProcess
>
> Process
> -1737287884 Semaphore>wait
> -1737287976 SharedQueue>next
> -1742543240 TMessageRelay>runWriterProcess
> -1742543424 [] in Object>fork:at:
> -1742543332 [] in BlockContext>newProcess
>
> Process
> -1737223064 Semaphore>wait
> -1737223156 SharedQueue>next
> -1742540032 TMessageRouter>runEventLoop
> -1742539856 [] in Object>fork:at:
> -1742539764 [] in BlockContext>newProcess
>
> Process
> -1737223840 Semaphore>wait
> -1737223932 SharedQueue>next
> -1742533760 TMessageRelay>runWriterProcess
> -1742533944 [] in Object>fork:at:
> -1742533852 [] in BlockContext>newProcess
>
> Process
> -1737215796 Semaphore>wait
> -1737215888 SharedQueue>next
> -1742530616 TMessageRouter>runEventLoop
> -1742530440 [] in Object>fork:at:
> -1742530348 [] in BlockContext>newProcess
>
> Process
> -1737222124 Semaphore>wait
> -1737222216 SharedQueue>next
> -1742524344 TMessageRelay>runWriterProcess
> -1742524528 [] in Object>fork:at:
> -1742524436 [] in BlockContext>newProcess
>
> Process
> -1737222880 Semaphore>wait
> -1737222972 SharedQueue>next
> -1742521036 TMessageRouter>runEventLoop
> -1742520860 [] in Object>fork:at:
> -1742520768 [] in BlockContext>newProcess
>
> Process
> -1737223536 Semaphore>wait
> -1737223628 SharedQueue>next
> -1742514764 TMessageRelay>runWriterProcess
> -1742514948 [] in Object>fork:at:
> -1742514856 [] in BlockContext>newProcess
>
> Process
> -1737214824 Semaphore>wait
> -1737214928 SharedQueue>next
> -1742511620 TMessageRouter>runEventLoop
> -1742511444 [] in Object>fork:at:
> -1742511352 [] in BlockContext>newProcess
>
> Process
> -1737215492 Semaphore>wait
> -1737215584 SharedQueue>next
> -1742505348 TMessageRelay>runWriterProcess
> -1742505532 [] in Object>fork:at:
> -1742505440 [] in BlockContext>newProcess
>
> Process
> -1737215308 Semaphore>wait
> -1737215400 SharedQueue>next
> -1742502204 TMessageRouter>runEventLoop
> -1742502028 [] in Object>fork:at:
> -1742501936 [] in BlockContext>newProcess
>
> Process
> -1737223248 Semaphore>wait
> -1737223340 SharedQueue>next
> -1742495932 TMessageRelay>runWriterProcess
> -1742496116 [] in Object>fork:at:
> -1742496024 [] in BlockContext>newProcess
>
> Process
> -1742275584 Semaphore>wait
> -1742275676 Socket>waitForDataIfClosed:
> -1742275768 Socket>waitForData
> -1742275860 TConnectionDispatcher>acceptConnectionFrom:
> -1742276136 [] in TConnectionDispatcher>futureAcceptConnectionFrom:
> -1742275952 BlockContext>on:do:
> -1742277028 [] in TConnectionDispatcher>futureAcceptConnectionFrom:
> -1742276936 [] in BlockContext>newProcess
>
> Process
> -1737204640 Semaphore>wait
> -1737204732 SharedQueue>next
> -1738680880 TMessageRouter>runEventLoop
> -1738680752 [] in Object>fork:at:
> -1738680660 [] in BlockContext>newProcess
>
> Process
> -1737221816 Semaphore>wait
> -1737221908 SharedQueue>next
> -1738657952 TMessageRelay>runWriterProcess
> -1738658136 [] in Object>fork:at:
> -1738658044 [] in BlockContext>newProcess
>
> Process
> -1737211292 Semaphore>wait
> -1737211384 SharedQueue>next
> -1738649596 TMessageRelay>runWriterProcess
> -1738649872 [] in Object>fork:at:
> -1738649688 [] in BlockContext>newProcess
>
> Process
> -1737211800 Semaphore>wait
> -1737220784 Delay>wait
> -1738506672 TMessageRouterClient>runHeartbeat
> -1738506996 [] in Object>fork:at:
> -1738506904 [] in BlockContext>newProcess
>
> Process
> -1737276872 Semaphore>wait
> -1737276964 SharedQueue>next
> -1738372976 TMessageRelay>runWriterProcess
> -1738373160 [] in Object>fork:at:
> -1738373068 [] in BlockContext>newProcess
>
> Process
> -1737211108 Semaphore>wait
> -1737211200 SharedQueue>next
> -1738369928 TMessageRouter>runEventLoop
> -1738369800 [] in Object>fork:at:
> -1738369708 [] in BlockContext>newProcess
>
> Process
> -1737212260 Semaphore>wait
> -1737212352 SharedQueue>next
> -1738360920 TMessageRelay>runWriterProcess
> -1738361196 [] in Object>fork:at:
> -1738361012 [] in BlockContext>newProcess
>
> Process
> -1737211892 Semaphore>wait
> -1737220876 Delay>wait
> -1738305304 TMessageRouterClient>runHeartbeat
> -1738305592 [] in Object>fork:at:
> -1738305500 [] in BlockContext>newProcess
>
> Process
> -1737299840 Semaphore>wait
> -1737299932 Delay>wait
> -1738303108 [] in TAudioStreamInput>runPinger
> -1738303244 BlockContext>repeat
> -1738303376 TAudioStreamInput>runPinger
> -1738303652 [] in TAudioStreamInput>startPinger
> -1738303468 [] in BlockContext>newProcess
>
> Process
> -1737301448 Semaphore>wait
> -1737301540 Delay>wait
> -1737950096 [] in TAudioStreamInput>runPinger
> -1737950232 BlockContext>repeat
> -1737950364 TAudioStreamInput>runPinger
> -1737950640 [] in TAudioStreamInput>startPinger
> -1737950456 [] in BlockContext>newProcess
>
> Process
> -1737211984 Semaphore>wait
> -1737212076 SharedQueue>next
> -1737323020 TMessageRouter>runEventLoop
> -1737322892 [] in Object>fork:at:
> -1737322800 [] in BlockContext>newProcess
>
> Process
> -1737320664 Semaphore>wait
> -1737320756 SharedQueue>next
> -1737320572 [] in TErrorReportPlugin class>runLoggerProcess
> -1737320848 BlockContext>on:do:
> -1737321304 TErrorReportPlugin class>runLoggerProcess
> -1737321212 [] in Object>fork:at:
> -1737321120 [] in BlockContext>newProcess
>
> Process
> -1737219576 Semaphore>wait
> -1737219668 SharedQueue>next
> -1737314076 TMessageRelay>runWriterProcess
> -1737314352 [] in Object>fork:at:
> -1737314168 [] in BlockContext>newProcess
>
> Process
> -1737220992 Semaphore>wait
> -1737221084 Delay>wait
> -1737312544 TMessageRouterClient>runHeartbeat
> -1737312924 [] in Object>fork:at:
> -1737312740 [] in BlockContext>newProcess
>
> Process
> -1737294120 Semaphore>wait
> -1737294268 Delay>wait
> -1742503340 [] in TMediaControlEndpoint>runPinger
> -1742503616 BlockContext>repea
>
>
>