How to debug\profile scheduler utilization

Polexy · November 18, 2022, 1:52pm

when our app working: scheduler utilization stocking on 100%, but total cpu usage is about 50%, how we can understand where is problem and optimize it?

[{total,0.5281588460041117,"52.8%"},
 {weighted,1.0563176920082233,"105.6%"},
 {normal,1,1.0,"100.0%"},
 {normal,2,1.0,"100.0%"},
 {normal,3,1.0,"100.0%"},
 {normal,4,1.0,"100.0%"},
 {cpu,5,0.08379955305185231,"8.4%"},
 {cpu,6,0.01765390297141619,"1.8%"},
 {cpu,7,0.082705427673925,"8.3%"},
 {cpu,8,0.04070323424296014,"4.1%"}]

                       lock   id  #tries  #collisions  collisions [%]  time [us]  duration [%]
                      -----  --- ------- ------------ --------------- ---------- -------------
                  run_queue    6 5557965        17786          0.3200     265722        0.0750
             alcu_allocator   10  138892         1264          0.9101     253522        0.0715
                  proc_main 2402 1553115         1480          0.0953      90911        0.0256
                  port_lock  289  198267          269          0.1357      23203        0.0065
               drv_ev_state  128  510171         2246          0.4402      20033        0.0057
                       mseg    1   73798           82          0.1111      13695        0.0039
    erl_db_catree_base_node    1   94973          128          0.1348       8790        0.0025
                  proc_msgq 2402 2324178          765          0.0329       4670        0.0013
                proc_status 2402 1398041           56          0.0040       4003        0.0011
                crypto_stat   41   42574           19          0.0446       3305        0.0009
              pid_ref_table    5  580838           61          0.0105       2688        0.0008
               db_hash_slot  448  738619           16          0.0022        138        0.0000
                     db_tab   64 1433299            5          0.0003         38        0.0000
 dirty_run_queue_sleep_list    2   50657            8          0.0158          5        0.0000

Average thread real-time    : 1037288 us
Accumulated system run-time : 4465310 us
Average scheduler run-time  : 1037413 us

        Thread    alloc      aux      bifbusy_wait check_io emulator      ets       gc  gc_full      nif    other     port     send    sleep   timers

Stats per thread:
     async( 0)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 1)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 2)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 3)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 4)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 5)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 6)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 7)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 8)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
     async( 9)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
       aux( 1)    0.05%    0.42%    0.00%    0.00%    0.12%    0.00%    0.00%    0.00%    0.00%    0.00%    1.42%    0.00%    0.00%   98.00%    0.00%
dirty_cpu_( 1)    1.25%    0.00%    0.00%    1.53%    0.00%    0.04%    0.00%    7.16%    4.27%    0.00%    0.02%    0.00%    0.00%   85.72%    0.00%
dirty_cpu_( 2)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_cpu_( 3)    0.24%    0.00%    0.00%    0.35%    0.00%    0.01%    0.00%    1.72%    0.99%    0.00%    0.00%    0.00%    0.00%   96.68%    0.00%
dirty_cpu_( 4)    0.72%    0.00%    0.00%    1.36%    0.00%    0.04%    0.00%    5.74%    2.91%    0.00%    0.01%    0.00%    0.00%   89.22%    0.00%
dirty_io_s( 1)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 2)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 3)    0.00%    0.00%    0.00%    0.02%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.98%    0.00%
dirty_io_s( 4)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 5)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 6)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 7)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 8)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s( 9)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
dirty_io_s(10)    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
      poll( 0)    0.00%    0.00%    0.00%    0.00%    0.03%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.97%    0.00%
 scheduler( 1)   16.98%    0.26%    7.91%    0.00%    0.23%   62.26%    0.42%    2.98%    0.05%    7.55%    0.31%    0.86%    0.08%    0.00%    0.10%
 scheduler( 2)   18.75%    0.11%    1.55%    0.00%    0.13%   75.10%    0.13%    0.72%    0.06%    2.39%    0.24%    0.75%    0.06%    0.00%    0.02%
 scheduler( 3)   15.70%    0.09%    2.75%    0.00%    0.13%   79.12%    0.11%    0.27%    0.01%    0.02%    0.21%    1.35%    0.22%    0.00%    0.02%
 scheduler( 4)   16.46%    0.07%    1.02%    0.00%    0.09%   74.49%    0.03%    1.66%    0.06%    5.23%    0.20%    0.67%    0.02%    0.00%    0.01%

Stats per type:
         async    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
           aux    0.05%    0.42%    0.00%    0.00%    0.12%    0.00%    0.00%    0.00%    0.00%    0.00%    1.42%    0.00%    0.00%   98.00%    0.00%
dirty_cpu_sche    0.55%    0.00%    0.00%    0.81%    0.00%    0.02%    0.00%    3.66%    2.04%    0.00%    0.01%    0.00%    0.00%   92.91%    0.00%
dirty_io_sched    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%  100.00%    0.00%
          poll    0.00%    0.00%    0.00%    0.00%    0.03%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%    0.00%   99.97%    0.00%
     scheduler   16.97%    0.13%    3.31%    0.00%    0.15%   72.75%    0.17%    1.41%    0.04%    3.79%    0.24%    0.91%    0.09%    0.00%    0.04%

