Re: [Pharo-dev] Weird ZnClient benchmarking result

[Henrik-Nergaard]

Hi Sven,

What you are seeing is most likely a $, vs $. issue.
See BenchmarkResult >>#printFrequenceOn: it uses both decimal and thousand
separators.

If i run this code:
-
| counter |
counter :=
ZnClient new in: [ :client |
  client loggingOff.
  [ client get: 'http://localhost:8080'. counter ] bench 
].
counter.
-

Then i get 9035 ('1,773 per second') when no inspector is open, and only 22
('5.995 per second') when inspecting the logs.

Best regards,
Henrik








--
Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html

Re: [Pharo-dev] Weird ZnClient benchmarking result

[Henrik Sperre Johansen]

Sven Van Caekenberghe-2 wrote
> Hi,
> 
> While benchmarking ZnClient I encountered something weird and counter
> intuitive that I cannot explain.
> 
> This was on macOS running Pharo 7 and 6.
> 
> First you need to setup a fast local HTTP server, can be anything, for
> example:
> 
> $ brew install nginx
> $ brew services start nginx
> $ curl http://localhost:8080
> 
> In Pharo, the benchmark code looks as follows:
> 
> ZnClient new in: [ :client |
>   [ client get: 'http://localhost:8080' ] bench ].
> 
> On my machine this gives about 2500 req/s.
> 
> ZnClient uses object logging: it emits special event objects that contain
> information regarding what happens (full details and timing information)
> using an Announcer. Subscribers can then decide what to do with this
> detailed information. This mechanism is always active, but there is an
> option to turn it totally off for maximum performance:
> 
> ZnClient new in: [ :client |
>   client loggingOff.
>   [ client get: 'http://localhost:8080' ] bench ].
> 
> This gives about 3000 req/s, a non-trivial + 500 req/s improvement.
> 
> Now comes the weird thing. GT contains a custom view for Announcers,
> inspect:
> 
>   ZnLogEvent announcer.
> 
> And select the Announcements tab. Leave this window open.
> 
> Now, the first expression (with full logging enabled and an active
> subscriber with a UI) is way FASTER than first, it yields about 7000 to
> 8000 req/s. Since the benchmark runs in the main UI thread, no actual
> drawing happens until the expression finishes.
> 
> Running both expression inside a Time profiler show how in the first case
> significant time (actually *most* time ;-) is spent in the logging:
> 
> 
> 
> In the second case, with logging disabled, that changes to:
> 
> 
> 
> One has to take into account that the request has to be processed by the
> server, so from the client's perspective, most time will always be spent
> waiting for a reply, #readResponse. With the logging enabled, probably
> less time is spent waiting, since the client does a bit more work. Still
> what should be slower is more than 2 times as fast !
> 
> I have a feeling that this has to do with scheduling (probably interacting
> with network IO), as going deep into the last #readResponse above, I see:
> 
> 
> 
> But I still cannot understand why doing apparently more work results in
> faster throughput.
> 
> Can anyone explain this behaviour ?
> 
> Thx,
> 
> Sven
> 
> 
> 
> Screen Shot 2017-12-10 at 16.59.36.png (68K)
> ;
> Screen Shot 2017-12-10 at 17.00.28.png (60K)
> ;
> Screen Shot 2017-12-10 at 17.07.39.png (140K)
> ;

Just a theory, but iirc, if the vm heartbeat thread isn't running properly,
newly arrived external events only gets checked every N executed bytecodes.
Could explain an increase in delay times before the socket semaphore is
signalled. 
Should be easily testable, any low-priority thread with an infinite loop
would probably do enough work.

Cheers,
Henry




--
Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html

Re: [Pharo-dev] Weird ZnClient benchmarking result

[Sven Van Caekenberghe]

@ Henrik

Arg, arg, arg, yes of course. 
I actually did think about that, but still did not look carefully enough !! 
Really stupid of me.

It is even worse because I wrote that code ...

Now, the #printOn: of BenchmarkResult is much clearer, less confusing:

ZnClient new in: [ :client |
[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ]. 

a BenchmarkResult(14,732 iterations in 5 seconds. 2,946 per second)

vs

ZnClient new in: [ :client |
client loggingOff.
[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].

a BenchmarkResult(42 iterations in 5 seconds 88 milliseconds. 8.255 per second)

Still the same issue with $, and $. in frequency, but the iteration count is 
crystal clear.

The reason #bench works like that is backwards compatibility at the time we 
introduced that.

@ Ben

Yes, I should have looked at the other side as well, to confirm things actually 
happened as I imagined them (the did not).

Thx and sorry for the noise.

Sven

> On 10 Dec 2017, at 18:00, Henrik-Nergaard  wrote:
> 
> Hi Sven,
> 
> What you are seeing is most likely a $, vs $. issue.
> See BenchmarkResult >>#printFrequenceOn: it uses both decimal and thousand
> separators.
> 
> If i run this code:
> -
> | counter |
> counter :=
> ZnClient new in: [ :client |
>  client loggingOff.
>  [ client get: 'http://localhost:8080'. counter ] bench 
> ].
> counter.
> -
> 
> Then i get 9035 ('1,773 per second') when no inspector is open, and only 22
> ('5.995 per second') when inspecting the logs.
> 
> Best regards,
> Henrik
> 
> 
> 
> 
> 
> 
> 
> 
> --
> Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html
> 

Re: [Pharo-dev] Weird ZnClient benchmarking result

[Norbert Hartl]

I like that kind of noise because these numbers are very informative. And they 
show that pharo can be used in heavy scenarios, too

> Am 10.12.2017 um 19:14 schrieb Sven Van Caekenberghe :
> 
> @ Henrik
> 
> Arg, arg, arg, yes of course. 
> I actually did think about that, but still did not look carefully enough !! 
> Really stupid of me.
> 
> It is even worse because I wrote that code ...
> 
> Now, the #printOn: of BenchmarkResult is much clearer, less confusing:
> 
> ZnClient new in: [ :client |
>[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ]. 
> 
> a BenchmarkResult(14,732 iterations in 5 seconds. 2,946 per second)
> 
> vs
> 
> ZnClient new in: [ :client |
>client loggingOff.
>[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
> 
> a BenchmarkResult(42 iterations in 5 seconds 88 milliseconds. 8.255 per 
> second)
> 
> Still the same issue with $, and $. in frequency, but the iteration count is 
> crystal clear.
> 
> The reason #bench works like that is backwards compatibility at the time we 
> introduced that.
> 
> @ Ben
> 
> Yes, I should have looked at the other side as well, to confirm things 
> actually happened as I imagined them (the did not).
> 
> Thx and sorry for the noise.
> 
> Sven
> 
>> On 10 Dec 2017, at 18:00, Henrik-Nergaard  wrote:
>> 
>> Hi Sven,
>> 
>> What you are seeing is most likely a $, vs $. issue.
>> See BenchmarkResult >>#printFrequenceOn: it uses both decimal and thousand
>> separators.
>> 
>> If i run this code:
>> -
>> | counter |
>> counter :=
>> ZnClient new in: [ :client |
>> client loggingOff.
>> [ client get: 'http://localhost:8080'. counter ] bench 
>> ].
>> counter.
>> -
>> 
>> Then i get 9035 ('1,773 per second') when no inspector is open, and only 22
>> ('5.995 per second') when inspecting the logs.
>> 
>> Best regards,
>> Henrik
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> --
>> Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html
>> 

Re: [Pharo-dev] Weird ZnClient benchmarking result

[Stephane Ducasse]

sven did you submit a fix to get a clearer printout?

Stef


On Sun, Dec 10, 2017 at 7:14 PM, Sven Van Caekenberghe  wrote:
> @ Henrik
>
> Arg, arg, arg, yes of course.
> I actually did think about that, but still did not look carefully enough !!
> Really stupid of me.
>
> It is even worse because I wrote that code ...
>
> Now, the #printOn: of BenchmarkResult is much clearer, less confusing:
>
> ZnClient new in: [ :client |
> [ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
>
> a BenchmarkResult(14,732 iterations in 5 seconds. 2,946 per second)
>
> vs
>
> ZnClient new in: [ :client |
> client loggingOff.
> [ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
>
> a BenchmarkResult(42 iterations in 5 seconds 88 milliseconds. 8.255 per 
> second)
>
> Still the same issue with $, and $. in frequency, but the iteration count is 
> crystal clear.
>
> The reason #bench works like that is backwards compatibility at the time we 
> introduced that.
>
> @ Ben
>
> Yes, I should have looked at the other side as well, to confirm things 
> actually happened as I imagined them (the did not).
>
> Thx and sorry for the noise.
>
> Sven
>
>> On 10 Dec 2017, at 18:00, Henrik-Nergaard  wrote:
>>
>> Hi Sven,
>>
>> What you are seeing is most likely a $, vs $. issue.
>> See BenchmarkResult >>#printFrequenceOn: it uses both decimal and thousand
>> separators.
>>
>> If i run this code:
>> -
>> | counter |
>> counter :=
>> ZnClient new in: [ :client |
>>  client loggingOff.
>>  [ client get: 'http://localhost:8080'. counter ] bench
>> ].
>> counter.
>> -
>>
>> Then i get 9035 ('1,773 per second') when no inspector is open, and only 22
>> ('5.995 per second') when inspecting the logs.
>>
>> Best regards,
>> Henrik
>>
>>
>>
>>
>>
>>
>>
>>
>> --
>> Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html
>>
>
>

Re: [Pharo-dev] Weird ZnClient benchmarking result

[Sven Van Caekenberghe]

https://pharo.fogbugz.com/f/cases/21232/BenchmarkResult-printFrequencyOn-can-be-confusing

https://github.com/pharo-project/pharo/pull/794

> On 12 Dec 2017, at 07:22, Stephane Ducasse  wrote:
> 
> sven did you submit a fix to get a clearer printout?
> 
> Stef
> 
> 
> On Sun, Dec 10, 2017 at 7:14 PM, Sven Van Caekenberghe  wrote:
>> @ Henrik
>> 
>> Arg, arg, arg, yes of course.
>> I actually did think about that, but still did not look carefully enough !!
>> Really stupid of me.
>> 
>> It is even worse because I wrote that code ...
>> 
>> Now, the #printOn: of BenchmarkResult is much clearer, less confusing:
>> 
>> ZnClient new in: [ :client |
>>[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
>> 
>> a BenchmarkResult(14,732 iterations in 5 seconds. 2,946 per second)
>> 
>> vs
>> 
>> ZnClient new in: [ :client |
>>client loggingOff.
>>[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
>> 
>> a BenchmarkResult(42 iterations in 5 seconds 88 milliseconds. 8.255 per 
>> second)
>> 
>> Still the same issue with $, and $. in frequency, but the iteration count is 
>> crystal clear.
>> 
>> The reason #bench works like that is backwards compatibility at the time we 
>> introduced that.
>> 
>> @ Ben
>> 
>> Yes, I should have looked at the other side as well, to confirm things 
>> actually happened as I imagined them (the did not).
>> 
>> Thx and sorry for the noise.
>> 
>> Sven
>> 
>>> On 10 Dec 2017, at 18:00, Henrik-Nergaard  wrote:
>>> 
>>> Hi Sven,
>>> 
>>> What you are seeing is most likely a $, vs $. issue.
>>> See BenchmarkResult >>#printFrequenceOn: it uses both decimal and thousand
>>> separators.
>>> 
>>> If i run this code:
>>> -
>>> | counter |
>>> counter :=
>>> ZnClient new in: [ :client |
>>> client loggingOff.
>>> [ client get: 'http://localhost:8080'. counter ] bench
>>> ].
>>> counter.
>>> -
>>> 
>>> Then i get 9035 ('1,773 per second') when no inspector is open, and only 22
>>> ('5.995 per second') when inspecting the logs.
>>> 
>>> Best regards,
>>> Henrik
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> 
>>> --
>>> Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html
>>> 
>> 
>> 
> 

Re: [Pharo-dev] Weird ZnClient benchmarking result

[Stephane Ducasse]

Tx this is cool!

On Sat, Feb 3, 2018 at 12:17 AM, Sven Van Caekenberghe  wrote:
> https://pharo.fogbugz.com/f/cases/21232/BenchmarkResult-printFrequencyOn-can-be-confusing
>
> https://github.com/pharo-project/pharo/pull/794
>
>> On 12 Dec 2017, at 07:22, Stephane Ducasse  wrote:
>>
>> sven did you submit a fix to get a clearer printout?
>>
>> Stef
>>
>>
>> On Sun, Dec 10, 2017 at 7:14 PM, Sven Van Caekenberghe  wrote:
>>> @ Henrik
>>>
>>> Arg, arg, arg, yes of course.
>>> I actually did think about that, but still did not look carefully enough !!
>>> Really stupid of me.
>>>
>>> It is even worse because I wrote that code ...
>>>
>>> Now, the #printOn: of BenchmarkResult is much clearer, less confusing:
>>>
>>> ZnClient new in: [ :client |
>>>[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
>>>
>>> a BenchmarkResult(14,732 iterations in 5 seconds. 2,946 per second)
>>>
>>> vs
>>>
>>> ZnClient new in: [ :client |
>>>client loggingOff.
>>>[ client get: 'http://localhost:8080' ] benchFor: 5 seconds ].
>>>
>>> a BenchmarkResult(42 iterations in 5 seconds 88 milliseconds. 8.255 per 
>>> second)
>>>
>>> Still the same issue with $, and $. in frequency, but the iteration count 
>>> is crystal clear.
>>>
>>> The reason #bench works like that is backwards compatibility at the time we 
>>> introduced that.
>>>
>>> @ Ben
>>>
>>> Yes, I should have looked at the other side as well, to confirm things 
>>> actually happened as I imagined them (the did not).
>>>
>>> Thx and sorry for the noise.
>>>
>>> Sven
>>>
 On 10 Dec 2017, at 18:00, Henrik-Nergaard  wrote:

 Hi Sven,

 What you are seeing is most likely a $, vs $. issue.
 See BenchmarkResult >>#printFrequenceOn: it uses both decimal and thousand
 separators.

 If i run this code:
 -
 | counter |
 counter :=
 ZnClient new in: [ :client |
 client loggingOff.
 [ client get: 'http://localhost:8080'. counter ] bench
 ].
 counter.
 -

 Then i get 9035 ('1,773 per second') when no inspector is open, and only 22
 ('5.995 per second') when inspecting the logs.

 Best regards,
 Henrik








 --
 Sent from: http://forum.world.st/Pharo-Smalltalk-Developers-f1294837.html

>>>
>>>
>>
>
>