LogObject::_checkout_write using a lot of CPU on many core servers

[bryancall]

When running benchmarking on large AMD servers (128 core servers) I am seeing a large amount of CPU being used in LogObject::_checkout_write. Here are the results from the benchmark:

https://github.com/bryancall/benchmark/blob/main/reports/amd_epic_7742_rhel7_aocc_rpms_no-freelist_jemalloc_openss111/http2_benchmark.report

[zwoop]

Curious if (significantly) increasing proxy.config.log.log_buffer_size would help here ?

[ywkaras]

Outside chance that #7382 would fix this.

[ywkaras]

One thing I'm seeing is that, when one thread is blocked waiting on this memory allocation:

trafficserver/proxy/logging/LogObject.cc

Line 399 in 564663b

new_buffer = new LogBuffer(Log::config, this, Log::config->log_buffer_size);

, any other thread trying to reserve (checkout) buffer space from the same LogObject will keep getting the return value LB_RETRY from LogBuffer::writer_checkout(), and will thus busy wait. So we could be indirectly seeing the memory allocation blocking problem. If this is the case, it would likely help to execute a thread yield when the LB_RETRY return value is returned.

I think I need to reproduce the problem with a baseline build, then see if this change improves things.

[ywkaras]

When I ran the benchmark on a 64-CPU Intex Xeon, I did not see this problem. It seems it is AMD dependent, or perhaps configuration dependent.

[bryancall]

Here is output from the package using the gcc compiler. This is using the http/2 benchmark. It isn't as bad as AOCC, but still it is an expensive operation:

**http2load**
finished in 120.34s, 24928.55 req/s, 390.48MB/s
requests: 3000000 total, 3000000 started, 3000000 done, 3000000 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 3000000 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 45.89GB (49274125891) total, 39.21MB (41119867) headers (space savings 96.56%), 45.78GB (49152000000) data
                     min         max         mean         sd        +/- sd
time for request:      297us    629.51ms      8.01ms      8.71ms    88.32%
time for connect:    33.66ms     91.14ms     53.87ms     14.13ms    55.50%
time to 1st byte:    35.44ms    123.39ms     69.10ms     16.27ms    63.50%
req/s           :     121.07      183.79      140.32       22.49    72.00%

