I've not seen those cowboy mocking libraries but is it possible that they have to be told to stop somehow, and instead there is maybe a 5s timeout on its process ending after yours ends and maybe another 5s start on the next? 5s is the default and you say 10s so this is the first thing that jumps out at me. Maybe watch sleeping processes waiting on something during those 2 5s chunks?
On Sunday, June 26, 2016 at 9:46:16 AM UTC-6, Sébastien Varlet wrote: > > 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/584b8771-2245-4af3-8167-d34f4e902b05%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
