Test phoenix page with wrk and crashes Phoenix.CodeReloader.Server

Phoenix Forum Questions / Help
,
1

Hi, I installed wrk and test my application which uses a simple liveview and database Postgres. I sent a basic request like this:

wrk -t12 -c400 -d30s http://localhost:4000/

And I got this error:

exited in: GenServer.call(Phoenix.CodeReloader.Server, {:reload!, MishkaHtmlWeb.Endpoint}, :infinity) ** (EXIT) no process: the process is not alive or there’s no process currently associated with the given name, possibly because its application isn’t started

Result

1 ❯ wrk -t12 -c400 -d30s http://localhost:4000/
Running 30s test @ http://localhost:4000/
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   824.82ms  222.74ms   2.00s    70.99%
    Req/Sec    43.40     42.10   280.00     82.20%
  6643 requests in 30.05s, 129.67MB read
  Socket errors: connect 157, read 22637, write 0, timeout 107
  Non-2xx or 3xx responses: 4374
Requests/sec:    221.06
Transfer/sec:      4.32MB

When I disable code_reloader

[error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/Desktop/mishka-cms/_build/dev/lib/sourceror/ebin/Elixir.MishkaInstaller.Database.DependencySchema.beam. Function: get_file. Process: code_server.']

OR

[error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/Desktop/mishka-cms/_build/dev/lib/certifi/ebin/Elixir.Oban.beam. Function: get_file. Process: code_server.']

And many another errors, but system is back after crash

ir.Logger'}
Logger - error: {rLeomgogveed_failri n-g _ehrarnord:l er,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.LoLgogger - geerrr'or: }
{removed_failing_hLaogger -n delrerro,r':E lixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
Logger - error: Logg{err e- meoved_fairlrionrg:_ handler,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
Logger - error: {rLeomogved_failignegr_ h-a nedrlreorr,:' Elixir.Logger'}
{removed_failinLgo_ghgaenrd l-e re,rr'oErl:i xir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failingLogg_erha n-d leerrro,r':E lixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {Lroegmgoevre d-_ fearirloirn:g _handler,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {removed_failing_handler,'Elixir.Logger'}
Logger - error: {Lroegmgoevre d-_ fearirloing_handlerr:, 'Elixir.Logger'}
gremoved_failing_handler,'Elixir.Logger'L}o
 ger - error: {removedL_ofgagielri n-g _ehrarnodrl:e r,'Elixir.Logger'}
rremoved_failing_handler,'Elixir.LoggLeorg'g}e
  - error: {removeLdo_gfgaeilri n-g _ehrarnodrl:e r,'Elixir.Logger'}
 removed_failing_handler,'Elixir.LLooggggeerr' }-
 error: {removed_failing_handlLeorg,g'eErl i-x ierr.rLoorg:g er'}
rremoved_failing_handler,'ElixirL.oLgoggegre r-' }e
 ror: {removed_failing_haLnodglgeerr, '-E leirxriorr.:L ogger'}
 removed_failing_handler,'Elixir.LogLgoegrg'e}r
 - error: {removedLogger_ -f aeirlrionrg:_ handler,'Elixir.Logger'}
eremoved_Lfoagigleirn g-_ hearnrdler,'Elixor: ir.LoggeLro'g}g
rr - error:{ removed_failing_handler,L'oElixir.Loggerg'g}e
  - erro{remorv:e d_failing_handler,'Elixir.Logger'}
rLroegmgoevre d-_ fearirloirn:g _handler,'Elixir.LoggLeorg'g}e
  - error{: removed_failing_hanLdolgegre,r' E-l iexrirro.rL:o gger'}
