On 2024-01-12 00:47 +01, Alexander Bluhm <alexander.bluhm@gmx.net> wrote:
> Hi Florian,
>
> Did you have a chance to look at your test setup again?  Otto has
> positive results and I found some artifacts with your config.  So
> it may be problems in the measurement.

sorry for the delay, I needed some time to figure out what's going on.

Thanks for spotting rrl, I always forget about that.

(What happens here is if the same client asks the (qname,qtype) tuple
more than 200 times a second it gets rate limited. Without your diff the
input file was just big enough that we wouldn't hit it. The diff made
things faster so we ran into this issue).

With that out of the way I spotted a new issue which I think is a bad
interaction with the scheduler. But we already know that the scheduler
sucks.

Anyway, here goes:

8 cpu VM, nsd server-count: 8.
On current I establish that this particular setup can do about 29k qps.

If I then limit the qps to 20k, thusly:
    dnsperf -c 1 -l 300 -d dnsperf.input -Q 20000 -s ...
I get a very smooth traffic graph on -current and dnsperf reports this:

Statistics:

  Queries sent:         6000000
  Queries completed:    5999087 (99.98%)
  Queries lost:         913 (0.02%)

  Response codes:       NOERROR 5999087 (100.00%)
  Average packet size:  request 30, response 348
  Run time (s):         300.000134
  Queries per second:   19996.947735

  Average Latency (s):  0.000273 (min 0.000059, max 0.561247)
  Latency StdDev (s):   0.001668


With the diff, I get extremely spiky traffic and dnsperf reports this:
Statistics:

  Queries sent:         2376641
  Queries completed:    2371935 (99.80%)
  Queries lost:         4706 (0.20%)

  Response codes:       NOERROR 2371935 (100.00%)
  Average packet size:  request 30, response 348
  Run time (s):         300.000139
  Queries per second:   7906.446337

  Average Latency (s):  0.000530 (min 0.000055, max 4.935858)
  Latency StdDev (s):   0.039866


It also says this, a lot:

Warning: received a response with an unexpected (maybe timed out) id: 26040
Warning: received a response with an unexpected (maybe timed out) id: 26046
Warning: received a response with an unexpected (maybe timed out) id: 26043

That means that packets don't get lost but get delayed for a very long
time, at least 5 seconds.

I intentionally did *not* fiddle around with -t and -q, because this
demonstrates that there are workloads that get considerably worse with
the diff.

The difference between -current and the diff goes away if I set
server-count to 1 or 2. Performance also considerably increases on
-current with a server-count of 1 or 2, this particular vm can then do
125k qps.

>
> Any objections to commit?

No objection from me with a DNS hat on, server-count 8 is not a sensible
setup so it doesn't matter that things get worse with that, it also
seems unrelated to the diff, it just uncovers the next problem...

Could this negatively impact nfs work loads?

