Stalled travis_tests in linux32x86

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
12 messages Options
Reply | Threaded
Open this post in threaded view
|

Stalled travis_tests in linux32x86

Nicolas Cellier
 
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...
Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

fniephaus
 
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 <[hidden email]> 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...
Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Nicolas Cellier
 
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 <[hidden email]>:
 
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 <[hidden email]> 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...



exploreSourceFiles.png (86K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Nicolas Cellier
 
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 <[hidden email]>:
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 <[hidden email]>:
 
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 <[hidden email]> 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...



Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Nicolas Cellier
 
OK, it's more complex (readLimit only refers to available buffer length not file length) and more simple than that...

Just trying with:

../../../products/sqcogspurlinux/lib/squeak/5.0-201711262336/squeak TravisCI.image test.st

letting it run a few minutes and interrupting it, I'm in the infinite loop (nextChunk = '').
That's because the method thinks it is written at position 11319975 (it might differ for you, because I launched the test.st several times)
But the read only copy thinks it is already atEnd at position 11320088
So it reads an empty chunk without making progress and will loop infinitely...

I think that (SourceFiles at: 2) was not flushed and the readOnlyCopy is then shorten.
This happens only in linux, because only in recent linux we have this problem that opening an already opened file does not take care of pending buffer of already opened file...

We can work around for now by forcing a flush in readOnlyCopy:

StandardFileStream>>readOnlyCopy
    self flush.
    ^ self class readOnlyFileNamed: self name.

Having this method in the image lets the tests pass in linux...



2017-12-04 23:19 GMT+01:00 Nicolas Cellier <[hidden email]>:
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 <[hidden email]>:
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 <[hidden email]>:
 
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 <[hidden email]> 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...




Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Nicolas Cellier
 


2017-12-05 23:02 GMT+01:00 Nicolas Cellier <[hidden email]>:
OK, it's more complex (readLimit only refers to available buffer length not file length) and more simple than that...

Just trying with:

../../../products/sqcogspurlinux/lib/squeak/5.0-201711262336/squeak TravisCI.image test.st

letting it run a few minutes and interrupting it, I'm in the infinite loop (nextChunk = '').
That's because the method thinks it is written at position 11319975 (it might differ for you, because I launched the test.st several times)
But the read only copy thinks it is already atEnd at position 11320088
So it reads an empty chunk without making progress and will loop infinitely...


Ahem, I don't remember to which substance I was exposed yesterday, those are the wrong figures...
But the diagnosis is correct/reproducible today:

10483842 is the position where we search for method source
10483729 is the current (file position) and (file atEnd) is true, so we cannot go beyond that...
The readOnlyCopy looks like truncated...

Flushing the original before doing a readOnlyCopy is an effective workaround.

I think that (SourceFiles at: 2) was not flushed and the readOnlyCopy is then shorten.
This happens only in linux, because only in recent linux we have this problem that opening an already opened file does not take care of pending buffer of already opened file...

We can work around for now by forcing a flush in readOnlyCopy:

StandardFileStream>>readOnlyCopy
    self flush.
    ^ self class readOnlyFileNamed: self name.

Having this method in the image lets the tests pass in linux...



2017-12-04 23:19 GMT+01:00 Nicolas Cellier <[hidden email]>:
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 <[hidden email]>:
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 <[hidden email]>:
 
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 <[hidden email]> 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...





Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Ben Coman
 


On 7 December 2017 at 05:05, Nicolas Cellier <[hidden email]> wrote:
 


2017-12-05 23:02 GMT+01:00 Nicolas Cellier <[hidden email]>:
OK, it's more complex (readLimit only refers to available buffer length not file length) and more simple than that...

Just trying with:

../../../products/sqcogspurlinux/lib/squeak/5.0-201711262336/squeak TravisCI.image test.st

letting it run a few minutes and interrupting it, I'm in the infinite loop (nextChunk = '').
That's because the method thinks it is written at position 11319975 (it might differ for you, because I launched the test.st several times)
But the read only copy thinks it is already atEnd at position 11320088
So it reads an empty chunk without making progress and will loop infinitely...


Ahem, I don't remember to which substance I was exposed yesterday, those are the wrong figures...


A HeinekenBug?   Like a Heisenbug, but more amber.
cheers -ben

 
But the diagnosis is correct/reproducible today:

10483842 is the position where we search for method source
10483729 is the current (file position) and (file atEnd) is true, so we cannot go beyond that...
The readOnlyCopy looks like truncated...

Flushing the original before doing a readOnlyCopy is an effective workaround.

I think that (SourceFiles at: 2) was not flushed and the readOnlyCopy is then shorten.
This happens only in linux, because only in recent linux we have this problem that opening an already opened file does not take care of pending buffer of already opened file...

We can work around for now by forcing a flush in readOnlyCopy:

StandardFileStream>>readOnlyCopy
    self flush.
    ^ self class readOnlyFileNamed: self name.

Having this method in the image lets the tests pass in linux...



2017-12-04 23:19 GMT+01:00 Nicolas Cellier <[hidden email]>:
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 <[hidden email]>:
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 <[hidden email]>:
 
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 <[hidden email]> 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...







Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Nicolas Cellier
 


2017-12-06 23:13 GMT+01:00 Ben Coman <[hidden email]>:
 


On 7 December 2017 at 05:05, Nicolas Cellier <[hidden email]> wrote:
 


2017-12-05 23:02 GMT+01:00 Nicolas Cellier <[hidden email]>:
OK, it's more complex (readLimit only refers to available buffer length not file length) and more simple than that...

Just trying with:

../../../products/sqcogspurlinux/lib/squeak/5.0-201711262336/squeak TravisCI.image test.st

letting it run a few minutes and interrupting it, I'm in the infinite loop (nextChunk = '').
That's because the method thinks it is written at position 11319975 (it might differ for you, because I launched the test.st several times)
But the read only copy thinks it is already atEnd at position 11320088
So it reads an empty chunk without making progress and will loop infinitely...


Ahem, I don't remember to which substance I was exposed yesterday, those are the wrong figures...


A HeinekenBug?   Like a Heisenbug, but more amber.
cheers -ben

 

:)

