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.
For more options, visit https://groups.google.com/d/optout.
