Performances of source code search on latest Pharo

HI,

We have a regression on source code search performances in latest Pharo.

I am on Windows 10.

With Pharo 6.1 it takes a few seconds to look for a string in all the
image source code.

With the latest Pharo 7 it takes minutes.

To reproduce:
- Open a playground
- Type something
- Select the text, right click
- Clic on "Code search..." -> "Method source with it"

https://pharo.fogbugz.com/f/cases/21612/Performances-regression-on-source-code-search

--
Cyril Ferlicot
https://ferlicot.fr

Here some new precisions:

Time to execute: SystemNavigation new browseMethodsWithSourceString:
'Method source with it' matchCase: false

Pharo 6.1: 2480ms

Pharo 7: 132041ms

The difference seems to come from SourceFileArray>>sourceCodeAt:

Pharo 6.1:

sourceCodeAt: sourcePointer
 "Retrieves the source code for the pointer received as argument"

 ^ self
  readStreamAt: sourcePointer
  ifPresent: [ :stream | stream nextChunk ]
  ifAbsent: [ '' ]

Pharo 7:

sourceCodeAt: sourcePointer
 "Retrieves the source code for the pointer received as argument"

 ^ self
  readStreamAt: sourcePointer
  ifPresent: [ :stream | (ChunkReadStream on: stream) next ]
  ifAbsent: [ '' ]

It seems that we have a huge performance problem at some points with
the new streams.

On Sat, Mar 17, 2018 at 7:08 PM, Cyril Ferlicot
<[hidden email]> wrote:


--
Cyril Ferlicot
https://ferlicot.fr

On Sun, Mar 18, 2018 at 12:56 AM, Eliot Miranda <[hidden email]> wrote:
> Hi Cyril,
>

Hi Eliot,

I already did it and most of the time is spent in
ZnCharacterReadStream>>nextElement.
This is why I said it was probably linked to the recent changes on
Pharo's streams to use Zinc ones.

I don't have enough knowledge on the streams and time to help more.

Here is the profiler:

 - 132607 tallies, 132646 msec.
**Tree**
--------------------------------
Process: (40s) Morphic UI Process: nil
--------------------------------
99.7% {132298ms} SystemNavigation>>browseMethodsWithSourceString:matchCase:
  99.7% {132239ms} SystemNavigation>>allMethodsWithSourceString:matchCase:
    99.7% {132235ms} ByteString(String)>>displayProgressFrom:to:during:
      99.7% {132235ms}
MorphicUIManager(UIManager)>>displayProgress:from:to:during:
        99.7% {132235ms} Job>>run
          99.7% {132235ms} BlockClosure>>ensure:
            99.7% {132221ms} Job>>run
              99.7% {132219ms} CurrentJob class(DynamicVariable
class)>>value:during:
                99.7% {132219ms} CurrentJob(DynamicVariable)>>value:during:
                  99.7% {132219ms} BlockClosure>>ensure:
                    99.7% {132219ms} CurrentJob(DynamicVariable)>>value:during:
                      99.7% {132219ms} Job>>run
                        99.7% {132219ms} BlockClosure>>cull:
                          99.7% {132219ms}
SystemNavigation>>allMethodsWithSourceString:matchCase:
                            99.7% {132219ms} SystemNavigation>>allBehaviorsDo:
                              94.8% {125787ms} SystemDictionary>>allClassesDo:
                                |94.8% {125787ms} OrderedCollection>>do:
                                |  94.8% {125783ms}
SystemDictionary>>allClassesDo:
                                |    94.8% {125774ms}
SystemNavigation>>allBehaviorsDo:
                                |      94.8% {125759ms}
SystemNavigation>>allMethodsWithSourceString:matchCase:
                                |        88.5% {117424ms}
AColorSelectorMorph class(Behavior)>>selectorsDo:
                                |          |88.5% {117418ms}
MethodDictionary>>keysDo:
                                |          |  88.4% {117317ms}
