TraitsFileOutTest is failing

Correct log attached this time

Cheers,

Karl

On Mon, Jan 13, 2014 at 11:53 PM, karl ramberg <karlramberg@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@gmail.com> wrote:

2014/1/13 Frank Shearar <frank.shearar@gmail.com>

On 11 January 2014 22:55, Frank Shearar <frank.shearar@gmail.com> wrote:
> On 11 January 2014 19:19, tim Rowledge <tim@rowledge.org> wrote:
>>
>> On 11-01-2014, at 6:29 AM, Frank Shearar <frank.shearar@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:)...