-removed_failing_handler,'Elixir.LoLgoggegre'r}
  error: {removed_failing_haLnodglgeerr, '-E leirxroirr:. Logger'}
{removed_failingL_ohgagnedrl e-r ,e'rErloirx:i r.Logger'}
{removed_failing_handler,'Elixir.Logger'}
 removed_fLaoiglgienrg _-h aenrdrloerr:, 'Elixir.LLooggggeerr' }-
 error: {removed_failing_hanLogdgleerr ,- 'eErlrioxri:r .Logger'}
{removed_failing_handler,'Elixir.Logger'}
L{orgegmeorv e-d _efrariolr: inLgo_ghgaenrd l-e re,r'rEolri:x ir.Logger'}
{removed_Lfoagigleirn g-_ hearnrdolre:r ,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
L{ogrgeemro v-e de_rfraoirl:i ng_handlLeorg,g'eErl i-x ierr.rLoorg:g er'}
{removed_failing_handlerL,o'gEgleirx i-r .eLrorgogre:r '}
{removed_failing_handler,'Elixir.Logger'}
:removed_failing_hLaongdgleerr ,-' Eelrirxoirr:. LoLogger -g geerrr'o}r
  {removed_failing_handler,Lo'gger E-l iexrirro.rL:o gger'}
{removed_failing_handler,'LogEgleirx i-r .eLrorgogre:r '}
{removed_failing_handler,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
 ogger - error: {removed_failiLnogg_ghearn d-l eerr,r'oErl:i xir.LogLgoegrg'e}r
 - error: {Loremgogveerd _-f aeirlrionrg:_ handler,'Elixir.Logger'}
-remoLvoegdg_efra i-l ienrgr_ohra:n dler,'Elixir.LoLgoggegre'r}
o error: {removed_failing_handler,'ElixLiorg.gLeorg g-e re'r}r
 r: {removed_failing_Lhoagngdelre r-, 'eErlrioxri:r .Logger'}
{removed_failing_handlLeorg,g'eErl i-x ierr.rLoorg:g er'}
{removed_failing_handler,'ElixLioggerr .-L oegrgreor'}
r:{ removed_failing_handler,'Elixir.Logger'}
rremoved_failing_handler,'EliLxoigrg.eLro g-g eerr'r}o
 : {removed_failing_handlerL,o'gEgleirx i-r .eLrorgogre:r '}
{removed_failingLogger_ h-a nedrlreorr,: 'Elixir.LLogger o- error: gger'}
{removed_failing_handler,'Elixir.Logger'}
{removed_failing_handler,L'oEglgiexri r-. Leorgrgoerr:' }
eremoved_failing_handler,'Elixir.LoggeLro'g}g
 r - error: {Lroegmgoevre d-_ ferror: ailing_handler,'Elixir.Logger'}
{removed_failing_handler,'LEolgigxeirr .-L oegrgreorr':}
{removed_failingL_ohgagnedrl e-r ,e'rrEor: lLogigxeirr .-L oegrgreorr':}
{removed_faiLolgignegr_ h-a nedrlreorr,:' Elixir.Logger'}
{removed_failing_handler,'LEolgigxeirr .-L oegrgreorr':}
{removed_failLionggg_ehra n-d errorl:er,'El ixir.Logger'}
{removed_failing_Lhoagngdelre r-, 'eErlror: ixir.Logger'}
rremoved_failing_handler,'EliLxoigrg.eLro g-g eerr'r}o
 : {removed_failing_handler,'Elixir.Logger'}
{removed_failiLnogg_ghearn d-l eerr,r'Elixir.Logogerr:' }
 o{removedg_gfeari l-i negr_rhoarn:d ler,'Elixir.LogLgoegrg'e}r
 - e{rrreomro:v ed_failLionggg_ehra n-d lerror: er,'Elixir.Logger'}
{removed_failing_hLaongdgleerr ,-' Eelrirxoirr:. Logger'}
{removed_failing_handler,L'oEglgiexri r-. Leorgrgoerr:' }
 removed_failing_handler,'ELloigxgierr. L-o gegrerro'r}:
r{removed_failing_handler,'EliLxoigrg.eLro g-g eerr'r}o
 : {removed_failing_handleLro,g'gEelri x-i re.rLroogrg:e r'}
{rLeomgogveerd _-f aeirlrionrg:_ handler,'Elixir.Logger'}
{removed_failing_haLnodglgeerr, '-E leirxriorr.:L ogger'}
{removed_failing_handler,L'oEglgiexri r-. Leorgrgoerr:' }
{removed_failLionggg_ehra n-d leerrr,o'rE:l ixir.Logger'}
{removed_failiLnogg_ghearn d-l eerr,ro'rE:l ixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
{reLmoogvgeedr_ f-a ielrirnogr_:h andler,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
{removed_failing_handler,'Elixir.Logger'}
=ERROR REPORT==== 30-Jun-2022::00:21:57.830977 ===
{error,simple_handler_process_dead}
=DEBUG REPORT==== 30-Jun-2022::00:21:57.830959 ===
    logger: removed_failing_handler
    handler: {'Elixir.Logger','Elixir.Logger.Handler'}
    log_event: #{level => debug,
                 meta =>
                     #{file => "logger_backend.erl",gl => <0.0.0>,
                       internal_log_event => true,line => 71,
                       mfa => {logger_backend,call_handlers,3},
                       pid => <0.42.0>,time => 1656532278766785},
                 msg =>
                     {report,
                         [{logger,remove_handler_failed},
                          {reason,
                              {attempting_syncronous_call_to_self,
                                  {remove_handler,'Elixir.Logger'}}}]}}
    config: #{config =>
                  #{counter => {atomics,#Ref<0.195498935.3989176323.141648>},
                    sasl => false,
                    thresholds => {20,500},
                    translators =>
                        [{'Elixir.Plug.Cowboy.Translator',translate},
                         {'Elixir.Logger.Translator',translate}],
                    truncate => 8096,utc_log => false},
              formatter => {logger_formatter,#{}},
              id => 'Elixir.Logger',module => 'Elixir.Logger.Handler'}
    reason: {error,undef,
             [{'Elixir.ErlangError',normalize,
               [undef,
                [{'Elixir.Plug.Cowboy.Translator',translate,
                  [debug,debug,report,
                   {logger,
                    [{logger,remove_handler_failed},
                     {reason,
                      {attempting_syncronous_call_to_self,
                       {remove_handler,'Elixir.Logger'}}}]}],
                  []},
                 {'Elixir.Logger.Handler',do_translate,6,
                  [{file,"lib/logger/handler.ex"},{line,227}]},
                 {'Elixir.Logger.Handler',do_log,4,
                  [{file,"lib/logger/handler.ex"},{line,129}]},
                 {'Elixir.Logger.Handler',log,2,
                  [{file,"lib/logger/handler.ex"},{line,84}]},
                 {logger_backend,call_handlers,3,
                  [{file,"logger_backend.erl"},{line,51}]}]],
               []},
              {'Elixir.Logger.Handler',do_log,4,
               [{file,"lib/logger/handler.ex"},{line,135}]},
              {'Elixir.Logger.Handler',log,2,
               [{file,"lib/logger/handler.ex"},{line,84}]}]}

