Hi Jose, In case it helps, I also ran this test case and watched some surprising results in observer. They are concerning but they still don't tell me what's going on.
"If your tests do nothing, do you still get the slowdown?" -> I tried a test "lol" do assert true end, it's fast :) "What if you add a Bypass to a new application?" -> What do you mean ? <https://lh3.googleusercontent.com/-8eWp7fiZtkQ/V3FE-wOy8fI/AAAAAAAAAY4/WQ34yKIs7f8MTPw-8-RCPght1No_SAIywCLcB/s1600/Screen%2BShot%2B2016-06-27%2Bat%2B16.13.44.png> <https://lh3.googleusercontent.com/-DfG0lUOejsQ/V3FFBQ3dNzI/AAAAAAAAAZA/o9d3ieihB6c2SIvul_uviIKsccedql6kgCLcB/s1600/Screen%2BShot%2B2016-06-27%2Bat%2B16.17.24.png> Le lundi 27 juin 2016 16:16:44 UTC+1, José Valim a écrit : > > The next course of action is to try to isolate the error. If your tests do > nothing, do you still get the slowdown? What if you add a Bypass to a new > application? Maybe something is holding the requests on the server? Try > removing or moving components around until you find the minimum sample that > reproduces it. > > On Monday, June 27, 2016, Sébastien Varlet <[email protected] > <javascript:>> wrote: > >> Hi, >> >> Thanks for your answer. >> >> The Bypass documentation explains that it takes care of shutting down >> what was setup for each test (I guess their macros setup an on_exit >> callback). Also I coded many other tests the exact same way in the same >> codebase and they never caused this problem. >> >> I verified, each test adds its own ~2 seconds not 5 (I have 5 tests >> therefore the test case takes 10 secs). >> >> Also, when I replace the JSON document by a very small one such as: >> >> @prebaked_response """ >> { >> "response": { >> "blog": {}, >> "posts": [] >> } >> } >> """ >> >> the problem disappears. So if the size of the document is the issue, I'm >> back to square one: is the json decoding taking too long ? apparently no >> since mix test --trace reports a duration for each test between 30ms and >> 200ms. Is the JSON document passed/copied around and it's taking too long ? >> apparently no for the same reason... >> >> I'm really confused here. >> >> >> >> >> Le lundi 27 juin 2016 15:06:00 UTC+1, OvermindDL1 a écrit : >>> >>> 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/fb765078-480d-4078-bd9c-2e4b0a2d76ef%40googlegroups.com >> >> <https://groups.google.com/d/msgid/elixir-lang-talk/fb765078-480d-4078-bd9c-2e4b0a2d76ef%40googlegroups.com?utm_medium=email&utm_source=footer> >> . >> For more options, visit https://groups.google.com/d/optout. >> > > > -- > > > *José Valim* > www.plataformatec.com.br > Skype: jv.ptec > Founder and Director of R&D > > -- 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/c42e232b-a59c-45b9-b8ce-66ec68dd22a1%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
