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 -- You received this message because you are subscribed to the Google Groups "elixir-lang-talk" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-talk/9b34b5d5-a574-43d6-bd41-5ef2d77ab005%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
