[squeak-dev] Timing out Trait tests

Nicolas Cellier nicolas.cellier.aka.nice at gmail.com
Mon Jan 13 23:28:45 UTC 2014


2014/1/14 karl ramberg <karlramberg at gmail.com>

> TraitsFileOutTest is failing
>
> Correct log attached this time
>
> Cheers,
> Karl
>
> id:     #[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
means the file was closed...

I observed increasing failure rate related to randomly closed change log
the last few months (particularly when loading/merging with MC), it would
be good to identify the root cause...



>
> On Mon, Jan 13, 2014 at 11:53 PM, karl ramberg <karlramberg at gmail.com>wrote:
>
>> I get a prim failed error on a MultiByteFileStream on Windows 8 running
>> the Traits tests.
>>
>> Cheers,
>> Karl
>>
>>
>> On Mon, Jan 13, 2014 at 10:15 PM, Nicolas Cellier <
>> nicolas.cellier.aka.nice at gmail.com> wrote:
>>
>>>
>>> 2014/1/13 Frank Shearar <frank.shearar at gmail.com>
>>>
>>>> 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
>>>>
>>>> I don't get same figures here:
>>>
>>> 1st run:
>>> **Leaves**
>>> 50.5% {3145ms} CompiledMethod>>originalTraitMethod:
>>> 18.1% {1125ms} Delay>>wait
>>> 11.8% {731ms} MultiByteFileStream>>nextPut:
>>> 5.1% {316ms} Trait(ClassDescription)>>organization
>>> 3.3% {206ms} MultiByteFileStream(StandardFileStream)>>open:forWrite:
>>> 1.7% {108ms} CompiledMethodWithNode>>selector
>>> 1.1% {67ms} ByteSymbol(Symbol)>>=
>>>
>>> 2nd run:
>>>
>>> **Leaves**
>>> 50.5% {1991ms} CompiledMethod>>originalTraitMethod:
>>> 15.7% {617ms} MultiByteFileStream>>nextPut:
>>> 8.8% {346ms} Delay>>wait
>>> 4.6% {180ms} MultiByteFileStream(StandardFileStream)>>open:forWrite:
>>> 3.9% {153ms} Trait(ClassDescription)>>organization
>>> 2.3% {92ms} ByteSymbol(Symbol)>>=
>>> 1.5% {59ms} WeakArray class>>finalizationProcess
>>> 1.4% {54ms} CompiledMethodWithNode>>selector
>>> 1.1% {42ms} Array(SequenceableCollection)>>indexOf:startingAt:ifAbsent:
>>>
>>> Hmm, great variations between 2 runs?
>>> I also note presence of AnObsoleteC1/2 as large consumers... Not that
>>> healthy.
>>>
>>> With an AndreasSystemProfiler, here are the leaves:
>>>
>>> 1st run:
>>> **Leaves**
>>> 57.1 (2,518)  Array  elementsForwardIdentityTo:
>>> 16.4 (722)  StandardFileStream  primWrite:from:startingAt:count:
>>> 6.5 (288)  Symbol  flushCache
>>> 5.7 (252)  StandardFileStream  primOpen:writable:
>>>
>>> 2nd run:
>>> **Leaves**
>>> 64.8 (4,436)  Array  elementsForwardIdentityTo:
>>> 17.3 (1,183)  StandardFileStream  primWrite:from:startingAt:count:
>>> 4.6 (318)  Symbol  flushCache
>>> 4.1 (282)  StandardFileStream  primOpen:writable:
>>>
>>> Though I failed to find the direct call to elementsForwardIdentityTo: in
>>> the send chain (probably thru becomeForward:)...
>>>
>>>
>>>
>>>
>>>
>>
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.squeakfoundation.org/pipermail/squeak-dev/attachments/20140114/1a79bc4a/attachment.htm


More information about the Squeak-dev mailing list