hackney slow on reading chunked reply of ~20mb

[nateless]

Hello,

We've been thinking its Tesla's problem (elixir-tesla/tesla#471) but after profiling we get that reading the large body takes roughly 40 seconds.

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                  11057     0.00      2178  [      0.20]
io_lib_fread:fread_result/3                      11057     0.00      2182  [      0.20]
prim_inet:enc_time/1                             11057     0.00      2345  [      0.21]
io_lib_fread:fread/2                             11057     0.01      2447  [      0.22]
hackney_http:read_chunk/2                        11056     0.01      2623  [      0.24]
io_lib_fread:fread1/8                            11057     0.01      2632  [      0.24]
prim_inet:recv/3                                 11056     0.01      2656  [      0.24]
hackney_http:'-fun.te_chunked/2-'/2              11057     0.01      2660  [      0.24]
io_lib_fread:fread_field/3                       11057     0.01      3053  [      0.28]
io_lib_fread:fread_field/1                       11057     0.01      3697  [      0.33]
io_lib:fread/2                                   11057     0.01      3770  [      0.34]
erlang:list_to_integer/2                         11065     0.01      4087  [      0.37]
inet_tcp:recv/3                                  11056     0.01      4200  [      0.38]
io_lib_fread:fread_field/4                       22114     0.01      4220  [      0.19]
erlang:port_get_data/1                           11059     0.01      4906  [      0.44]
inet_db:lookup_socket/1                          11059     0.01      4910  [      0.44]
lists:reverse/2                                  22121     0.01      5107  [      0.23]
hackney_response:stream_body1/2                  11057     0.01      5242  [      0.47]
gen:do_call/4                                        5     0.01      5411  [   1082.20]
hackney_tcp:recv/3                               11056     0.01      5507  [      0.50]
prim_inet:ctl_cmd/3                              11063     0.01      5975  [      0.54]
hackney_response:stream_body_recv/2              11055     0.01      5994  [      0.54]
erlang:port_control/3                            11063     0.01      6007  [      0.54]
hackney_response:recv/1                          11056     0.01      6048  [      0.55]
hackney_response:stream_body/2                   11055     0.01      6424  [      0.58]
io_lib_fread:fread1/7                            11057     0.01      6915  [      0.63]
prim_inet:recv0/3                                11056     0.02      7441  [      0.67]
hackney_response:read_body/3                         2     0.02      7485  [   3742.50]
hackney_http:te_chunked/2                        11057     0.02      7831  [      0.71]
hackney_http:parse_body/1                        11058     0.02      7901  [      0.71]
erlang:send/2                                        2     0.02      8016  [   4008.00]
prim_inet:async_recv/3                           11056     0.02      8423  [      0.76]
hackney_http:transfer_decode/2                   11057     0.02      8967  [      0.81]
io_lib_fread:fread/4                             22114     0.02      9052  [      0.41]
hackney_http:read_size/1                         11057     0.02      9683  [      0.88]
gen_tcp:recv/3                                   11056     0.02      9914  [      0.90]
lists:reverse/1                                  33187     0.02     10943  [      0.33]
io_lib_fread:fread_unsigned/7                    11057     0.03     13152  [      1.19]
io_lib_fread:fread_digits/4                      77394     0.03     13471  [      0.17]
hackney_http:read_size/3                         77394     0.26    123753  [      1.60]
erts_internal:port_control/3                     11063     0.27    129846  [     11.74]
erlang:setelement/3                              44314    11.24   5414710  [    122.19]
hackney_http:execute/2                           11067    87.74  42250379  [   3817.69]
----------------------------------------------  ------  -------  --------  [----------]
Total:                                          665854  100.00%  48154095  [     72.32]
"total = 100.02"

[Polexy]

i have also reproduced, execution time is increased with chunk size

    N = 100,
    Start = erlang:system_time(microsecond),
    [begin
         {ok, _Code, _Headers, Ref} = hackney:request(get, Url, [], [], []),
         hackney:body(Ref)
    end
        || _X <- lists:seq(1, N)],
    Diff = erlang:system_time(microsecond) - Start,
    io:format("~p requests, total time: ~ps~n",[N, Diff/1000000]).

without chunks, Total size: 1301.7705078125KB
100 requests, total time: 0.649146s

Total size: 1301.7705078125KB, chunk size: 1024, chunks: 1302
100 requests, total time: 0.461806s

Total size: 1301.7705078125KB, chunk size: 10240, chunks: 131
100 requests, total time: 0.467853s

Total size: 1301.7705078125KB, chunk size: 102400, chunks: 14
100 requests, total time: 0.623883s

Total size: 1301.7705078125KB, chunk size: 1024000, chunks: 2
100 requests, total time: 9.556485s
---

Total size: 13096.701171875KB, chunk size: 1024000, chunks: 14
100 requests, total time: 53.445918s
vs
without chunks, Total size: 13096.701171875KB
100 requests, total time: 6.320183s