Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Body parsing optimization #710

Merged
merged 1 commit into from
Mar 1, 2023
Merged

Body parsing optimization #710

merged 1 commit into from
Mar 1, 2023

Conversation

Polexy
Copy link
Contributor

@Polexy Polexy commented Nov 25, 2022

I have found some problem with body parsing for chunked encoded messages: #690 (comment)
I have understood parsing logic and optimized it. The main point of it to wait necessary portion of data instead of parsing each packet.
My results:

before fix

no chunks:
100 requests, total time: 0.663915s
100 requests, total time: 0.677419s
100 requests, total time: 0.678405s

Total data: 1301.7705078125KB, chunk size: 4096, total chunks: 326
100 requests, total time: 0.742954s
100 requests, total time: 0.727678s
100 requests, total time: 0.709221s

Total data: 1301.7705078125KB, chunk size: 40960, total chunks: 33
100 requests, total time: 0.74006s
100 requests, total time: 0.717082s
100 requests, total time: 0.719162s

Total data: 1301.7705078125KB, chunk size: 409600, total chunks: 4
100 requests, total time: 3.619821s
100 requests, total time: 3.608936s
100 requests, total time: 3.611868s


Total data: 13096.701171875KB, chunk size: 4096000, total chunks: 4
10 requests, total time: 49.382239s

after fix

no chunks:
100 requests, total time: 0.597693s
100 requests, total time: 0.609578s
100 requests, total time: 0.595912s

Total data: 1301.7705078125KB, chunk size: 4096, total chunks: 326
100 requests, total time: 0.694447s
100 requests, total time: 0.690872s
100 requests, total time: 0.668783s

Total data: 1301.7705078125KB, chunk size: 40960, total chunks: 33
100 requests, total time: 0.552928s
100 requests, total time: 0.559099s
100 requests, total time: 0.583001s

Total data: 1301.7705078125KB, chunk size: 409600, total chunks: 4
100 requests, total time: 0.605153s
100 requests, total time: 0.620267s
100 requests, total time: 0.601012s

Total data: 13096.701171875KB, chunk size: 4096000, total chunks: 4
10 requests, total time: 0.604024s

before:

FUNCTION                                      CALLS        %  TIME  [uS / CALLS]
--------                                      -----  -------  ----  [----------]
prim_inet:recv0/3                               1833     0.24     427  [      0.23]
hackney_http:transfer_decode/2                  1838     0.25     444  [      0.24]
hackney_http:te_chunked/2                       1838     0.27     477  [      0.26]
hackney_http:read_size/1                        1838     0.28     499  [      0.27]
prim_inet:async_recv/3                          1833     0.29     514  [      0.28]
hackney_response:read_body/3                       6     0.33     594  [     99.00]
io_lib_fread:fread/4                            3676     0.35     624  [      0.17]
lists:reverse/1                                 5530     0.40     707  [      0.13]
io_lib_fread:fread_unsigned/7                   1838     0.43     762  [      0.41]
io_lib_fread:fread_digits/4                    11938     0.51     900  [      0.08]
erts_internal:port_control/3                    1839     1.49    2655  [      1.44]
hackney_http:read_size/3                       11938     1.86    3317  [      0.28]
erlang:setelement/3                             7421     7.52   13374  [      1.80]
hackney_http:execute/2                          1845    81.92  145728  [     78.99]
--------------------------------------------  ------  -------  ------  [----------]
Total:                                        108568  100.00%  177886  [      1.64]

after:

FUNCTION                                      CALLS        %  TIME  [uS / CALLS]
--------                                      -----  -------  ----  [----------]
erlang:demonitor/2                               29     0.64    33  [      1.14]
io_lib_format:build_limited/5                   144     0.66    34  [      0.24]
erlang:setelement/3                             133     0.85    44  [      0.33]
hackney_bstr:'-to_lower/1-lbc$^0/2-0-'/2        260     1.01    52  [      0.20]
hackney_http:read_size/3                         95     1.03    53  [      0.56]
io_lib_format:collect_cseq/2                     48     1.07    55  [      1.15]
dict:fold_seg/4                                  51     1.14    59  [      1.16]
erts_internal:open_port/2                         1     1.14    59  [     59.00]
io:execute_request/3                             25     1.28    66  [      2.64]
io_lib_format:indentation/2                    1028     1.45    75  [      0.07]
io_lib_format:cdata_to_chars/1                 1028     3.10   160  [      0.16]
erts_internal:port_control/3                     17    14.33   740  [     43.53]
hackney_response:read_body/3                      6    15.67   809  [    134.83]
hackney_http:execute/2                           23    28.20  1456  [     63.30]
--------------------------------------------  -----  -------  ----  [----------]
Total:                                         8996  100.00%  5164  [      0.57]

i have also checked tests\dialyzer on OTP 25.1.1

  All 207 tests passed.
$ ./rebar3 dialyzer
Job succeeded

@benoitc benoitc merged commit 9a4f16b into benoitc:master Mar 1, 2023
@benoitc
Copy link
Owner

benoitc commented Mar 1, 2023

thanks!

danielfinke added a commit to 2600hz/erlang-hackney that referenced this pull request Sep 6, 2024
When streaming a chunked response, it is possible to cause a TCP receive
hang under particular circumstances. If at one point the parser buffer
doesn't have the whole chunk, at a later point the buffer ends up empty
`<<>>`, and subsequently `hackney_response:stream_body/1` is called,
`hackney_response:recv/2` will hang if the expected remaining size
exceeds the remainder of the response. That expected size is actually
stale, from the earlier point when the parser did not have the whole
chunk. This issue slipped in with benoitc#710.

This was identified when using https://github.com/benoitc/couchbeam and
sending several chunked requests. If the last non-terminating chunk
completed the response JSON object, `hackney_response:skip_body/1` is
called to discard the remaining body, but is told to receive a number of
bytes equal to the expected remaining size which will frequently exceed
the small terminating chunk and trailers. As a result, the recv
operation hangs waiting for bytes that will never arrive.

Now, the transfer state (`BufSize`/`ExpectedSize`) are reset after each
successful chunk. The speed benefit of benoitc#710 is retained
(tested with the same approach as in that PR).

- correct some related typespecs
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants