[BUG?] Slow file writing due to excessive GC

Henrik Gedenryd Henrik.Gedenryd at lucs.lu.se
Tue Oct 9 15:07:43 UTC 2001


When I file out a few files of source code in a fairly standard manner, I
get a very weird timing profile: Roughly half the time is spent on garbage
collection, even though Squeak reports 80M of free RAM, and the
open:forWrite: shouldn't fail for any other reason I have been able to find.
Some typical code for reproducing this is:

MessageTally spyOn: [
    {ClassOrganizer. StandardFileStream. SystemDictionary.
            WriteStream. Symbol. DisplayScreen}
        do: [:c | c fileOut]]

Can anyone explain this behavior? This is a Mac VM (3.1.1, but it oughtn't
matter).

Henrik


- 510 tallies, 8804 msec.

**Tree**
100.0% {8804ms} ClassOrganizer class(Class)>>fileOut
  100.0% {8804ms} ClassOrganizer class(Class)>>fileOutAsHtml:
    45.7% {4023ms} FileStream class>>newFileNamed:
      |45.7% {4023ms} StandardFileStream class>>newFileNamed:
      |  45.7% {4023ms} StandardFileStream class>>isAFileNamed:
      |    45.7% {4023ms} StandardFileStream>>open:forWrite:
      |      45.7% {4023ms} StandardFileStream(Object)>>retryWithGC:until:
      |        45.7% {4023ms} SystemDictionary>>garbageCollect
    44.7% {3935ms} ClassOrganizer class(Class)>>fileOutOn:moveSource:toFile:
      |44.7% {3935ms} ClassOrganizer
class(Class)>>fileOutOn:moveSource:toFile:initializing:
      |  42.0% {3698ms} ClassOrganizer
class(ClassDescription)>>fileOutOn:moveSource:toFile:
      |    |41.2% {3627ms} ClassOrganizer
class(ClassDescription)>>fileOutCategory:on:moveSource:toFile:
      |    |  41.2% {3627ms} ClassOrganizer
class(ClassDescription)>>printMethodChunk:with...n:moveSource:toFile:
      |    |    25.9% {2280ms}
StandardFileStream(PositionableStream)>>copyMethodChunkFrom:
      |    |      |25.9% {2280ms}
StandardFileStream(PositionableStream)>>nextChunkText
      |    |      |  23.1% {2034ms}
StandardFileStream(PositionableStream)>>nextChunk
      |    |      |    |10.6% {933ms} WriteStream>>nextPut:
      |    |      |    |8.8% {775ms} StandardFileStream>>next
      |    |      |    |  |5.1% {449ms} primitives
      |    |      |    |  |3.7% {326ms} StandardFileStream>>basicNext
      |    |      |    |3.3% {291ms} primitives
      |    |      |  2.2% {194ms}
StandardFileStream(PositionableStream)>>skipSeparatorsAndPeekNext
      |    |    11.4% {1004ms}
StandardFileStream(PositionableStream)>>copyPreamble:from:
      |    |      |10.4% {916ms} StandardFileStream>>next:
      |    |      |  10.4% {916ms}
StandardFileStream(PositionableStream)>>nextInto:
      |    |      |    10.4% {916ms}
StandardFileStream>>next:into:startingAt:
      |    |    2.4% {211ms} ClassOrganizer>>categoryOfElement:
      |    |      2.4% {211ms} ClassOrganizer>>numberOfCategoryOfElement:
      |  2.7% {238ms} Metaclass>>fileOutOn:moveSource:toFile:initializing:
      |    2.7% {238ms}
Metaclass(ClassDescription)>>fileOutOn:moveSource:toFile:
      |      2.7% {238ms}
Metaclass(ClassDescription)>>fileOutCategory:on:moveSource:toFile:
      |        2.7% {238ms}
Metaclass(ClassDescription)>>printMethodChunk:with...n:moveSource:toFile:
    9.4% {828ms} StandardFileStream>>close

**Leaves**
45.7% {4023ms} SystemDictionary>>garbageCollect
11.4% {1004ms} WriteStream>>nextPut:
11.2% {986ms} StandardFileStream>>next:into:startingAt:
9.4% {828ms} StandardFileStream>>close
6.5% {572ms} StandardFileStream>>basicNext
5.5% {484ms} StandardFileStream>>next
3.7% {326ms} StandardFileStream(PositionableStream)>>nextChunk

**Memory**
    old            +52,684 bytes
    young        -72,636 bytes
    used        -19,952 bytes
    free        +19,952 bytes

**GCs**
    full            6 totalling 3,675ms (42.0% uptime), avg 613.0ms
    incr        17 totalling 14ms (0.0% uptime), avg 1.0ms
    tenures        0
    root table    0 overflows






More information about the Squeak-dev mailing list