I shudder to think how horrible a bugweiser could be!

Since ESUG 2016 in Prague I recommend pils: it helps understanding the VM, or at least let you think so.

Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

timrowledge
 

> On 06-12-2017, at 2:30 PM, Nicolas Cellier <[hidden email]> wrote:
>
> I shudder to think how horrible a bugweiser could be!
>

It would just a be  a watered down bug that made you vaguely sick afterwards

> Since ESUG 2016 in Prague I recommend pils: it helps understanding the VM, or at least let you think so.

Like QM, when you think you understand the VM it is just evidence that you don't understand just how much trouble you’re in..

tim
--
tim Rowledge; [hidden email]; http://www.rowledge.org/tim
Oxymorons: Living dead


Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

David T. Lewis
In reply to this post by Nicolas Cellier
 
On Wed, Dec 06, 2017 at 11:30:37PM +0100, Nicolas Cellier wrote:

>  
> 2017-12-06 23:13 GMT+01:00 Ben Coman <[hidden email]>:
>
> >
> > On 7 December 2017 at 05:05, Nicolas Cellier <nicolas.cellier.aka.nice@
> > gmail.com> wrote:
> >
> >>
> >> 2017-12-05 23:02 GMT+01:00 Nicolas Cellier <nicolas.cellier.aka.nice@gmai
> >> l.com>:
> >>
> >>> OK, it's more complex (readLimit only refers to available buffer length
> >>> not file length) and more simple than that...
> >>>
> >>> Just trying with:
> >>>
> >>> ../../../products/sqcogspurlinux/lib/squeak/5.0-201711262336/squeak
> >>> TravisCI.image test.st
> >>>
> >>> letting it run a few minutes and interrupting it, I'm in the infinite
> >>> loop (nextChunk = '').
> >>> That's because the method thinks it is written at position 11319975 (it
> >>> might differ for you, because I launched the test.st several times)
> >>> But the read only copy thinks it is already atEnd at position 11320088
> >>> So it reads an empty chunk without making progress and will loop
> >>> infinitely...
> >>>
> >>>
> >> Ahem, I don't remember to which substance I was exposed yesterday, those
> >> are the wrong figures...
> >>
> >
> > A HeinekenBug?   Like a Heisenbug, but more amber.
> > cheers -ben
> >
>
> :)
>
> I shudder to think how horrible a bugweiser could be!
>
> Since ESUG 2016 in Prague I recommend pils: it helps understanding the VM,
> or at least let you think so.

