Smalltalk › Pharo › Pharo Smalltalk Developers

Weird ZnClient benchmarking result

_‹ Previous Topic Next Topic _›

Classic

List

Threaded

9 messages Options

Sven Van Caekenberghe-2

Weird ZnClient benchmarking result

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

Ben Coman

Re: Weird ZnClient benchmarking result

On 11 December 2017 at 00:14, Sven Van Caekenberghe <[hidden email]> 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.

Can you compare logging from Nginx to confirm the additional requests.

Perhaps in the second case each Annoucement is being re-Announced.

cheers -ben

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

Henrik-Nergaard

Re: Weird ZnClient benchmarking result

In reply to this post by Sven Van Caekenberghe-2

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: '<a href="http://localhost:8080'">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

Henrik Sperre Johansen

Re: Weird ZnClient benchmarking result

In reply to this post by Sven Van Caekenberghe-2

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: '<a href="http://localhost:8080'">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: '<a href="http://localhost:8080'">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)
> <http://forum.world.st/attachment/5060328/0/Screen%20Shot%202017-12-10%20at%2016.59.36.png>
> Screen Shot 2017-12-10 at 17.00.28.png (60K)
> <http://forum.world.st/attachment/5060328/1/Screen%20Shot%202017-12-10%20at%2017.00.28.png>
> Screen Shot 2017-12-10 at 17.07.39.png (140K)
> <http://forum.world.st/attachment/5060328/2/Screen%20Shot%202017-12-10%20at%2017.07.39.png>

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

Sven Van Caekenberghe-2

Re: Weird ZnClient benchmarking result

In reply to this post by Henrik-Nergaard

@ 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: '<a href="http://localhost:8080'">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: '<a href="http://localhost:8080'">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 <[hidden email]> 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: '<a href="http://localhost:8080'">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
>

NorbertHartl

Re: Weird ZnClient benchmarking result

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 <[hidden email]>:
>
> @ 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: '<a href="http://localhost:8080'">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: '<a href="http://localhost:8080'">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 <[hidden email]> 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: '<a href="http://localhost:8080'">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
>>

Stephane Ducasse-3

Re: Weird ZnClient benchmarking result

In reply to this post by Sven Van Caekenberghe-2

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

Stef

On Sun, Dec 10, 2017 at 7:14 PM, Sven Van Caekenberghe <[hidden email]> 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: '<a href="http://localhost:8080'">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: '<a href="http://localhost:8080'">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 <[hidden email]> 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: '<a href="http://localhost:8080'">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
>>
>
>

Sven Van Caekenberghe-2

Re: Weird ZnClient benchmarking result

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 <[hidden email]> 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 <[hidden email]> 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: '<a href="http://localhost:8080'">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: '<a href="http://localhost:8080'">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 <[hidden email]> 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: '<a href="http://localhost:8080'">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
>>>
>>
>>
>

Stephane Ducasse-3

Re: Weird ZnClient benchmarking result

Tx this is cool!

On Sat, Feb 3, 2018 at 12:17 AM, Sven Van Caekenberghe <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: '<a href="http://localhost:8080'">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: '<a href="http://localhost:8080'">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 <[hidden email]> 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: '<a href="http://localhost:8080'">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
>>>>
>>>
>>>
>>
>
>