max-au · November 18, 2022, 4:15pm

There are no visible lock contention signs in your paste, hence the problem might be outside of the BEAM.

How many CPU threads this machine has? In your paste, BEAM uses only 4 (which is relatively rare nowadays, unless the server is a VM with CPU limitations)
Are there any CPU limiters (e.g. cgroupsv2 with CPU controller) running?

Abdelghani · November 18, 2022, 8:36pm

Hello @Polexy, how can I get these tables please ?

paulo-f-oliveira · November 19, 2022, 4:40am

@Abdelghani

First element: scheduler:utilization/1.

Second element: lock profiler.

Third element: msacc.

Abdelghani · November 19, 2022, 5:07am

@paulo-f-oliveira Thank you so much bro, that will be very helpful

rvirding · November 19, 2022, 5:36pm

Do you only have 4 cores or is that all you are using? How many cores does the machine have?

Polexy · November 21, 2022, 10:03am

yes it’s only 4 cpu without additional rules\configuration
it has reproduced when worked with big json, so with eprof i found some problem with hackney

github.com/benoitc/hackney

hackney slow on reading chunked reply of ~20mb

opened 06:49PM - 25 Jun 21 UTC

nateless

Hello, We've been thinking Response headers: ``` <<< RESPONSE <<< content-lenght: content-type: application/json etag: "123-1624560200-ba73c0" date: Fri, 25 Jun 2021 17:20:10 GMT transfer-encoding: chunked ``` profile: ``` io_lib_fread:fread_skip_white/1 io_lib_fread:fread_result/3 prim_inet:enc_time/1 io_lib_fread:fread/2 hackney_http:read_chunk/2 io_lib_fread:fread1/8 prim_inet:recv/3 hackney_http:'-fun.te_chunked/2-'/2 io_lib_fread:fread_field/3 io_lib_fread:fread_field/1 io_lib:fread/2 erlang:list_to_integer/2 inet_tcp:recv/3 io_lib_fread:fread_field/4 erlang:port_get_data/1 inet_db:lookup_socket/1 lists:reverse/2 hackney_response:stream_body1/2 gen:do_call/4 hackney_tcp:recv/3 prim_inet:ctl_cmd/3 hackney_response:stream_body_recv/2 erlang:port_control/3 hackney_response:recv/1 hackney_response:stream_body/2 io_lib_fread:fread1/7 prim_inet:recv0/3 hackney_response:read_body/3 hackney_http:te_chunked/2 hackney_http:parse_body/1 erlang:send/2 prim_inet:async_recv/3 hackney_http:transfer_decode/2 io_lib_fread:fread/4 hackney_http:read_size/1 gen_tcp:recv/3 lists:reverse/1 io_lib_fread:fread_unsigned/7 io_lib_fread:fread_digits/4 hackney_http:read_size/3 erts_internal:port_control/3 erlang:setelement/3 hackney_http:execute/2 -------------------------- Total: "total = 100.02" ``` its Tesla's problem (https://github.com/teamon/te…sla/issues/471) but after profiling we get that reading the large body takes roughly 40 seconds. 11057 0.00 2178 [ 0.20] 11057 0.00 2182 [ 0.20] 11057 0.00 2345 [ 0.21] 11057 0.01 2447 [ 0.22] 11056 0.01 2623 [ 0.24] 11057 0.01 2632 [ 0.24] 11056 0.01 2656 [ 0.24] 11057 0.01 2660 [ 0.24] 11057 0.01 3053 [ 0.28] 11057 0.01 3697 [ 0.33] 11057 0.01 3770 [ 0.34] 11065 0.01 4087 [ 0.37] 11056 0.01 4200 [ 0.38] 22114 0.01 4220 [ 0.19] 11059 0.01 4906 [ 0.44] 11059 0.01 4910 [ 0.44] 22121 0.01 5107 [ 0.23] 11057 0.01 5242 [ 0.47] 5 0.01 5411 [ 1082.20] 11056 0.01 5507 [ 0.50] 11063 0.01 5975 [ 0.54] 11055 0.01 5994 [ 0.54] 11063 0.01 6007 [ 0.54] 11056 0.01 6048 [ 0.55] 11055 0.01 6424 [ 0.58] 11057 0.01 6915 [ 0.63] 11056 0.02 7441 [ 0.67] 2 0.02 7485 [ 3742.50] 11057 0.02 7831 [ 0.71] 11058 0.02 7901 [ 0.71] 2 0.02 8016 [ 4008.00] 11056 0.02 8423 [ 0.76] 11057 0.02 8967 [ 0.81] 22114 0.02 9052 [ 0.41] 11057 0.02 9683 [ 0.88] 11056 0.02 9914 [ 0.90] 33187 0.02 10943 [ 0.33] 11057 0.03 13152 [ 1.19] 77394 0.03 13471 [ 0.17] 77394 0.26 123753 [ 1.60] 11063 0.27 129846 [ 11.74] 44314 11.24 5414710 [ 122.19] 11067 87.74 42250379 [ 3817.69] -------------------- ------ ------- -------- [----------] 665854 100.00% 48154095 [ 72.32]