SystemNavigation>>allMethodsWithSourceString:matchCase:
                                |          |    88.4% {117239ms}
AColorSelectorMorph class(Behavior)>>sourceCodeAt:
                                |          |      88.3% {117157ms}
CompiledMethod>>sourceCode
                                |          |        88.2% {117055ms}
CompiledMethod>>getSourceFromFile
                                |          |          88.2% {117053ms}
BlockClosure>>on:do:
                                |          |            88.2%
{117051ms} CompiledMethod>>getSourceFromFile
                                |          |              88.2%
{117029ms} SourceFileArray>>sourceCodeAt:
                                |          |                88.2%
{117027ms} SourceFileArray>>readStreamAt:ifPresent:ifAbsent:
                                |          |                  88.2%
{117019ms} SourceFileArray>>readStreamAtFileIndex:atPosition:ifPresent:ifAbsent:
                                |          |                    87.9%
{116565ms} SourceFileArray>>sourceCodeAt:
                                |          |
87.8% {116486ms} ChunkReadStream>>next
                                |          |
87.2% {115615ms} ChunkReadStream>>basicNextChunk
                                |          |
85.0% {112685ms} SourceFile>>next
                                |          |
 84.8% {112484ms} ZnCharacterReadStream(ZnEncodedReadStream)>>next
                                |          |
   84.6% {112251ms} ZnCharacterReadStream>>nextElement
                                |          |
     45.5% {60313ms} primitives
                                |          |
     39.1% {51860ms}
ZnUTF8Encoder(ZnCharacterEncoder)>>nextFromStream:
                                |          |
       39.0% {51675ms} ZnUTF8Encoder>>nextCodePointFromStream:
                                |          |
         38.8% {51492ms}
BinaryFileStream(AbstractBinaryFileStream)>>next
                                |          |
           38.1% {50479ms} ByteArray(Collection)>>ifEmpty:ifNotEmpty:
                                |          |
             37.1% {49198ms} primitives
                                |        5.9% {7822ms}
ClassOrganization>>classComment
                                |          5.9% {7822ms}
ClassOrganization>>comment
                                |            5.9% {7822ms} RemoteString>>string
                                |              5.9% {7820ms}
SourceFileArray>>readStreamAtFileIndex:atPosition:ifPresent:ifAbsent:
                                |                5.9% {7779ms}
RemoteString>>string
                                |                  5.9% {7777ms}
ChunkReadStream>>next
                                |                    5.8% {7734ms}
ChunkReadStream>>basicNextChunk
                                |                      5.7% {7535ms}
SourceFile>>next
                                |                        5.7% {7517ms}
ZnCharacterReadStream(ZnEncodedReadStream)>>next
                                |                          5.7%
{7503ms} ZnCharacterReadStream>>nextElement
                                |                            3.0%
{3941ms} primitives
                                |                            2.7%
{3553ms} ZnUTF8Encoder(ZnCharacterEncoder)>>nextFromStream:
                                |                              2.7%
{3547ms} ZnUTF8Encoder>>nextCodePointFromStream:
                                |                                2.7%
{3519ms} BinaryFileStream(AbstractBinaryFileStream)>>next
                                |
2.6% {3446ms} ByteArray(Collection)>>ifEmpty:ifNotEmpty:
                                |
2.5% {3361ms} primitives
                              4.8% {6432ms} SystemDictionary>>allTraitsDo:
                                4.8% {6428ms} OrderedCollection>>do:
                                  4.8% {6428ms} SystemDictionary>>allTraitsDo:
                                    4.8% {6428ms}
SystemNavigation>>allBehaviorsDo:
                                      4.8% {6426ms}
SystemNavigation>>allMethodsWithSourceString:matchCase:
                                        4.8% {6370ms} ClyTraitChild1
classTrait(Behavior)>>selectorsDo:
                                          4.8% {6370ms}
MethodDictionary>>keysDo:
                                            4.8% {6362ms}
