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-co... -- 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 <cyril.ferlicot@gmail.com> wrote:
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-co...
-- Cyril Ferlicot https://ferlicot.fr
-- Cyril Ferlicot https://ferlicot.fr
Hi Cyril, can you use the profiler (either MessageTally, or better still, AndreasSystemProfiler) to get a better understanding? e.g. AndreasSystemProfiler spyOn: [SystemNavigation new browseMethodsWithSourceString: 'Method source with it' matchCase: false] On Sat, Mar 17, 2018 at 4:03 PM, Cyril Ferlicot <cyril.ferlicot@gmail.com> wrote:
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 <cyril.ferlicot@gmail.com> wrote:
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
-- Cyril Ferlicot https://ferlicot.fr
-- _,,,^..^,,,_ best, Eliot
On Sun, Mar 18, 2018 at 12:56 AM, Eliot Miranda <eliot.miranda@gmail.com> wrote:
Hi Cyril,
Hi Eliot,
can you use the profiler (either MessageTally, or better still, AndreasSystemProfiler) to get a better understanding?
e.g.
AndreasSystemProfiler spyOn: [SystemNavigation new browseMethodsWithSourceString: 'Method source with it' matchCase: false]
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 <cyril.ferlicot@gmail.com> 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... 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
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 ;) Guille On Sun, Mar 18, 2018 at 10:54 AM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
On 18 Mar 2018, at 00:03, Cyril Ferlicot <cyril.ferlicot@gmail.com> 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
-- Guille Polito Research Engineer French National Center for Scientific Research - *http://www.cnrs.fr* <http://www.cnrs.fr/> *Web:* *http://guillep.github.io* <http://guillep.github.io/> *Phone: *+33 06 52 70 66 13
On 18 Mar 2018, at 11:16, Guillermo Polito <guillermo.polito@inria.fr> 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.
Guille
On Sun, Mar 18, 2018 at 10:54 AM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
On 18 Mar 2018, at 00:03, Cyril Ferlicot <cyril.ferlicot@gmail.com> 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...
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
--
Guille Polito
Research Engineer French National Center for Scientific Research - http://www.cnrs.fr
Web: http://guillep.github.io Phone: +33 06 52 70 66 13
On dim. 18 mars 2018 at 11:18, Sven Van Caekenberghe <sven@stfx.eu> wrote:
On 18 Mar 2018, at 11:16, Guillermo Polito <guillermo.polito@inria.fr> 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.
Thank you for the fast fix :) And I did not add a number too much :) look at the other profiler I send. This is why I found it as a really huge lost of performances. Probably Windows who is slower on file reading even with AV disable for the .sources.
Guille
On Sun, Mar 18, 2018 at 10:54 AM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
On 18 Mar 2018, at 00:03, Cyril Ferlicot <cyril.ferlicot@gmail.com> 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...
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
--
Guille Polito
Research Engineer French National Center for Scientific Research - http://www.cnrs.fr
Web: http://guillep.github.io Phone: +33 06 52 70 66 13
-- Cyril Ferlicot https://ferlicot.fr
participants (4)
-
Cyril Ferlicot -
Eliot Miranda -
Guillermo Polito -
Sven Van Caekenberghe