A backtrace from gdb might have been useful, too.
There was an increasing number of reports of Linux VMs freezing or crashing lately. We suspect some possibly unrelated problems. One is due to oops-as-signed, a symptom is that GC fails to find the end of memory. The other seems related to async i/o. In yet others (and this may be yours) we see nanosleeps that are called with huge negative microsecond counts, yet higher up in the stack the value was 1000 microseconds.
- Bert -
On Apr 2, 2007, at 21:22 , Andreas Raab wrote:
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
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