SystemNavigation>>allMethodsWithSourceString:matchCase:
                                              4.8% {6356ms}
ClyTraitChild1 classTrait(Behavior)>>sourceCodeAt:
                                                4.8% {6350ms}
CompiledMethod>>sourceCode
                                                  4.8% {6344ms}
CompiledMethod>>getSourceFromFile
                                                    4.8% {6344ms}
BlockClosure>>on:do:
                                                      4.8% {6344ms}
CompiledMethod>>getSourceFromFile
                                                        4.8% {6342ms}
SourceFileArray>>sourceCodeAt:
                                                          4.8%
{6342ms} SourceFileArray>>readStreamAt:ifPresent:ifAbsent:
                                                            4.8%
{6342ms} SourceFileArray>>readStreamAtFileIndex:atPosition:ifPresent:ifAbsent:
                                                              4.7%
{6299ms} SourceFileArray>>sourceCodeAt:
                                                                4.7%
{6292ms} ChunkReadStream>>next
                                                                  4.7%
{6238ms} ChunkReadStream>>basicNextChunk

4.6% {6078ms} SourceFile>>next

4.6% {6063ms} ZnCharacterReadStream(ZnEncodedReadStream)>>next

 4.6% {6055ms} ZnCharacterReadStream>>nextElement

   2.5% {3256ms} primitives

   2.1% {2797ms} ZnUTF8Encoder(ZnCharacterEncoder)>>nextFromStream:

     2.1% {2785ms} ZnUTF8Encoder>>nextCodePointFromStream:

       2.1% {2779ms} BinaryFileStream(AbstractBinaryFileStream)>>next

         2.1% {2727ms} ByteArray(Collection)>>ifEmpty:ifNotEmpty:

           2.0% {2667ms} primitives

**Leaves**
51.6% {68474ms} ZnCharacterReadStream>>nextElement
42.3% {56100ms} ByteArray(Collection)>>ifEmpty:ifNotEmpty:
**Memory**
 old   +0 bytes
 young  -1,076,072 bytes
 used  -1,076,072 bytes
 free  +1,076,072 bytes
**GCs**
 full   0 totalling 0ms (0.0% uptime)
 incr  691 totalling 859ms (1.0% uptime), avg 1.0ms
 tenures  0
 root table 0 overflows

>
> --
> _,,,^..^,,,_
> best, Eliot


--
Cyril Ferlicot
https://ferlicot.fr

> On 18 Mar 2018, at 00:03, Cyril Ferlicot <[hidden email]> wrote:
>
> Time to execute: SystemNavigation new browseMethodsWithSourceString:
> 'Method source with it' matchCase: false
>
> Pharo 6.1: 2480ms
>
> Pharo 7: 132041ms

You didn't type a digit too much, did you ? That is 2 orders of magnitude, maybe on Windows ;-)

https://pharo.manuscript.com/f/cases/21612/Performances-regression-on-source-code-search

I can confirm that the slowdown pre/post recent file/stream changes in Pharo 7 is about 1 order of magnitude (x10).

There is however no fundamental problem, since the following are equally fast (~ 1s) in both cases (using old/new streams).

SmalltalkImage current sourcesFile asFileReference readStreamDo: [ :in | [ in atEnd ] whileFalse: [ in next ] ]

I think there is a ZnBufferedReadStream missing (between the ZnCharacterReadStream and the primitive File stream) in SourceFile>>#tryOpenReadOnly:

Sven

> On 18 Mar 2018, at 11:16, Guillermo Polito <[hidden email]> wrote:
>
> Yes, looking at the stack in the profiler, there is a buffered stream missing in there. The thing is that source/changes file reading/writing required special attention in the migration (or the image became unusable :)).
>
> I'll fix it tomorrow first thing in the morning, if you can wait a couple of hours ;)

I'll post the fixes later on. Was pretty easy, needs a 2nd pair of eyes.

--