A good pils is hard to beat, although I prefer something a bit hoppier. But
local preferences aside, "Bugweiser" is brilliant. I want to buy the Bugweiser
T-shirt.

Best of all, googling "bugweiser" turns up no hits at all, so Nicolas can take
credit for it. And Ben gets the credit (and/or blame?) for provoking the idea.

Normally I would not be concerned with intellectual property rights in a
case like this, but when I think of the potential revenues from Bugwieser
T-shirts, I think it is important to give credit where credit is due.

;-)

Dave

Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

Ben Coman
 
On 7 December 2017 at 11:45, David T. Lewis <[hidden email]> wrote:

>
> On Wed, Dec 06, 2017 at 11:30:37PM +0100, Nicolas Cellier wrote:
>>
>> 2017-12-06 23:13 GMT+01:00 Ben Coman <[hidden email]>:
>>
>> >
>> > On 7 December 2017 at 05:05, Nicolas Cellier <nicolas.cellier.aka.nice@
>> > gmail.com> wrote:
>> >
>> >>
>> >> 2017-12-05 23:02 GMT+01:00 Nicolas Cellier <nicolas.cellier.aka.nice@gmai
>> >> l.com>:
>> >>
>> >> Ahem, I don't remember to which substance I was exposed yesterday, those
>> >> are the wrong figures...
>> >>
>> >
>> > A HeinekenBug?   Like a Heisenbug, but more amber.
>> > cheers -ben
>> >
>>
>> :)
>>
>> I shudder to think how horrible a bugweiser could be!
>>
>> Since ESUG 2016 in Prague I recommend pils: it helps understanding the VM,
>> or at least let you think so.
>
> A good pils is hard to beat, although I prefer something a bit hoppier. But
> local preferences aside, "Bugweiser" is brilliant. I want to buy the Bugweiser
> T-shirt.

But I'm not sure...  Does this mean you're getting better at squashing bugs,
or that the bugs are learning to fight back?

cheers -ben

>
> Best of all, googling "bugweiser" turns up no hits at all, so Nicolas can take
> credit for it. And Ben gets the credit (and/or blame?) for provoking the idea.
>
> Normally I would not be concerned with intellectual property rights in a
> case like this, but when I think of the potential revenues from Bugwieser
> T-shirts, I think it is important to give credit where credit is due.
>
> ;-)
>
> Dave
>
Reply | Threaded
Open this post in threaded view
|

Re: Stalled travis_tests in linux32x86

David T. Lewis
 
On Thu, Dec 07, 2017 at 12:20:55PM +0800, Ben Coman wrote:

>  
> On 7 December 2017 at 11:45, David T. Lewis <[hidden email]> wrote:
> >
> > On Wed, Dec 06, 2017 at 11:30:37PM +0100, Nicolas Cellier wrote:
> >>
> >> 2017-12-06 23:13 GMT+01:00 Ben Coman <[hidden email]>:
> >> >
> >> > On 7 December 2017 at 05:05, Nicolas Cellier <nicolas.cellier.aka.nice@
> >> > gmail.com> wrote:
> >> >>
> >> >> 2017-12-05 23:02 GMT+01:00 Nicolas Cellier <nicolas.cellier.aka.nice@gmai
> >> >> l.com>:
> >> >>
> >> >> Ahem, I don't remember to which substance I was exposed yesterday, those
> >> >> are the wrong figures...
> >> >
> >> > A HeinekenBug?   Like a Heisenbug, but more amber.
> >> > cheers -ben
> >>
> >> :)
> >>
> >> I shudder to think how horrible a bugweiser could be!
> >>
> >> Since ESUG 2016 in Prague I recommend pils: it helps understanding the VM,
> >> or at least let you think so.
> >
> > A good pils is hard to beat, although I prefer something a bit hoppier. But
> > local preferences aside, "Bugweiser" is brilliant. I want to buy the Bugweiser
> > T-shirt.
>
> But I'm not sure...  Does this mean you're getting better at squashing bugs,
> or that the bugs are learning to fight back?

I am not really interested in spending time on squashing bugs, but I am interested
in preventing them and understanding where the bugs come from in the first place.
Bugweiser seems like a plausible explanation for quite a wide class of issues ;-)

Dave