**dstat**
You did not select any stats, using -cdngy by default.
ESC[7l----total-cpu-usage---- -dsk/total- ---net/lo-- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send: recv  send|  in   out | int   csw
  1   0  99   0   0   0|2614B  211k|   0     0 :   0     0 |   0     0 |  28k   84k
 44  34  22   0   0   0|3123B 1209k| 338M  338M:  11M  640k|   0     0 |1045k  443k
 46  34  20   0   0   0|   0    11M| 355M  355M:  11M  727k|   0     0 |1073k  440k
 46  34  20   0   0   0|   0    54M| 347M  347M:  11M  589k|   0     0 |1069k  419k
 45  35  19   0   0   0| 819B  688k| 386M  386M:  11M 1408k|   0     0 |1089k  509k
 48  32  19   0   0   0|   0  5896k| 368M  368M:  11M 1487k|   0     0 |1084k  499k
 43  37  20   0   0   1|   0    55M| 378M  378M:  11M 1542k|   0     0 |1096k  494k
 45  36  19   1   0   1|2048B   57M| 384M  384M:  11M 1689k|   0     0 |1095k  512k
 46  34  19   0   0   0|   0  4642k| 385M  385M:  11M 1547k|   0     0 |1089k  518k
 33  38  28   0   0   1|   0  4176k| 465M  465M:  11M 1877k|   0     0 |1001k  652k
 22  36  41   0   0   1|3686B   47M| 503M  503M:  11M 2015k|   0     0 | 858k  666k
 22  34  41   2   0   1|3277B   47M| 439M  439M:  11M 1637k|   0     0 |1122k  561k
 22  26  50   1   0   1|2867B   47M| 554M  554M:  11M 1814k|   0     0 | 806k  692k
**perf stat**

 Performance counter stats for process id '17983':

     10,466,445.26 msec task-clock                #   86.920 CPUs utilized
        28,088,848      context-switches          #    0.003 M/sec
         1,237,496      cpu-migrations            #    0.118 K/sec
           567,537      page-faults               #    0.054 K/sec
33,958,594,177,446      cycles                    #    3.245 GHz                      (66.69%)
   977,798,939,842      stalled-cycles-frontend   #    2.88% frontend cycles idle     (66.68%)
   675,897,082,577      stalled-cycles-backend    #    1.99% backend cycles idle      (66.69%)
 4,346,448,211,697      instructions              #    0.13  insn per cycle
                                                  #    0.22  stalled cycles per insn  (66.68%)
   916,758,375,688      branches                  #   87.590 M/sec                    (66.68%)
    27,001,398,959      branch-misses             #    2.95% of all branches          (66.70%)

     120.414481542 seconds time elapsed

**perf report**
# Total Lost Samples: 0
#
# Samples: 48M of event 'cycles'
# Event count (approx.): 36487625633965
#
#   Overhead  Shared Object         Symbol
# ..........  ....................  ..................................................
#
      39.17%  [kernel.kallsyms]     [k] native_queued_spin_lock_slowpath
      31.72%  traffic_server        [.] LogObject::_checkout_write
       1.79%  libpthread-2.17.so    [.] pthread_mutex_trylock
       1.67%  libjemalloc.so.2      [.] je_malloc_mutex_lock_slow
       0.54%  [kernel.kallsyms]     [k] copy_user_generic_string
       0.46%  [kernel.kallsyms]     [k] acpi_processor_ffh_cstate_enter
       0.43%  libc-2.17.so          [.] __memcpy_ssse3
       0.41%  [kernel.kallsyms]     [k] try_to_wake_up
       0.38%  [kernel.kallsyms]     [k] native_write_msr_safe

[bryancall]

Here is the annotation of the _checkout_write method:

[ywkaras]

I've not been able to reproduce the problem on the AMD proxy. These are my results:

-bash-4.2$ cat http2_benchmark.report 
**http2load**
finished in 10.17s, 98320.46 req/s, 1.50GB/s
requests: 1000000 total, 1000000 started, 1000000 done, 1000000 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 1000000 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 15.29GB (16419037931) total, 7.66MB (8031931) headers (space savings 96.63%), 15.26GB (16384000000) data
                     min         max         mean         sd        +/- sd
time for request:      111us    130.27ms      1.51ms      4.90ms    92.15%
time for connect:     3.38ms     87.15ms     38.33ms     20.31ms    69.00%
time to 1st byte:     5.59ms    106.70ms     47.40ms     19.96ms    74.00%
req/s           :     476.66      803.50      671.46       97.62    65.50%

**dstat**
You did not select any stats, using -cdngy by default.
----total-cpu-usage---- -dsk/total- ---net/lo-- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send: recv  send|  in   out | int   csw 
  1   0  99   0   0   0|2597B  211k|   0     0 :   0     0 |   0     0 |  28k   84k
 13   5  81   0   0   1|   0    19M|1590M 1590M:2169B 2064B|   0     0 | 340k  295k
**perf stat**

 Performance counter stats for process id '52642':

        167,926.60 msec task-clock                #   16.268 CPUs utilized          
           644,529      context-switches          #    0.004 M/sec                  
            16,677      cpu-migrations            #    0.099 K/sec                  
             7,170      page-faults               #    0.043 K/sec                  
   292,679,346,215      cycles                    #    1.743 GHz                      (67.12%)
    41,677,240,403      stalled-cycles-frontend   #   14.24% frontend cycles idle     (67.21%)
    22,998,344,897      stalled-cycles-backend    #    7.86% backend cycles idle      (67.20%)
   212,494,852,375      instructions              #    0.73  insn per cycle         
                                                  #    0.20  stalled cycles per insn  (67.15%)
    38,284,614,744      branches                  #  227.984 M/sec                    (67.13%)
     1,354,399,053      branch-misses             #    3.54% of all branches          (67.09%)

      10.322305247 seconds time elapsed

**perf report**
# Total Lost Samples: 0
#
# Samples: 1M of event 'cycles'
# Event count (approx.): 448142823289
#
#   Overhead  Shared Object         Symbol                                            
# ..........  ....................  ..................................................
#
       7.17%  libcrypto.so.1.1      [.] _aesni_ctr32_ghash_6x
       5.81%  libc-2.17.so          [.] __memcpy_ssse3
       3.51%  [kernel.kallsyms]     [k] copy_user_generic_string
       2.65%  libtscore.so.10.0.0   [.] freelist_new
       1.94%  [kernel.kallsyms]     [k] acpi_processor_ffh_cstate_enter
       1.60%  libc-2.17.so          [.] __memcmp_sse4_1
       1.04%  libtscpputil.so.10.0  [.] memcmp
       0.91%  traffic_server        [.] HpackIndexingTable::lookup
       0.80%  [kernel.kallsyms]     [k] _raw_spin_lock_irqsave
...

I'm seeing much lower req/s on the AMD than on the Intel Xeon.
Xeon:

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                64
On-line CPU(s) list:   0-63
Thread(s) per core:    2
Core(s) per socket:    16
Socket(s):             2
NUMA node(s):          2
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 79
Model name:            Intel(R) Xeon(R) CPU E5-2683 v4 @ 2.10GHz
Stepping:              1
CPU MHz:               1200.091
CPU max MHz:           3000.0000
CPU min MHz:           1200.0000
BogoMIPS:              4199.63
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              40960K

AMD:

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                128
On-line CPU(s) list:   0-127
Thread(s) per core:    2
Core(s) per socket:    64
Socket(s):             1
NUMA node(s):          1
Vendor ID:             AuthenticAMD
CPU family:            23
Model:                 49
Model name:            AMD EPYC 7742 64-Core Processor
Stepping:              0
CPU MHz:               2250.000
CPU max MHz:           2250.0000
CPU min MHz:           1500.0000
BogoMIPS:              4491.55
Virtualization:        AMD-V
L1d cache:             32K
L1i cache:             32K
L2 cache:              512K
L3 cache:              16384K

[ywkaras]

I've been able to cause a bottleneck in LogObject::_checkout_write() on the AMD host, using open source TS (commit 5c65bcb). I had to set proxy.config.exec_thread.autoconfig.scale to 2.0 . I ran TS (without manager) with this command:

TS_ROOT=$PWD LD_LIBRARY_PATH=$PWD/lib bin/traffic_server -f -F &

To see the bottleneck, I have to start with a empty log directory. I have to run 10 h2load processes at once with this script:

do_h2()
{
/home/wkaras/h2load --h1 -t 64 -D 60 -c 512 http://localhost:80$1/fake > ~/80$1.log &
}

rm -f ~/80*.log

for P in $( seq 81 90 )
do
  do_h2 $P
done

"fake" is 1024 byte object that I create with a PUSH. When I run "perf top", I see about 95% of CPU time being spent in _checkout_write. But, the bottleneck gradually disappears, the % of CPU time drops (as squid.log gets full?).

For unknown reasons, I sometimes see the (disappearing) bottleneck in HttpTransact::OriginDead() instead of LogObject::_checkout_write().

[ywkaras]

I build this commit, ywkaras@cd61f97 , and re-ran the testing above. Total requests per second almost doubled when the yield was enabled.