>
> bluhm
>
> On Wed, Jan 10, 2024 at 12:48:08AM +0100, Alexander Bluhm wrote:
>> Hi Florian,
>> 
>> I have repeated your tests.  Client was Linux, nsd running on OpenBSD
>> with interface ixl 10 GBit.
>> 
>> I had to tune a few things.
>> 
>> dnsperf was idling.  When packets were lost, it was waiting and
>> running into timeouts.  The options -t 0.5 -q 1000 have fixed this.
>> 
>> Then nsd hit some rate limit.  rrl-ratelimit: 0 fixed this.
>> 
>> Without patch:
>> 
>> 1 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         3227517
>>   Queries completed:    3205187 (99.31%)
>>   Queries lost:         22330 (0.69%)
>> 
>>   Response codes:       NOERROR 3205187 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.022241
>>   Queries per second:   26704.942128
>> 
>>   Average Latency (s):  0.033894 (min 0.000269, max 0.060909)
>>   Latency StdDev (s):   0.007033
>> 
>> 2 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         3172874
>>   Queries completed:    3153564 (99.39%)
>>   Queries lost:         19310 (0.61%)
>> 
>>   Response codes:       NOERROR 3153564 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.017205
>>   Queries per second:   26275.932688
>> 
>>   Average Latency (s):  0.034950 (min 0.000204, max 0.064919)
>>   Latency StdDev (s):   0.006970
>> 
>> 4 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         2957082
>>   Queries completed:    2936696 (99.31%)
>>   Queries lost:         20386 (0.69%)
>> 
>>   Response codes:       NOERROR 2936696 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.020770
>>   Queries per second:   24468.231624
>> 
>>   Average Latency (s):  0.037364 (min 0.000396, max 0.071416)
>>   Latency StdDev (s):   0.007801
>> 
>> 8 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         2904008
>>   Queries completed:    2884021 (99.31%)
>>   Queries lost:         19987 (0.69%)
>> 
>>   Response codes:       NOERROR 2884021 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.023641
>>   Queries per second:   24028.774465
>> 
>>   Average Latency (s):  0.038088 (min 0.000477, max 0.072635)
>>   Latency StdDev (s):   0.007863
>> 
>> 10 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         2903668
>>   Queries completed:    2885793 (99.38%)
>>   Queries lost:         17875 (0.62%)
>> 
>>   Response codes:       NOERROR 2885793 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.020118
>>   Queries per second:   24044.243982
>> 
>>   Average Latency (s):  0.038434 (min 0.000666, max 0.069927)
>>   Latency StdDev (s):   0.007750
>> 
>> 1 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         3164221
>>   Queries completed:    3142602 (99.32%)
>>   Queries lost:         21619 (0.68%)
>> 
>>   Response codes:       NOERROR 3142602 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.019456
>>   Queries per second:   26184.104684
>> 
>>   Average Latency (s):  0.034711 (min 0.000322, max 0.062194)
>>   Latency StdDev (s):   0.006918
>> 
>> 2 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         3093913
>>   Queries completed:    3075364 (99.40%)
>>   Queries lost:         18549 (0.60%)
>> 
>>   Response codes:       NOERROR 3075364 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.021567
>>   Queries per second:   25623.428163
>> 
>>   Average Latency (s):  0.035943 (min 0.000225, max 0.064438)
>>   Latency StdDev (s):   0.007203
>> 
>> 4 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         3036341
>>   Queries completed:    3019280 (99.44%)
>>   Queries lost:         17061 (0.56%)
>> 
>>   Response codes:       NOERROR 3019280 (100.00%)
>>   Average packet size:  request 41, response 708
>>   Run time (s):         120.021467
>>   Queries per second:   25156.166438
>> 
>>   Average Latency (s):  0.036873 (min 0.000309, max 0.065962)
>>   Latency StdDev (s):   0.007325
>> 
>> 8 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         2874645
>>   Queries completed:    2854016 (99.28%)
>>   Queries lost:         20629 (0.72%)
>> 
>>   Response codes:       NOERROR 2854016 (100.00%)
>>   Average packet size:  request 41, response 708
>>   Run time (s):         120.019459
>>   Queries per second:   23779.610605
>> 
>>   Average Latency (s):  0.038397 (min 0.000289, max 0.078476)
>>   Latency StdDev (s):   0.008151
>> 
>> 10 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         2900660
>>   Queries completed:    2881717 (99.35%)
>>   Queries lost:         18943 (0.65%)
>> 
>>   Response codes:       NOERROR 2881717 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.021588
>>   Queries per second:   24009.988936
>> 
>>   Average Latency (s):  0.038323 (min 0.000786, max 0.070126)
>>   Latency StdDev (s):   0.007967
>> 
>> With patch:
>> 
>> 1 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         4876706
>>   Queries completed:    4835202 (99.15%)
>>   Queries lost:         41504 (0.85%)
>> 
>>   Response codes:       NOERROR 4835202 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.008427
>>   Queries per second:   40290.520598
>> 
>>   Average Latency (s):  0.020474 (min 0.000197, max 0.037249)
>>   Latency StdDev (s):   0.003392
>> 
>> 2 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         5333880
>>   Queries completed:    5291383 (99.20%)
>>   Queries lost:         42497 (0.80%)
>> 
>>   Response codes:       NOERROR 5291383 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.017653
>>   Queries per second:   44088.372566
>> 
>>   Average Latency (s):  0.018545 (min 0.000236, max 0.040967)
>>   Latency StdDev (s):   0.003340
>> 
>> 4 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         4774984
>>   Queries completed:    4740127 (99.27%)
>>   Queries lost:         34857 (0.73%)
>> 
>>   Response codes:       NOERROR 4740127 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.012948
>>   Queries per second:   39496.796629
>> 
>>   Average Latency (s):  0.021574 (min 0.000214, max 0.044003)
>>   Latency StdDev (s):   0.003443
>> 
>> 8 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         4570219
>>   Queries completed:    4540163 (99.34%)
>>   Queries lost:         30056 (0.66%)
>> 
>>   Response codes:       NOERROR 4540163 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.016320
>>   Queries per second:   37829.546848
>> 
>>   Average Latency (s):  0.023047 (min 0.000218, max 0.043848)
>>   Latency StdDev (s):   0.003457
>> 
>> 10 client(s) for 120s
>> Statistics:
>> 
>>   Queries sent:         4483909
>>   Queries completed:    4453033 (99.31%)
>>   Queries lost:         30876 (0.69%)
>> 
>>   Response codes:       NOERROR 4453033 (100.00%)
>>   Average packet size:  request 30, response 348
>>   Run time (s):         120.018514
>>   Queries per second:   37102.883977
>> 
>>   Average Latency (s):  0.023412 (min 0.000179, max 0.050242)
>>   Latency StdDev (s):   0.003542
>> 
>> 1 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         6182006
>>   Queries completed:    6142622 (99.36%)
>>   Queries lost:         39384 (0.64%)
>> 
>>   Response codes:       NOERROR 6142622 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.016841
>>   Queries per second:   51181.333793
>> 
>>   Average Latency (s):  0.016164 (min 0.000203, max 0.121570)
>>   Latency StdDev (s):   0.003032
>> 
>> 2 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         4606622
>>   Queries completed:    4566123 (99.12%)
>>   Queries lost:         40499 (0.88%)
>> 
>>   Response codes:       NOERROR 4566123 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.010458
>>   Queries per second:   38047.709142
>> 
>>   Average Latency (s):  0.021809 (min 0.000206, max 0.042266)
>>   Latency StdDev (s):   0.003622
>> 
>> 4 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         4405049
>>   Queries completed:    4371028 (99.23%)
>>   Queries lost:         34021 (0.77%)
>> 
>>   Response codes:       NOERROR 4371028 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.019519
>>   Queries per second:   36419.309429
>> 
>>   Average Latency (s):  0.023508 (min 0.000205, max 0.041420)
>>   Latency StdDev (s):   0.003575
>> 
>> 8 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         4543900
>>   Queries completed:    4513483 (99.33%)
>>   Queries lost:         30417 (0.67%)
>> 
>>   Response codes:       NOERROR 4513483 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.015983
>>   Queries per second:   37607.349348
>> 
>>   Average Latency (s):  0.023153 (min 0.000257, max 0.044908)
>>   Latency StdDev (s):   0.003653
>> 
>> 10 client(s) for 120s with DO bit set
>> Statistics:
>> 
>>   Queries sent:         4902997
>>   Queries completed:    4870271 (99.33%)
>>   Queries lost:         32726 (0.67%)
>> 
>>   Response codes:       NOERROR 4870271 (100.00%)
>>   Average packet size:  request 41, response 709
>>   Run time (s):         120.020385
>>   Queries per second:   40578.698360
>> 
>>   Average Latency (s):  0.021165 (min 0.000216, max 0.045527)
>>   Latency StdDev (s):   0.003578
>> 
>> So it is about 1.5 times faster.
>> 
>> bluhm
>

-- 
In my defence, I have been left unsupervised.