Just for the fun, I did a system tracing...

strace ../../../products/sqcogspurlinux/lib/squeak/5.0-201711262336/squeak TravisCI.image test.st > tmp.log 2>tmp.trace

Then interrupted and quit the image

It's amazing how many time we stat/open the changes file...
grep changes tmp.trace | grep open | wc
3027 15226 511279

sometimes, we open many .changes in a row and the file index keep increasing, like:

lstat64("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", {st_mode=S_IFREG|0644, st_size=10701044, ...}) = 0
open("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", O_RDONLY|O_LARGEFILE) = 206
lstat64("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", {st_mode=S_IFREG|0644, st_size=10701077, ...}) = 0
open("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", O_RDONLY|O_LARGEFILE) = 208
lstat64("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", {st_mode=S_IFREG|0644, st_size=10701103, ...}) = 0
open("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", O_RDONLY|O_LARGEFILE) = 10
lstat64("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", {st_mode=S_IFREG|0644, st_size=10701816, ...}) = 0
open("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", O_RDONLY|O_LARGEFILE) = 12
lstat64("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", {st_mode=S_IFREG|0644, st_size=10701900, ...}) = 0
open("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_07_37/TravisCI.changes", O_RDONLY|O_LARGEFILE) = 14

This is the famous case when we can exhaust the maximum number of opened files...

I don't remembered if we installed a workaround at image side?

But obviously we do not behave so well with respect to external resources...

Then I see patterns where we read .changes a few times every 2ms... like this:

open("/media/psf/Home/Smalltalk/OpenSmalltalk/opensmalltalk-vm/smalltalkCI-master/_builds/2017_12_04_22_
07_37/TravisCI.changes", O_RDONLY|O_LARGEFILE) = 9
fcntl64(9, F_GETFL)                     = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fstat64(9, {st_mode=S_IFREG|0644, st_size=10762271, ...}) = 0
fstat64(9, {st_mode=S_IFREG|0644, st_size=10762271, ...}) = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=234913}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
_llseek(9, 0, [0], SEEK_SET)            = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2042) = 2042
read(9, ": '' prior: 44316480!\roverride ^"..., 4096) = 37
read(9, "", 4096)                       = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=237225}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=239103}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2078) = 2078
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=241003}, NULL) = 0
sigreturn({mask=[]})                    = 2078
_llseek(9, 10762270, [10762270], SEEK_SET) = 0
read(9, "!", 4096)                      = 1
read(9, "", 4096)                       = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2078) = 2078
read(9, "!", 4096)                      = 1
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=243052}, NULL) = 0
sigreturn({mask=[]})                    = 1
read(9, "", 4096)                       = 0
recvmsg(4, {msg_namelen=0}, 0)          = -1 EAGAIN (Resource temporarily unavailable)
_newselect(5, [4], [], [4], {tv_sec=0, tv_usec=0}) = 0 (Timeout)
read(9, "", 4096)                       = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
read(9, "", 4096)                       = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=245075}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=247097}, NULL) = 0

sigreturn({mask=[]})                    = 0
read(9, "", 4096)                       = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=248983}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
read(9, "", 4096)                       = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=251019}, NULL) = 0
sigreturn({mask=[]})                    = 0
read(9, "", 4096)                       = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
read(9, "", 4096)                       = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422430, tv_usec=253017}, NULL) = 0
sigreturn({mask=[]})                    = 2079
...

It looks like we are looping like this during 103 seconds (I let sufficient time before pressing ctrl+alt+.)

--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422533, tv_usec=555087}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422533, tv_usec=556985}, NULL) = 0
sigreturn({mask=[]})                    = 0
_llseek(9, 0, [10762271], SEEK_CUR)     = 0
read(9, "", 4096)                       = 0
_llseek(9, 10760192, [10760192], SEEK_SET) = 0
read(9, "ceVariableNames: ''\r\tclassVariab"..., 2079) = 2079
read(9, "", 4096)                       = 0
read(9, "", 4096)                       = 0
--- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL} ---
gettimeofday({tv_sec=1512422533, tv_usec=559009}, NULL) = 0
sigreturn({mask=[]})                    = 0
gettimeofday({tv_sec=1512422533, tv_usec=559419}, NULL) = 0
gettimeofday({tv_sec=1512422533, tv_usec=559628}, NULL) = 0
gettimeofday({tv_sec=1512422533, tv_usec=559830}, NULL) = 0

