[erlang-questions] performance drop in R15A?

Zabrane Mickael <>
Mon Apr 16 16:08:51 CEST 2012


Thanks Nico for sharing such useful info.

Regards,
Zabrane

On Apr 16, 2012, at 4:03 PM, Nico Kruber wrote:

> Thank you for the tips, indeed, by using the +sbt option I was able to improve 
> our benchmark results to a certain extend - not to the full R14B04 value 
> though :(
> I achieved the best results together with the +swt low and very_low option, so 
> I would probably go with "low". I also experienced with +rg and +scl but these 
> didn't influence the results too much.
> 
> I also attached the cpuinfo from the test system (basically an 8-core Opteron 
> 2376 with 8GB RAM).
> 
> using Scalaris "make bench":
>           wall clock throughput // latency
> R14B04:                         999  //  40
> "+swt low"                    1097  //  36
> "+swt very_low"               1101  //  36
> R15B: (same as "+sbt u")        679  //  59
> "+scl true"                    682  //  59
> "+sbt db"                      836  //  48
> "+sbt ns"                      828  //  48
> "+sbt ts"                      840  //  48
> "+sbt ps"                      816  //  49
> "+sbt s"                       822  //  49
> "+sbt nnts"                    825  //  48
> "+sbt nnps"                    834  //  48
> "+sbt tnnps"                   830  //  48
> "+scl true +sbt db"            827  //  48
> "+scl true +sbt db +swt low"  1029  //  39
> "+sbt db +swt low"            1019  //  39
> "+sbt db +swt very_low"       1038  //  39
> "+swt low"                     764  //  52
> "+sbt db +swt low +rg 4"      1008  //  40
> "+sbt db +swt low +rg 8"      1042  //  38
> "+sbt db +swt low +rg 16"     1011  //  40
> 
> Recall that this creates 4 erlang VMs with the same (given) start-up options.
> 
> 
> On Thursday 12 April 2012 16:44:48 Tomas Abrahamsson wrote:
>>> Hi Nico,
>>> According to erts documetation, since OTP R15B, the virtual machine
>>> doesn't bind the schedulers to logical processors.
>>> I don't know if it's the reason of your performance drop but it might
>>> worst looking around the +sbt option.
>> 
>> There's also the +scl true|false flag, to "[e]nable or
>> disable scheduler compaction of load", that's new in
>> R15, iirc, but the +sbt option may have more impact.
>> 
>> With the particular workload we previously had, when we
>> continued to measure more, it turned out that R15B was
>> actually faster than R14B04 on machines with more CPUs:
>> 
>> We had one machine with 2 Xeon X5660 CPUs (24
>> hyperthreads in total) where R15B was faster.  We had
>> another machine with 2 Xeon E5540 CPUs (16 HTs in
>> total) where I think R15B and R14B04 were roughly on
>> par with each other.
>> 
>> We also did experiment a bit with the +rg ReaderGroupsLimit
>> option. I think we did set it to be the same as the
>> number of schedulers (online).
>> 
>> BRs
>> Tomas
>> 
>>>> is there any news on this?
>>>> Our internal test server has a new additional configuration which
>>>> compiles
>>>> the
>>>> latest otp from github once per day and tests its performance with the
>>>> mentioned benchmarks.
>>>> The resulting graphs for R14B04, R15B and latest git checkout are
>>>> attached. As
>>>> you can see - nothing has changed since then so I suppose it is still
>>>> present
>>>> in R15B01 :(
>>>> 
>>>> I don't know how to debug this any further. If there is anything I could
>>>> do to
>>>> help you identify the issue, please tell me.
>>>> 
>>>> 
>>>> Regards
>>>> Nico Kruber
>>>> 
>>>> On Wednesday 14 December 2011 17:41:33 Nico Kruber wrote:
>>>>> ok, I did some profiling and made some optimisations but the differences
>>>>> between R15B (git checkout from master just now) and R14B04 are still
>>>>> the
>>>>> same:
>>>>> 
>>>>> First the results of the calls to bench:quorum_read(10, 50000) (best of
>>>>> three) ------------------------------------------------------------
>>>>> 
>>>>> |   R14B04   |   R15B     | time surplus
>>>>> 
>>>>> ------------------------------------------------------------
>>>>> timer:tc, smp8:8   |    22484619|    26641737| +18%
>>>>> timer:tc, smp4:4   |    34009785|    35963489| + 6%
>>>>> timer:tc, smp2:2   |    32863428|    34102038| + 4%
>>>>> timer:tc, smpoff   |    53805419|    54214795| + 1%
>>>>> ------------------------------------------------------------
>>>>> 
>>>>> It seems there is some lock-contention or some other problem with smp in
>>>>> our
>>>>> case which hasn't been there before.
>>>>> I also observed that the results using R15B vary quite much, especially
>>>>> with
>>>>> smp8:8 (see below for an example). R14B04 is more stable among different
>>>>> test runs.
>>>>> But still, even without smp, R15B is slower than R14B04 :(
>>>>> 
>>>>> Lukas suggested to run fprof to a bit deeper and maybe find the function
>>>>> taking longer in R15 than in R14B04.
>>>>> Although it was helpful in finding some hot spots, it did however not
>>>>> help
>>>>> with this problem. Following are the totals reported by fprof
>>>>> (if you like, I can send the complete logs - didn't want to send too
>>>>> much to
>>>>> the mailing list though).
>>>>> 
>>>>> ------------------------------------------------------------
>>>>> 
>>>>> |   R14B04   |   R15B     | time surplus
>>>>> 
>>>>> ------------------------------------------------------------
>>>>> fprof, CNT, smp8:8 |     7723796|     7722635| n/a
>>>>> fprof, ACC, smp8:8 |       98239|       85477| -13%
>>>>> fprof, OWN, smp8:8 |      300534|      264018| -12%
>>>>> ------------------------------------------------------------
>>>>> 
>>>>> As you can see, according to fprof, R15B should be faster (but it
>>>>> isn't!).
>>>>> I assume that some function calls are not reported by fprof
>>>>> (e.g. I did not see erlang:length/1).
>>>>> Is there some way to include them again in order to analyse further?
>>>>> Maybe suspend or garbage_collect are not in ACC or OWN?
>>>>> But even here, R15B wastes less time as you can see in the table below.
>>>>> ----------------------------------------------------------
>>>>> 
>>>>> |   R14B04   |   R15B     |
>>>>> 
>>>>> ----------------------------------------------------------
>>>>> fprof, suspend, smp8:8         |  9.8421e+06| 8.51855e+06|
>>>>> fprof, garbage_collect, smp8:8 |        1315|         794|
>>>>> ----------------------------------------------------------
>>>>> 
>>>>> We do rely quite much on the process dictionary (erlang:put and
>>>>> erlang:get)
>>>>> which you might see as an "non-typical usage pattern" for erlang.
>>>>> However, if I switch to ets instead, performance of
>>>>> bench:quorum_read(10,
>>>>> 50000) for R15B does not change and for R14B04 decreases by about 7%.
>>>>> 
>>>>> Everything else I would consider "typical use" - or at least I'm not
>>>>> aware
>>>>> of anything untypical.
>>>>> 
>>>>> I hope, someone can help to further analyse the problem. I did
>>>>> everything I
>>>>> could think of and are stuck now.
>>>>> Is other real-world software also affected? E.g. testing couchdb would
>>>>> be
>>>>> nice.
>>>>> 
>>>>> 
>>>>> Regards
>>>>> Nico Kruber
>>>>> 
>>>>> 
>>>>> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
>>>>> how to re-produce the values
>>>>> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
>>>>> 
>>>>> I'm using scalaris from http://code.google.com/p/scalaris/
>>>>> ./configure && make
>>>>> ================ R15B ===============
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh
>>>>> Erlang R15B (erts-5.9) [source] [64-bit] [smp:8:8] [async-threads:0]
>>>>> [hipe]
>>>>> [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {33764932,ok} % 1st try
>>>>> {26641737,ok} % 2nd try
>>>>> {27575975,ok} % 3rd try
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh "+S4:4"
>>>>> Erlang R15B (erts-5.9) [source] [64-bit] [smp:4:4] [async-threads:0]
>>>>> [hipe]
>>>>> [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {35963489,ok} % 1st try
>>>>> {36332156,ok} % 2nd try
>>>>> {37295819,ok} % 3rd try
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh "+S2:2"
>>>>> Erlang R15B (erts-5.9) [source] [64-bit] [smp:2:2] [async-threads:0]
>>>>> [hipe]
>>>>> [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {34102038,ok} % 1st try
>>>>> {34379052,ok} % 2nd try
>>>>> {34416173,ok} % 3rd try
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh "-smp disable"
>>>>> Erlang R15B (erts-5.9) [source] [64-bit] [async-threads:0] [hipe]
>>>>> [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {54214795,ok} % 1st try
>>>>> {55210947,ok} % 2nd try
>>>>> {54537194,ok} % 3rd try
>>>>> 
>>>>> ================ R14B04 ===============
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh
>>>>> Erlang R14B04 (erts-5.8.5) [source] [64-bit] [smp:8:8] [rq:8]
>>>>> [async-threads:0] [hipe] [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {22598819,ok} % 1st try
>>>>> {22706185,ok} % 2nd try
>>>>> {22484619,ok} % 3rd try
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh "+S4:4"
>>>>> Erlang R14B04 (erts-5.8.5) [source] [64-bit] [smp:4:4] [rq:4]
>>>>> [async-threads:0] [hipe] [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {35482368,ok} % 1st try
>>>>> {34009785,ok} % 2nd try
>>>>> {34527203,ok} % 3rd try
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh "+S2:2"
>>>>> Erlang R14B04 (erts-5.8.5) [source] [64-bit] [smp:2:2] [rq:2]
>>>>> [async-threads:0] [hipe] [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {33590356,ok} % 1st try
>>>>> {33192033,ok} % 2nd try
>>>>> {32863428,ok} % 3rd try
>>>>> --------------------------------
>>>>> ./bin/firstnode.sh "-smp disable"
>>>>> Erlang R14B04 (erts-5.8.5) [source] [64-bit] [rq:1] [async-threads:0]
>>>>> [hipe]
>>>>> [kernel-poll:false]
>>>>> 
>>>>> timer:tc(bench, quorum_read, [10, 50000]).
>>>>> {53805419,ok} % 1st try
>>>>> {54054538,ok} % 2nd try
>>>>> {54066521,ok} % 3rd try
>>>>> 
>>>>> 
>>>>> fprof runs:
>>>>> ./bin/firstnode.sh
>>>>> 
>>>>> fprof:trace([start, {procs, processes()}]).
>>>>> bench:quorum_read(10, 1000).
>>>>> fprof:trace(stop).
>>>>> fprof:profile().
>>>>> fprof:analyse([{dest, "test.R15B.fprof.log"}]). % or R14B04 respectively
>>>>> 
>>>>>> cat test.R14B04.fprof.log |grep suspend|cut -d',' -f3 | awk '{s+=$1}
>>>>> 
>>>>> END
>>>>> 
>>>>>> {print s}'
>>>>> 
>>>>> 9.8421e+06
>>>>> 
>>>>>> cat test.R15B.fprof.log |grep suspend|cut -d',' -f3 | awk '{s+=$1} END
>>>>>> {print s}'
>>>>> 
>>>>> 8.51855e+06
>>>>> 
>>>>>> cat test.R14B04.fprof.log |grep garbage_collect|cut -d',' -f3 | awk
>>>>>> '{s+=$1} END {print s}'
>>>>> 
>>>>> 1315.33
>>>>> 
>>>>>> cat test.R15B.fprof.log |grep garbage_collect|cut -d',' -f3 | awk
>>>>> 
>>>>> '{s+=$1}
>>>>> 
>>>>>> END {print s}'
>>>>> 
>>>>> 794.956
>>>>> 
>>>>> On Friday 09 December 2011 12:09:56 Kenneth Lundin wrote:
>>>>>> On 12/5/11, Nico Kruber <> wrote:
>>>>>>> Is there any news on this?
>>>>>>> 
>>>>>>> The performance drop of the recent R15 checkout compared to R14B04
>>>>> 
>>>>> in
>>>>> 
>>>>>>> our
>>>>>>> application is now at _30%_ compared to a drop of "only" 15% in
>>>>> 
>>>>> R15A!
>>>>> 
>>>>>> When working with R15B we are of course performing a number of
>>>>>> bencmarks to keep track of the performance.
>>>>>> 
>>>>>> Whe always strive to improve general performance in each release AND
>>>>>> OUR BENCHMARKS INDICATE THAT R15B IS FASTER IN GENERAL THAN R14B04.
>>>>>> 
>>>>>> It is however always possible that some specific operations or
>>>>>> combinations of operations get slower while others are optimized.
>>>>>> 
>>>>>> Regarding the findings for this particular application we think the
>>>>>> reason for slowdown is a very frequent but non typical usage pattern
>>>>>> that now becomes visible as a performance bottleneck.
>>>>>> 
>>>>>> 
>>>>>> / Kenneth, Erlang/OTP
>>>>> 
>>>>> Ericsson_______________________________________________
> <bench.cpuinfo>_______________________________________________
> erlang-questions mailing list
> 
> http://erlang.org/mailman/listinfo/erlang-questions






More information about the erlang-questions mailing list