Hi José, Sure: Erlang/OTP 18 [erts-7.3] [source] [64-bit] [smp:8:8] [async-threads:10] [hipe] [kernel-poll:false] Interactive Elixir (1.3.0)
Thanks Le lundi 4 juillet 2016 10:31:24 UTC+2, José Valim a écrit : > > I will investigate. Can you please post your exact Erlang and Elixir > versions? If you start IEx with "iex" you can see both. > > > > *José Valim* > www.plataformatec.com.br > Skype: jv.ptec > Founder and Director of R&D > > On Mon, Jul 4, 2016 at 10:28 AM, Sébastien Varlet <[email protected] > <javascript:>> wrote: > >> Hi there, >> >> There is an update to this problem. As explained by @mosic in the >> elixir-forum ( >> https://elixirforum.com/t/strange-behavio-u-r-in-my-tests/939/5), the >> timings improve a lot if the prebaked_response module attribute is replaced >> by a context property set by a setup callback. >> >> It is very counterintuitive as I explain in this thread of the >> elixir-forum as module attributes are supposed to be set once at compile >> time. Doing the same in a setup callback means the load is moved from >> compile time to runtime and the JSON file will be read as many times as >> there are tests in the test case. >> >> After applying @mosic's patch, I observed the same significant >> improvement of the test timings. >> >> @mosic and I would really like to understand why. >> >> Le lundi 27 juin 2016 17:27:36 UTC+2, Sébastien Varlet a écrit : >>> >>> 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]> >>>> 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/0aae05f1-087e-4176-bba9-6d64eab9ebff%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