It's not the good way to find the bug, bt it's interesting...

2017-12-04 21:58 GMT+01:00 Nicolas Cellier <nicolas.cellier.aka.nice@gmail.com>:

Hi Fabio,
no, I opened the test image --headfull and it is blocked in tests:

MCMockPackageInfo(PackageInfo) changeRecordForOverriddenMethod:

with parameter: a MethodReference MCMethodDefinitionTest >> #override

This is invoked from MCMethodDefinition>>tearDown.

It is blocked in this infinite loop:

[file position < (position-1)] "then pick it up from the front"
whileTrue: [chunk := file nextChunk].

here file position is 0, and inst. var. readLimit is 0 too...
So nextChunk invariably return '' and the position does not advance.

Why is readLimit 0???
The file is TravisCI.changes and I can open and read it normally in the FileList.
The problem comes from SourceFiles which already has an incorrect readLimit set to zero (image attached)

It remains to discover how this ever happened, and why only in linux...

2017-12-04 7:35 GMT+01:00 Fabio Niephaus <lists@fniephaus.com>:

Hi Nicolas,
Is it possible that this was related to this:
http://forum.world.st/Squeak-trunk-updates-fail-td5059208.html

Best,
Fabio

On Sun, 3 Dec 2017 at 11:08 am, Nicolas Cellier <nicolas.cellier.aka.nice@gmail.com> wrote:

Hi,
for quite some times the travis build for linux32x86 times out during the .travis_test.sh phase.

It's very hard for me to build a 32bits vm from 64bits ubuntu (14.xx). So I've tried with a 32bits VM (debian9), changed to opensmalltalk root directory of my working copy, and

export ARCH="linux32x86"
export FLAVOR="squeak.cog.spur"
export TRAVIS_BUILD_DIR=`pwd`
export TRAVIS_OS_NAME=linux
./.travis_build.sh
./.travis_test.sh

The tests effectively seem to block with 100% CPU.

So I performed a few stack dump via kill -USR1, and it seems that tests are stuck in a very long operation, here is one of the samples:

All Smalltalk process stacks (active first):
Process 0x192cda8 priority 40
0xbfc67d94 M MultiByteFileStream(StandardFileStream)>basicNext 0x129bdc8: a(n) MultiByteFileStream
0xbfc67db0 M UTF8TextConverter>skipSeparatorsAndPeekNextFrom: 0x129bd58: a(n) UTF8TextConverter
0xbfc67dd0 M UTF8TextConverter>parseLangTagFor:fromStream: 0x129bd58: a(n) UTF8TextConverter
0xbfc67df0 M UTF8TextConverter>nextChunkFromStream: 0x129bd58: a(n) UTF8TextConverter
0xbfc67e0c M MultiByteFileStream>nextChunk 0x129bdc8: a(n) MultiByteFileStream
0xbfc67e5c M [] in MCMockPackageInfo(PackageInfo)>changeRecordsForMethod:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc67e7c M BlockClosure>ensure: 0x129bf80: a(n) BlockClosure
0xbfc74bb0 M MCMockPackageInfo(PackageInfo)>changeRecordsForMethod:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74bd0 M MCMockPackageInfo(PackageInfo)>changeRecordForOverriddenMethod: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74bec M MCMockPackageInfo(PackageInfo)>isOverrideOfYourMethod: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74c0c M [] in MCMockPackageInfo(PackageInfo)>overriddenMethodsDo: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74c30 M [] in MCMockPackageInfo(PackageInfo)>methodsInCategory:ofClass:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74c54 M Array(SequenceableCollection)>do: 0x129d178: a(n) Array
0xbfc74c70 M MCMockPackageInfo(PackageInfo)>methodsInCategory:ofClass:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74c9c M [] in MCMockPackageInfo(PackageInfo)>overriddenMethodsInClass:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74cbc M [] in MCMockPackageInfo(PackageInfo)>overrideCategoriesForClass:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74ce0 M Array(SequenceableCollection)>do: 0x129aa48: a(n) Array
0xbfc74cfc M MCMockPackageInfo(PackageInfo)>overrideCategoriesForClass:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74d1c M MCMockPackageInfo(PackageInfo)>overriddenMethodsInClass:do: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74d40 M [] in MCMockPackageInfo(PackageInfo)>allOverriddenMethodsDo: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc74d60 M [] in MCTestCase class(Behavior)>allSubclassesDo: 0x1b38d88: a(n) MCTestCase class
0xbfc74d84 M Array(SequenceableCollection)>do: 0x1ae4c70: a(n) Array
0xbfc74da0 M MCTestCase class(Class)>subclassesDo: 0x1b38d88: a(n) MCTestCase class
0xbfc74dbc M MCTestCase class(Behavior)>allSubclassesDo: 0x1b38d88: a(n) MCTestCase class
0xbfc74ddc M [] in TestCase class(Behavior)>allSubclassesDo: 0x1b35988: a(n) TestCase class
0xbfc74e00 M Array(SequenceableCollection)>do: 0x27fa510: a(n) Array
0xbfc74e1c M TestCase class(Class)>subclassesDo: 0x1b35988: a(n) TestCase class
0xbfc74e38 M TestCase class(Behavior)>allSubclassesDo: 0x1b35988: a(n) TestCase class
0xbfc74e58 M [] in Object class(Behavior)>allSubclassesDo: 0x1a25910: a(n) Object class
0xbfc74e7c M Array(SequenceableCollection)>do: 0x1297d50: a(n) Array
0xbfc6bb9c M Object class(Class)>subclassesDo: 0x1a25910: a(n) Object class
0xbfc6bbb8 M Object class(Behavior)>allSubclassesDo: 0x1a25910: a(n) Object class
0xbfc6bbd8 M [] in ProtoObject class(Behavior)>allSubclassesDo: 0x1a25a98: a(n) ProtoObject class
0xbfc6bbfc M Array(SequenceableCollection)>do: 0x4334a28: a(n) Array
0xbfc6bc18 M ProtoObject class(Class)>subclassesDo: 0x1a25a98: a(n) ProtoObject class
0xbfc6bc34 M ProtoObject class(Behavior)>allSubclassesDo: 0x1a25a98: a(n) ProtoObject class
0xbfc6bc58 I ProtoObject class(Behavior)>withAllSubclassesDo: 0x1a25a98: a(n) ProtoObject class
0xbfc6bc74 M MCMockPackageInfo(PackageInfo)>allOverriddenMethodsDo: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc6bc90 M MCMockPackageInfo(PackageInfo)>overriddenMethodsDo: 0x1a265d0: a(n) MCMockPackageInfo
0xbfc6bcac M [] in MCMockPackageInfo(PackageInfo)>overriddenMethods 0x1a265d0: a(n) MCMockPackageInfo
0xbfc6bcd0 M Array class(SequenceableCollection class)>new:streamContents: 0x1a124a8: a(n) Array class
0xbfc6bcf0 M Array class(SequenceableCollection class)>streamContents: 0x1a124a8: a(n) Array class
0xbfc6bd0c M MCMockPackageInfo(PackageInfo)>overriddenMethods 0x1a265d0: a(n) MCMockPackageInfo
0xbfc6bd2c M [] in MCPackage>snapshot 0x129ca58: a(n) MCPackage
0xbfc6bd48 M BlockClosure>on:do: 0x129cac8: a(n) BlockClosure
0xbfc6bd6c M CurrentReadOnlySourceFiles class>cacheDuring: 0x1baa718: a(n) CurrentReadOnlySourceFiles class
0xbfc6bd94 M MCPackage>snapshot 0x129ca58: a(n) MCPackage
0xbfc6bdb4 M MCPackageLoader>updatePackage:withSnapshot: 0x129cc40: a(n) MCPackageLoader
0xbfc6bde0 I MCPackageLoader class>updatePackage:withSnapshot: 0x1c00d30: a(n) MCPackageLoader class
0xbfc6be08 I MCSnapshot>updatePackage: 0x4148418: a(n) MCSnapshot
0xbfc6be2c I MCMethodDefinitionTest(MCTestCase)>restoreMocks 0x4049e20: a(n) MCMethodDefinitionTest
0xbfc6be44 M MCMethodDefinitionTest>tearDown 0x4049e20: a(n) MCMethodDefinitionTest
0xbfc6be5c M [] in MCMethodDefinitionTest(TestCase)>runCase 0x4049e20: a(n) MCMethodDefinitionTest
0xbfc6be7c M MethodContext(ContextPart)>resume: 0x129c2e0: a(n) MethodContext
0xbfc68c2c M BlockClosure>ensure: 0x129c128: a(n) BlockClosure
0xbfc68c48 M MCMethodDefinitionTest(TestCase)>runCase 0x4049e20: a(n) MCMethodDefinitionTest
0xbfc68c60 M SCISqueakTestRunner(SCITestRunner)>basicRunCase: 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68c80 M [] in SCISqueakTestRunner(SCITestRunner)>runCase: 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68c9c M BlockClosure>on:do: 0x129c218: a(n) BlockClosure
0xbfc68cc4 M [] in SCISqueakTestRunner(SCITestRunner)>runCase: 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68ce0 M BlockClosure>on:do: 0x129c340: a(n) BlockClosure
0xbfc68d08 M [] in SCISqueakTestRunner(SCITestRunner)>runCase: 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68d24 M Time class>millisecondsToRun: 0x1a10700: a(n) Time class
0xbfc68d40 M SmalltalkCI class>timeToRun: 0x3afeee8: a(n) SmalltalkCI class
0xbfc68d64 M SCISqueakTestRunner(SCITestRunner)>runCase: 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68d80 M MCMethodDefinitionTest(TestCase)>run: 0x4049e20: a(n) MCMethodDefinitionTest
0xbfc68d9c M [] in SCISqueakTestRunner(SCITestRunner)>runAll 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68dbc M OrderedCollection>do: 0x401f7f0: a(n) OrderedCollection
0xbfc68de0 I SCISqueakTestRunner(SCITestRunner)>runAll 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68df8 M [] in SCISqueakTestRunner(SCITestRunner)>run 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68e1c I Time class>millisecondsToRun: 0x1a10700: a(n) Time class
0xbfc68e40 I SmalltalkCI class>timeToRun: 0x3afeee8: a(n) SmalltalkCI class
0xbfc68e5c M [] in SCISqueakTestRunner(SCITestRunner)>run 0x4050a68: a(n) SCISqueakTestRunner
0xbfc68e7c M BlockClosure>ensure: 0x4050b80: a(n) BlockClosure
0x4050c10 s SCISqueakTestRunner(SCITestRunner)>run
0x41492c8 s SCISqueakTestRunner class(SCITestRunner class)>runSuite:spec:
0x401e3f0 s SCISqueakTestRunner class(SCITestRunner class)>runClasses:spec:
0x4040da0 s SCISqueakTestRunner class(SCITestRunner class)>runSpec:
0x4148790 s SmalltalkCISqueak(SmalltalkCI)>runTests
0x414a428 s [] in SmalltalkCISqueak(SmalltalkCI)>basicTest
0x3bab9b0 s SmalltalkCISqueak class(SmalltalkCI class)>run:spec:in:
0x401e4c0 s [] in SmalltalkCISqueak(SmalltalkCI)>basicTest
0x4040e00 s [] in SmalltalkCISqueak class(SmalltalkCI class)>fold:on:block:
0x41487f0 s Time class>millisecondsToRun:
0x414a488 s SmalltalkCI class>timeToRun:
0x401e560 s SmalltalkCISqueak class(SmalltalkCI class)>fold:on:block:
0x4040e60 s SmalltalkCISqueak class(SmalltalkCI class)>fold:block:
0x4148850 s SmalltalkCISqueak class(SmalltalkCI class)>stage:id:block:
0x401e5c0 s SmalltalkCISqueak(SmalltalkCI)>basicTest
0x401e620 s [] in SmalltalkCISqueak(SmalltalkCI)>test
0x401da40 s BlockClosure>on:do:
0x401dae0 s [] in SmalltalkCISqueak(SmalltalkCI)>test
0x4040bc0 s [] in SmalltalkCISqueak class(SmalltalkCI class)>withBuildStatusReportingDo:
0x401db70 s BlockClosure>on:do:
0x401dbe8 s SmalltalkCISqueak class(SmalltalkCI class)>withBuildStatusReportingDo:
0x401dc48 s SmalltalkCISqueak(SmalltalkCI)>test
0x4040c20 s SmalltalkCI class>test:projectDirectory:
0x41486d0 s SmalltalkCI class>test:
0x401dd48 s UndefinedObject>DoIt
0x401de88 s Compiler>evaluateCue:ifFail:
0x401df20 s Compiler>evaluateCue:ifFail:logged:
0x4040c80 s Compiler>evaluate:in:to:notifying:ifFail:logged:
0x401e178 s Compiler class>evaluate:for:notifying:logged:
0x4040ce0 s Compiler class>evaluate:for:logged:
0x4148730 s Compiler class>evaluate:logged:
0x414a3c8 s [] in ReadStream(PositionableStream)>fileInAnnouncing:
0x401e1f0 s BlockClosure>on:do:
0x401e268 s [] in ReadStream(PositionableStream)>fileInAnnouncing:
0x4040d40 s [] in MorphicUIManager>displayProgress:at:from:to:during:
0x401e2e8 s BlockClosure>on:do:
0x401e360 s [] in MorphicUIManager>displayProgress:at:from:to:during:
0x401d240 s BlockClosure>ensure:
0x401d2f0 s MorphicUIManager>displayProgress:at:from:to:during:
0x40409e0 s ProgressInitiationException>defaultResumeValue
0x41484f0 s ProgressInitiationException(Exception)>resume
0x414a248 s ProgressInitiationException>defaultAction
0x3bab890 s UndefinedObject>handleSignal:
0x401d3b8 s ProgressInitiationException(Exception)>signal
0x401d418 s ProgressInitiationException>display:at:from:to:during:
0x4040a40 s ProgressInitiationException class>display:at:from:to:during:
0x4148550 s ByteString(String)>displayProgressAt:from:to:during:
0x414a2a8 s ByteString(String)>displayProgressFrom:to:during:
0x401d4a0 s ReadStream(PositionableStream)>fileInAnnouncing:
0x4040aa0 s ReadStream(PositionableStream)>fileIn
0x41485b0 s CodeLoader>installSourceFile:
0x414a308 s [] in CodeLoader>installSourceFiles
0x3bab8f0 s Array(SequenceableCollection)>do:
0x401d780 s CodeLoader>installSourceFiles
0x401d930 s ProjectLauncher>startUpAfterLogin
0x4040b00 s ProjectLauncher>startUp
0x4148610 s [] in AutoStart class>startUp:
0x414a368 s WorldState>runStepMethodsIn:
0x3bab950 s PasteUpMorph>runStepMethods
0x401d9c8 s WorldState>doOneCycleNowFor:
0x4040b60 s WorldState>doOneCycleFor:
0x4148670 s PasteUpMorph>doOneCycle
0x1e09b00 s [] in MorphicProject>spawnNewProcess
0x1ad4dd8 s [] in BlockClosure>newProcess

It' like MCMethodDefinitionTest>tearDown never finish (or is very very long) because MCMockPackageInfo(PackageInfo)>overriddenMethods is very very long.

I don't know what is different on linux32x86 VM compared to OSX, but it would be interesting to understand what's going on exactly...