[squeak-dev] Timing out Trait testsFrank Shearar frank.shearar at gmail.comMon Jan 13 19:52:59 UTC 2014
On 11 January 2014 22:55, Frank Shearar <frank.shearar at gmail.com> wrote: > On 11 January 2014 19:19, tim Rowledge <tim at rowledge.org> wrote: >> >> On 11-01-2014, at 6:29 AM, Frank Shearar <frank.shearar at gmail.com> wrote: >> >>> A bunch of the Trait tests fail, despite no one having worked on the >>> Traits code in quite a while. The symptom is that the tests time out >>> [1]. I've tried to debug some, only to find that they pass. For >>> instance, <timeout: 60> sometimes "fixes" the tests. >>> >>> But the tests shouldn't be failing. Any takers? >> >> I noticed similar issues when running test on a Pi; being a relatively slow machine it takes longer to do some things and needed a larger timeout value. >> >> If tests that used to run within the time are now taking longer but still pass if given enough time, that implies to me that either >> a) the tests are being run on a slower machine due to some system configuration change (are other jobs also running and taking time?) >> b) something has changed in the execution path to slow down the tested code. Which obviously, ought not be the case. > > They time out on my beefy work laptop: a 2.7 GHz machine. That's > probably a higher spec machine than the build server. > > If I was a betting man I'd be inclined to put my money on (b). Attached is the output of MessageTally spyOn: [[TraitCompositionTest debug: #testAliasCompositions] on: TestFailure do: [#fail]], after adding <timeout: 60> to the test. The leaves are very interesting: **Leaves** 43.1% {28650ms} CompiledMethod>>originalTraitMethod: 36.9% {24505ms} Text>>size 9.7% {6425ms} Delay>>wait 3.4% {2239ms} SecurityManager class>>default 1.1% {749ms} CompiledMethod>>checkOKToAdd:at: _24 seconds_ in Text >> #size ?! Also, CompiledMethod>>originalTraitMethod: hasn't changed in 4 years. In fact the only things that have changed, that I can see, in the code path are Chris Muller's fixing of TestCase >> #debug and Nicolas Cellier's cleanup of the Compiler API. Nothing looks even remotely capable of slowing stuff down this dramatically. frank -------------- next part -------------- - 66321 tallies, 66496 msec. **Tree** -------------------------------- Process: other processes -------------------------------- 9.7% {6427ms} EventSensor>>eventTickler 9.7% {6425ms} Delay>>wait -------------------------------- Process: (40s) 30120: nil -------------------------------- 90.1% {59929ms} TraitCompositionTest(TestCase)>>debug 80.2% {53345ms} TraitCompositionTest(TestCase)>>runCase |78.8% {52408ms} TraitCompositionTest(TestCase)>>performTest | |78.8% {52408ms} TraitCompositionTest>>testAliasCompositions | | 48.5% {32241ms} Trait(ClassDescription)>>uses: | | |48.5% {32241ms} Trait(TraitDescription)>>installTraitsFrom: | | | 35.0% {23274ms} Trait(ClassDescription)>>installTraitsFrom: | | | |33.7% {22394ms} Trait(ClassDescription)>>installTraitMethodDict: | | | | |21.7% {14426ms} TraitOrganizer(Categorizer)>>classify:under: | | | | | |21.7% {14426ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault: | | | | | | 21.7% {14424ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault:logged: | | | | | | 21.7% {14424ms} TraitOrganizer(ClassOrganizer)>>notifyOfChangedSelector:from:to: | | | | | | 21.7% {14424ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | | | | | 21.2% {14122ms} Trait(ClassDescription)>>classify:under:from:trait: | | | | | | 21.2% {14122ms} Trait(ClassDescription)>>updateTraits | | | | | | 21.2% {14122ms} Trait(TraitDescription)>>installTraitsFrom: | | | | | | 19.1% {12706ms} Trait(ClassDescription)>>installTraitsFrom: | | | | | | |16.5% {10985ms} Trait(ClassDescription)>>installTraitMethodDict: | | | | | | | |13.4% {8906ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | | | | | |7.3% {4858ms} CompiledMethod>>originalTraitMethod: | | | | | | | | | |7.3% {4838ms} primitives | | | | | | | | |5.8% {3871ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | | | | | | 5.8% {3834ms} Text>>size | | | | | | | |3.0% {1970ms} TraitOrganizer(Categorizer)>>classify:under: | | | | | | | | 3.0% {1970ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault: | | | | | | | | 3.0% {1970ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault:logged: | | | | | | | | 3.0% {1967ms} TraitOrganizer(ClassOrganizer)>>notifyOfChangedSelector:from:to: | | | | | | | | 3.0% {1965ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | | | | | | | 2.0% {1337ms} AnObsoleteC2 class(ClassDescription)>>classify:under:from:trait: | | | | | | | | 2.0% {1337ms} AnObsoleteC2 class(ClassDescription)>>updateTraits | | | | | | | | 2.0% {1337ms} AnObsoleteC2 class(ClassDescription)>>installTraitsFrom: | | | | | | | | 2.0% {1334ms} AnObsoleteC2 class(ClassDescription)>>installTraitMethodDict: | | | | | | | | 1.8% {1177ms} AnObsoleteC2 class(ClassDescription)>>traitAddSelector:withMethod: | | | | | | | | 1.1% {751ms} CompiledMethod>>originalTraitMethod: | | | | | | | | 1.1% {748ms} primitives | | | | | | |2.6% {1719ms} ClassTrait(ClassDescription)>>updateTraitsFrom: | | | | | | | 2.6% {1716ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | | | | | | 2.6% {1714ms} ClassTrait(ClassDescription)>>installTraitsFrom: | | | | | | | 2.6% {1711ms} ClassTrait(ClassDescription)>>installTraitMethodDict: | | | | | | | 2.5% {1693ms} ClassTrait(ClassDescription)>>traitAddSelector:withMethod: | | | | | | | 1.3% {883ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | | | | |1.3% {876ms} Text>>size | | | | | | | 1.2% {780ms} CompiledMethod>>originalTraitMethod: | | | | | | | 1.2% {776ms} primitives | | | | | | 2.1% {1416ms} AnObsoleteC2 class(ClassDescription)>>updateTraits | | | | | | 2.1% {1416ms} AnObsoleteC2 class(ClassDescription)>>installTraitsFrom: | | | | | | 2.1% {1413ms} AnObsoleteC2 class(ClassDescription)>>installTraitMethodDict: | | | | | | 2.1% {1392ms} AnObsoleteC2 class(ClassDescription)>>traitAddSelector:withMethod: | | | | | | 1.1% {720ms} CompiledMethod>>originalTraitMethod: | | | | | | 1.1% {716ms} primitives | | | | |9.7% {6426ms} Trait(ClassDescription)>>traitRemoveSelector: | | | | | |9.4% {6259ms} TraitOrganizer(ClassOrganizer)>>removeElement: | | | | | | 9.4% {6257ms} TraitOrganizer(ClassOrganizer)>>notifyOfChangedSelector:from:to: | | | | | | 9.4% {6257ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | | | | | 9.4% {6257ms} Trait(ClassDescription)>>classify:under:from:trait: | | | | | | 9.4% {6257ms} Trait(ClassDescription)>>updateTraits | | | | | | 9.4% {6257ms} Trait(TraitDescription)>>installTraitsFrom: | | | | | | 8.0% {5349ms} Trait(ClassDescription)>>installTraitsFrom: | | | | | | |6.9% {4605ms} Trait(ClassDescription)>>installTraitMethodDict: | | | | | | | |6.9% {4559ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | | | | | 4.0% {2679ms} CompiledMethod>>originalTraitMethod: | | | | | | | | |4.0% {2670ms} primitives | | | | | | | | 2.7% {1797ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | | | | | 2.7% {1776ms} Text>>size | | | | | | |1.1% {739ms} ClassTrait(ClassDescription)>>updateTraitsFrom: | | | | | | | 1.1% {739ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | | | | | | 1.1% {739ms} ClassTrait(ClassDescription)>>installTraitsFrom: | | | | | | | 1.1% {735ms} ClassTrait(ClassDescription)>>installTraitMethodDict: | | | | | | | 1.1% {728ms} ClassTrait(ClassDescription)>>traitAddSelector:withMethod: | | | | | | 1.4% {908ms} AnObsoleteC2 class(ClassDescription)>>updateTraits | | | | | | 1.4% {908ms} AnObsoleteC2 class(ClassDescription)>>installTraitsFrom: | | | | | | 1.4% {907ms} AnObsoleteC2 class(ClassDescription)>>installTraitMethodDict: | | | | | | 1.4% {902ms} AnObsoleteC2 class(ClassDescription)>>traitAddSelector:withMethod: | | | | |2.3% {1526ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | | 1.3% {875ms} CompiledMethod>>originalTraitMethod: | | | | | 1.3% {869ms} primitives | | | |1.3% {879ms} ClassTrait(ClassDescription)>>updateTraitsFrom: | | | | 1.3% {879ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | | | 1.3% {877ms} ClassTrait(ClassDescription)>>updateTraits | | | | 1.3% {877ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | | | 1.3% {876ms} ClassTrait(ClassDescription)>>installTraitsFrom: | | | | 1.3% {875ms} ClassTrait(ClassDescription)>>installTraitMethodDict: | | | | 1.3% {867ms} ClassTrait(ClassDescription)>>traitAddSelector:withMethod: | | | 13.5% {8967ms} Trait(ClassDescription)>>updateTraits | | | 13.5% {8967ms} Trait(TraitDescription)>>installTraitsFrom: | | | 11.8% {7815ms} Trait(ClassDescription)>>installTraitsFrom: | | | |10.3% {6856ms} Trait(ClassDescription)>>installTraitMethodDict: | | | | |8.7% {5773ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | | |5.2% {3464ms} CompiledMethod>>originalTraitMethod: | | | | | | |5.2% {3455ms} primitives | | | | | |3.3% {2219ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | | | 3.3% {2200ms} Text>>size | | | | |1.5% {1001ms} Trait(ClassDescription)>>traitRemoveSelector: | | | | | 1.1% {711ms} TraitOrganizer(ClassOrganizer)>>removeElement: | | | | | 1.1% {709ms} TraitOrganizer(ClassOrganizer)>>notifyOfChangedSelector:from:to: | | | | | 1.1% {709ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | | | | 1.1% {709ms} AnObsoleteC2 class(ClassDescription)>>classify:under:from:trait: | | | | | 1.1% {709ms} AnObsoleteC2 class(ClassDescription)>>updateTraits | | | | | 1.1% {709ms} AnObsoleteC2 class(ClassDescription)>>installTraitsFrom: | | | | | 1.1% {707ms} AnObsoleteC2 class(ClassDescription)>>installTraitMethodDict: | | | | | 1.0% {694ms} AnObsoleteC2 class(ClassDescription)>>traitAddSelector:withMethod: | | | |1.4% {955ms} ClassTrait(ClassDescription)>>updateTraitsFrom: | | | | 1.4% {955ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | | | 1.4% {955ms} ClassTrait(ClassDescription)>>installTraitsFrom: | | | | 1.4% {955ms} ClassTrait(ClassDescription)>>installTraitMethodDict: | | | | 1.4% {946ms} ClassTrait(ClassDescription)>>traitAddSelector:withMethod: | | | 1.7% {1152ms} AnObsoleteC2 class(ClassDescription)>>updateTraits | | | 1.7% {1152ms} AnObsoleteC2 class(ClassDescription)>>installTraitsFrom: | | | 1.7% {1151ms} AnObsoleteC2 class(ClassDescription)>>installTraitMethodDict: | | | 1.5% {986ms} AnObsoleteC2 class(ClassDescription)>>traitAddSelector:withMethod: | | 30.3% {20159ms} Trait(Behavior)>>compile: | | 30.3% {20159ms} Trait(ClassDescription)>>compile:notifying: | | 30.3% {20159ms} Trait(ClassDescription)>>compile:classified:notifying: | | 30.3% {20159ms} Trait(ClassDescription)>>compile:classified:withStamp:notifying: | | 30.3% {20159ms} Trait(ClassDescription)>>compile:classified:withStamp:notifying:logSource: | | 30.1% {20014ms} Trait(ClassDescription)>>addAndClassifySelector:withMethod:inProtocol:notifying: | | 17.9% {11892ms} Trait(TraitDescription)>>addSelectorSilently:withMethod: | | |17.9% {11883ms} Trait(ClassDescription)>>updateTraits | | | 17.9% {11883ms} Trait(TraitDescription)>>installTraitsFrom: | | | 12.6% {8403ms} Trait(ClassDescription)>>installTraitsFrom: | | | |11.3% {7533ms} Trait(ClassDescription)>>installTraitMethodDict: | | | | |7.0% {4624ms} TraitOrganizer(Categorizer)>>classify:under: | | | | | |7.0% {4624ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault: | | | | | | 7.0% {4624ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault:logged: | | | | | | 7.0% {4622ms} TraitOrganizer(ClassOrganizer)>>notifyOfChangedSelector:from:to: | | | | | | 7.0% {4622ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | | | | | 6.9% {4561ms} Trait(ClassDescription)>>classify:under:from:trait: | | | | | | 6.9% {4561ms} Trait(ClassDescription)>>updateTraits | | | | | | 6.9% {4561ms} Trait(TraitDescription)>>installTraitsFrom: | | | | | | 6.2% {4151ms} Trait(ClassDescription)>>installTraitsFrom: | | | | | | 5.7% {3794ms} Trait(ClassDescription)>>installTraitMethodDict: | | | | | | 4.1% {2699ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | | | |2.4% {1587ms} CompiledMethod>>originalTraitMethod: | | | | | | | |2.4% {1582ms} primitives | | | | | | |1.6% {1060ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | | | | 1.6% {1052ms} Text>>size | | | | | | 1.6% {1053ms} TraitOrganizer(Categorizer)>>classify:under: | | | | | | 1.6% {1053ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault: | | | | | | 1.6% {1053ms} TraitOrganizer(ClassOrganizer)>>classify:under:suppressIfDefault:logged: | | | | | | 1.6% {1052ms} TraitOrganizer(ClassOrganizer)>>notifyOfChangedSelector:from:to: | | | | | | 1.6% {1052ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | | | | | 1.2% {799ms} AnObsoleteC2 class(ClassDescription)>>classify:under:from:trait: | | | | | | 1.2% {799ms} AnObsoleteC2 class(ClassDescription)>>updateTraits | | | | | | 1.2% {799ms} AnObsoleteC2 class(ClassDescription)>>installTraitsFrom: | | | | | | 1.2% {797ms} AnObsoleteC2 class(ClassDescription)>>installTraitMethodDict: | | | | | | 1.1% {714ms} AnObsoleteC2 class(ClassDescription)>>traitAddSelector:withMethod: | | | | |4.3% {2873ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | | 2.1% {1410ms} CompiledMethod>>originalTraitMethod: | | | | | |2.1% {1405ms} primitives | | | | | 2.1% {1393ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | | 2.1% {1374ms} Text>>size | | | |1.3% {867ms} ClassTrait(ClassDescription)>>updateTraitsFrom: | | | | 1.3% {867ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | | 5.2% {3480ms} Trait(ClassDescription)>>updateTraits | | | 4.6% {3055ms} Trait(TraitDescription)>>installTraitsFrom: | | | 4.0% {2692ms} Trait(ClassDescription)>>installTraitsFrom: | | | 3.3% {2175ms} Trait(ClassDescription)>>installTraitMethodDict: | | | 3.2% {2136ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | 1.6% {1065ms} CompiledMethod>>originalTraitMethod: | | | |1.6% {1058ms} primitives | | | 1.6% {1034ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | 1.5% {1011ms} Text>>size | | 12.2% {8113ms} ClassOrganizer(Categorizer)>>classify:under: | | 12.2% {8113ms} ClassOrganizer>>classify:under:suppressIfDefault: | | 12.2% {8113ms} ClassOrganizer>>classify:under:suppressIfDefault:logged: | | 12.2% {8113ms} ClassOrganizer>>notifyOfChangedSelector:from:to: | | 12.2% {8113ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | | 12.2% {8113ms} Trait(ClassDescription)>>classify:under:from:trait: | | 12.2% {8113ms} Trait(ClassDescription)>>updateTraits | | 12.2% {8113ms} Trait(TraitDescription)>>installTraitsFrom: | | 6.2% {4125ms} Trait(ClassDescription)>>installTraitsFrom: | | |4.8% {3212ms} Trait(ClassDescription)>>installTraitMethodDict: | | | |4.8% {3180ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | | | 2.6% {1711ms} CompiledMethod>>originalTraitMethod: | | | | |2.6% {1704ms} primitives | | | | 2.1% {1387ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | | | 2.1% {1370ms} Text>>size | | |1.4% {909ms} ClassTrait(ClassDescription)>>updateTraitsFrom: | | | 1.4% {907ms} ClassTrait(TraitDescription)>>installTraitsFrom: | | 6.0% {3988ms} Trait(ClassDescription)>>updateTraits | | 5.2% {3474ms} Trait(TraitDescription)>>installTraitsFrom: | | 4.6% {3033ms} Trait(ClassDescription)>>installTraitsFrom: | | 4.0% {2636ms} Trait(ClassDescription)>>installTraitMethodDict: | | 3.9% {2603ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | | 2.0% {1299ms} CompiledMethod>>originalTraitMethod: | | |2.0% {1297ms} primitives | | 1.8% {1225ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | | 1.8% {1212ms} Text>>size |1.4% {937ms} TraitCompositionTest(TraitsTestCase)>>tearDown | 1.4% {937ms} TraitsResource class>>resetIfDirty | 1.4% {937ms} TraitsResource class(TestResource class)>>reset | 1.4% {937ms} TraitsResource>>tearDown 9.9% {6583ms} TraitsResource class(TestResource class)>>isAvailable 9.9% {6583ms} TraitsResource class(TestResource class)>>current 9.9% {6583ms} TraitsResource class(Behavior)>>new 9.9% {6583ms} TraitsResource(TestResource)>>initialize 9.9% {6583ms} TraitsResource>>setUp 7.9% {5257ms} Trait(ClassDescription)>>compile:classified: 7.9% {5257ms} Trait(ClassDescription)>>compile:classified:notifying: 7.9% {5246ms} Trait(ClassDescription)>>compile:classified:withStamp:notifying: 7.9% {5246ms} Trait(ClassDescription)>>compile:classified:withStamp:notifying:logSource: 6.9% {4566ms} Trait(ClassDescription)>>addAndClassifySelector:withMethod:inProtocol:notifying: 3.5% {2353ms} ClassOrganizer(Categorizer)>>classify:under: |3.5% {2353ms} ClassOrganizer>>classify:under:suppressIfDefault: | 3.5% {2353ms} ClassOrganizer>>classify:under:suppressIfDefault:logged: | 3.5% {2351ms} ClassOrganizer>>notifyOfChangedSelector:from:to: | 3.5% {2349ms} Trait(TraitDescription)>>notifyOfRecategorizedSelector:from:to: | 3.5% {2349ms} Trait(ClassDescription)>>classify:under:from:trait: | 3.5% {2349ms} Trait(ClassDescription)>>updateTraits | 3.5% {2349ms} Trait(TraitDescription)>>installTraitsFrom: | 3.5% {2349ms} Trait(ClassDescription)>>installTraitsFrom: | 2.8% {1837ms} Trait(ClassDescription)>>installTraitMethodDict: | 2.7% {1814ms} Trait(ClassDescription)>>traitAddSelector:withMethod: | 1.6% {1084ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: | |1.6% {1047ms} Text>>size | 1.0% {684ms} CompiledMethod>>originalTraitMethod: | 1.0% {677ms} primitives 3.3% {2212ms} Trait(TraitDescription)>>addSelectorSilently:withMethod: 3.3% {2196ms} Trait(ClassDescription)>>updateTraits 3.3% {2196ms} Trait(TraitDescription)>>installTraitsFrom: 3.3% {2196ms} Trait(ClassDescription)>>installTraitsFrom: 2.6% {1722ms} Trait(ClassDescription)>>installTraitMethodDict: 2.6% {1696ms} Trait(ClassDescription)>>traitAddSelector:withMethod: 1.7% {1131ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble: 1.7% {1116ms} Text>>size **Leaves** 43.1% {28650ms} CompiledMethod>>originalTraitMethod: 36.9% {24505ms} Text>>size 9.7% {6425ms} Delay>>wait 3.4% {2239ms} SecurityManager class>>default 1.1% {749ms} CompiledMethod>>checkOKToAdd:at: **Memory** old +759,580 bytes young -296,592 bytes used +462,988 bytes free -462,988 bytes **GCs** full 0 totalling 0 ms (0% uptime) incr 4 totalling 85 ms (0.1% uptime), avg 21.3 ms tenures 2 (avg 2 GCs/tenure) root table 0 overflows
More information about the Squeak-dev mailing list |