But I think I can’t access to terminal because when I reload page as developer it works but I can’t see anything in my terminal

It should be noted I am in developer mode

Update in production mode, but in developer enviroment with asdf no docker test

❯ wrk -t3 -c200 -d5s http://localhost:4000/
Running 5s test @ http://localhost:4000/
  3 threads and 200 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   247.60ms   63.94ms 446.92ms   66.52%
    Req/Sec   252.73     84.91   540.00     74.00%
  3781 requests in 5.01s, 215.40MB read
  Socket errors: connect 0, read 131, write 0, timeout 0
Requests/sec:    753.94
Transfer/sec:     42.95MB

The errors:

00:32:39.424 [info] Postgrex.Protocol (#PID<0.11126.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.15842.0> exited

00:32:39.249 [error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/.asdf/installs/erlang/25.0.2/lib/ssh-4.14.1/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server.']
00:32:39.251 [error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/.asdf/installs/erlang/25.0.2/lib/snmp-5.13/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server.']
00:32:39.258 [error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/.asdf/installs/erlang/25.0.2/lib/sasl-4.2/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server.']
00:32:39.260 [error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/.asdf/installs/erlang/25.0.2/lib/runtime_tools-1.19/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server.']
00:32:39.267 [error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/.asdf/installs/erlang/25.0.2/lib/reltool-0.9/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server.']
00:32:39.281 [error] [label: {:erl_prim_loader, :file_error}, report: 'File operation error: emfile. Target: /Users/shahryar/.asdf/installs/erlang/25.0.2/lib/public_key-1.13/ebin/Elixir.Logger.Translator.beam. Function: get_file. Process: code_server.']

If I test with one thread I see a warning like this:

00:35:46.177 request_id=Fv0wHqiYgac8c_sABb8n [info] GET /
00:35:46.177 request_id=Fv0wHptBlxGuorIAB-4l [info] Sent 200 in 223ms
00:35:46.178 [warning] Ranch acceptor reducing accept rate: out of file descriptors
# and ----
00:35:46.213 [info] Postgrex.Protocol (#PID<0.11129.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.24908.0> exited
00:35:46.213 [info] Postgrex.Protocol (#PID<0.11124.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.24905.0> exited
00:35:46.215 [info] Postgrex.Protocol (#PID<0.11120.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.24938.0> exited
2

I don’t think you’ll get any useful information from testing your app in :dev build. For the :prod build, it seems you’ve drained your DB connection pool.

2 Likes
3

Yeah, you are right, but I put it here to know how the other developer test concurrent users test in their local.
I want to test my API and HTML pages.

Could you explain a bit about it please, I add pool_size: 10 in my config, did you mean that?

4

Yes, I had that config in mind. That option means that you can have up to 10 concurrent DB operations. Next ones will queue up and timeout after a specific time.

1 Like
5

I don’t know queue_target can help me in this test or not, for now I want to fix based on my code if phoenix has any option for it. For example, store some data in ram!! As ETS or Genserver is not my plan for now.

I think it is very disappointment, my site is broken with just 1599 requests in 30.06s, 63.99MB read

I do not know the queue_target: 50000 option can help me or not!!

My VPS config:

4 GB RAM
3 vCPU Shared
80 GB SSD

I am dropped just with 53 concurrent requests!! :smiling_face_with_tear:, Postgres can’t Handel just 53 request, or I have another problem in my side

6

Seems you are running out of file descriptors. Set a higher number using eg ulimit -n

7

Hmm, I did not code for a file in my home page, it is a LiveView

Where can I set ulimit -n ?

8

I didn’t mean that your app was opening too many files. On *nix systems sockets are files. The issue here is that ranch (thus cowboy thus phoenix) opens more connections (files) than you are allowed to open. (*nix systems have limits on how many files/sockets a process can open.). Calling ulimit -n in your terminal will show you the current limit, calling eg ulimit -n 1024 will set the limit for the current and child processes.
Thus you may try to issue that command in the terminal from which you call phx.server.
Side note, it’s not a great test, since you shouldn’t run the test code from the same system that’s under test.

1 Like
9

Quick addition to my previous answer. If you want to stress test a system, be sure to check with your provider that it’s ok!

1 Like
10

Yeah, I will test it with full production mod in my server, thank you for your advice, but I still have problem with Postgres

11

If you have issue with Postgres, please share. You should be able to handle quite a few connections.

12

Hi Dear @krstfk, I shared it on top post

Please see this comment Test phoenix page with wrk and crashes Phoenix.CodeReloader.Server

00:35:46.213 [info] Postgrex.Protocol (#PID<0.11129.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.24908.0> exited
00:35:46.213 [info] Postgrex.Protocol (#PID<0.11124.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.24905.0> exited
00:35:46.215 [info] Postgrex.Protocol (#PID<0.11120.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.24938.0> exited
13

Does it still happen when you increase the fd limit? If so, have you tried increasing the pool size?

1 Like
14

The another errors I reported in the previous comment were fixed with your help. But at the end of the wrk test, I can see these errors:

10:59:21.522 [info] Postgrex.Protocol (#PID<0.11129.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4738.1> exited
10:59:21.522 request_id=Fv2gupaYPBGGmZoAC_8E [info] Sent 200 in 328ms
10:59:21.522 [info] Postgrex.Protocol (#PID<0.11133.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4797.1> exited
10:59:21.523 [info] Postgrex.Protocol (#PID<0.11131.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4762.1> exited
10:59:21.524 request_id=Fv2gupkCvVL65u0ADAOE [info] Sent 200 in 291ms
10:59:21.524 [info] Postgrex.Protocol (#PID<0.11127.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4793.1> exited
10:59:21.525 [info] Postgrex.Protocol (#PID<0.11126.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4803.1> exited
10:59:21.525 [info] Postgrex.Protocol (#PID<0.11135.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4747.1> exited
10:59:21.526 [info] Postgrex.Protocol (#PID<0.11128.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4760.1> exited
10:59:21.526 request_id=Fv2gupniOnGvTHoACjVH [info] Sent 200 in 278ms
10:59:21.528 [info] Postgrex.Protocol (#PID<0.11132.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4807.1> exited

Yes, I increased it to 30 and got less error, but the whole requests were, just 22583 which is 750.27 Requests/ per sec. And I am wondering when I have more than this counted-request every time I should increase this pool_size?! . I expected not to have this problem, at least 3500 Requests/ per sec.
Do you have a suggestion for it?

config :mishka_database, MishkaDatabase.Repo,
  database: System.get_env("DATABASE_NAME") || "mishka_test",
  username: System.get_env("DATABASE_USER") || "postgres",
  password: System.get_env("DATABASE_PASSWORD") || "postgres",
  hostname: System.get_env("DATABASE_HOST") || "localhost",
  pool_size: 30,
  show_sensitive_data_on_connection_error: true

I tested it:

4.2 GHz Quad-Core Intel Core i7
32 GB 2400 MHz DDR4

❯ wrk -t12 -c400 -d30s http://localhost:4000/
Running 30s test @ http://localhost:4000/
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   316.66ms   69.38ms 583.32ms   77.31%
    Req/Sec    71.24     51.48   330.00     74.59%
  22583 requests in 30.10s, 1.26GB read
  Socket errors: connect 157, read 79, write 0, timeout 0
Requests/sec:    750.27
Transfer/sec:     42.74MB

Thank you in advance

15

Please remember that running the perf test locally is not really that useful unless you intend to run your app in exact same setup on production. You should run the tests on a replica of production to get a real understanding of the bottlenecks.

1 Like
16

Thank you for the advice, yes sure, but it takes 3 or 4 months to be deployed on server (mishka-cms), just for learning I wanted to try figuring out why my Postgres is discounted in my local.