Hi,
I’m currently working on a client for the Tumblr API. Turns out it’s way more work than anticipated but still a good way to practice.
However, I’m running at the moment into a problem with a test case where each test is taking about 2 seconds to run. These tests setup their own cowboy server (thanks to bypass) in order to simulate the calls. I have written such tests previously and never had this issue.
This is the file I’m working on:
https://github.com/svarlet/ex_tumblr/blob/rework_testing_with_bypass/test/ex_tumblr/posts_test.exs#L49
As you can see, the JSON response is read from a file ‘posts.json’ also in the github repo. It is a rather large file (400KB). So my first suspicion was about the size of the file and the time taken by Poison to parse it.
So I used ExProf to verify that:
FUNCTION CALLS % TIME [uS / CALLS]
-------- ----- ------- ---- [----------]
[...]
'Elixir.Enum':'-reduce/3-fun-1-'/4 207 0.03 196 [ 0.95]
'Elixir.ExTumblr.Utils.Parsing':'-to_struct/3-fun-0-'/2 206 0.04 198 [ 0.96]
lists:reverse/1 105 0.04 226 [ 2.15]
lists:foldl/3 236 0.04 246 [ 1.04]
erlang:binary_to_atom/2 206 0.04 246 [ 1.19]
hackney_bstr:'-to_lower/1-lbc$^0/2-0-'/2 130 0.05 282 [ 2.17]
inet_tcp:recv/3 280 0.05 303 [ 1.08]
hackney_tcp_transport:recv/3 280 0.05 303 [ 1.08]
hackney_http:ce_identity/1 280 0.05 306 [ 1.09]
prim_inet:recv/3 280 0.06 311 [ 1.11]
prim_inet:recv0/3 280 0.06 320 [ 1.14]
hackney_http:content_decode/3 280 0.06 321 [ 1.15]
'Elixir.String.Chars':to_string/1 342 0.06 322 [ 0.94]
'Elixir.String.Chars.Atom':to_string/1 342 0.06 326 [ 0.95]
gen_tcp:recv/3 280 0.06 326 [ 1.16]
erlang:atom_to_binary/2 343 0.06 333 [ 0.97]
hackney_response:stream_body_recv/2 279 0.06 340 [ 1.22]
'Elixir.Map':do_take/3 363 0.06 342 [ 0.94]
erlang:port_get_data/1 282 0.06 344 [ 1.22]
hackney_response:stream_body/2 279 0.06 353 [ 1.27]
hackney_http:te_identity/2 280 0.06 358 [ 1.28]
hackney_http:transfer_decode/2 280 0.06 363 [ 1.30]
hackney_response:read_body/3 281 0.07 382 [ 1.36]
maps:'-fold/3-fun-0-'/3 207 0.07 398 [ 1.92]
maps:find/2 343 0.07 402 [ 1.17]
hackney_bstr:char_to_lower/1 115 0.08 475 [ 4.13]
hackney_http:'-parse_body/1-fun-3-'/1 280 0.11 608 [ 2.17]
'Elixir.String.Chars':impl_for/1 342 0.11 626 [ 1.83]
'Elixir.ExTumblr.Post':'-parse/1-fun-0-'/1 340 0.11 632 [ 1.86]
'Elixir.String.Chars':'impl_for!'/1 342 0.11 639 [ 1.87]
hackney_http:execute/1 286 0.12 652 [ 2.28]
'Elixir.Enum':'-map/2-lists^map/1-0-'/2 381 0.12 670 [ 1.76]
hackney_http:'-parse_body/1-fun-2-'/2 280 0.12 674 [ 2.41]
hackney_response:stream_body1/2 560 0.12 685 [ 1.22]
inet_db:lookup_socket/1 282 0.12 693 [ 2.46]
prim_inet:async_recv/3 280 0.12 700 [ 2.50]
hackney_response:recv/1 280 0.13 714 [ 2.55]
prim_inet:enc_time/1 281 0.13 724 [ 2.58]
prim_inet:ctl_cmd/3 287 0.13 741 [ 2.58]
hackney_http:parse_body/1 561 0.13 761 [ 1.36]
erlang:port_control/3 287 0.14 785 [ 2.74]
'Elixir.Poison.Parser':array_values/3 711 0.14 791 [ 1.11]
'Elixir.Poison.Parser':number_frac/2 788 0.15 830 [ 1.05]
'Elixir.Poison.Parser':number_start/1 788 0.15 838 [ 1.06]
erlang:binary_to_integer/1 788 0.15 839 [ 1.06]
'Elixir.Poison.Parser':number_int/2 784 0.15 853 [ 1.09]
hackney_response:stream_body/1 281 0.16 883 [ 3.14]
'Elixir.Poison.Parser':number_exp/3 788 0.16 903 [ 1.15]
maps:from_list/1 729 0.27 1514 [ 2.08]
'Elixir.Poison.Parser':number_complete/2 788 0.28 1571 [ 1.99]
'Elixir.Poison.Parser':number_digits/1 784 0.29 1620 [ 2.07]
hackney_http:execute/2 567 0.29 1641 [ 2.89]
erts_internal:port_control/3 287 0.34 1905 [ 6.64]
erlang:setelement/3 1728 0.39 2228 [ 1.29]
'Elixir.Poison.Parser':object_pairs/3 5077 1.00 5634 [ 1.11]
'Elixir.Poison.Parser':number_digits_count/2 5947 1.20 6765 [ 1.14]
'Elixir.Poison.Parser':object_name/2 5077 1.80 10167 [ 2.00]
'Elixir.Poison.Parser':value/2 5769 2.14 12061 [ 2.09]
erlang:iolist_to_binary/1 9324 2.23 12558 [ 1.35]
erlang:binary_to_integer/2 11587 2.58 14537 [ 1.25]
'Elixir.Poison.Parser':string_escape/2 19399 4.10 23114 [ 1.19]
'Elixir.Poison.Parser':skip_whitespace/1 21712 7.95 44850 [ 2.07]
'Elixir.Poison.Parser':string_continue/2 46845 9.96 56241 [ 1.20]
'Elixir.Poison.Parser':string_chunk_size/2 303284 60.04 338888 [ 1.12]
------------------------------------------------------- ------ ------- ------ [----------]
Total: 457768 100.00% 564404 [ 1.23]
Indeed, parsing takes time (value indicated in µs) but this is about half a second. When I run my 4 tests I could expect the test suite to take 2 seconds if they run sequentially. Yet, the test suite takes more than 10 seconds to run.
mix test --trace test/ex_tumblr/posts_test.exs
ExTumblr.PostTest
- test parse/1 can transform a generic map into a Post struct (6.5ms)
ExTumblr.PostsTest
- test emits request to the right path (195.3ms)
- test parses the http response into a Posts struct (55.6ms)
- test specifies the api key in the query (33.7ms)
- test sends a GET request (28.5ms)
Finished in 10.1 seconds
5 tests, 0 failures
What I notice every time the suite runs is a ~10 seconds pause between the two test cases. To be more specific:
mix test --trace test/ex_tumblr/posts_test.exs
ExTumblr.PostTest
- test parse/1 can transform a generic map into a Post struct (6.5ms)
############### 10 SECONDS PAUSE HERE ##############
ExTumblr.PostsTest- test emits request to the right path (195.3ms)
- test parses the http response into a Posts struct (55.6ms)
- test specifies the api key in the query (33.7ms)
- test sends a GET request (28.5ms)
Finished in 10.1 seconds
5 tests, 0 failures
If I comment all these tests but one, I observe the same behaviour with a ~2 seconds pause. Every test basically adds its own ~2s pause.
I already posted this in the slack chat where @micmus and @ericmj were really kind and helpful but we couldn’t find the cause.
Can anybody find the problem ?
Thanks