Skip to content
This repository has been archived by the owner on Mar 27, 2023. It is now read-only.

Extend time until timeout in production #58

Closed
wants to merge 2 commits into from
Closed

Conversation

Baschdl
Copy link
Contributor

@Baschdl Baschdl commented Jun 23, 2020

Some changes orthogonal to our code (didn't we freeze all necessary package versions?) cause load times of more than 30 seconds for the first request (at least on my machine) and therefore cause the gunicorn worker to timeout.

Should fixes timeouts in #49 and possibly also error 500 in #21

Copy link
Contributor

@maltezacharias maltezacharias left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As per https://docs.gunicorn.org/en/stable/settings.html#timeout:

Generally set to thirty seconds. Only set this noticeably higher if you’re sure of the repercussions for sync workers. For the non sync workers it just means that the worker process is still communicating and is not tied to the length of time required to handle a single request.

I did some reading up on the different worker_classes and found this:

For full greenlet support applications might need to be adapted. When using, e.g., Gevent and Psycopg it makes sense to ensure psycogreen is installed and setup.

https://docs.gunicorn.org/en/stable/design.html

I think with async workers normally you shouldn't see a timeout happening here, have we implemented the above or is it possible that our DB calls are still synchronous? At least in requirements we have no psycogreen (yet?)

@Baschdl
Copy link
Contributor Author

Baschdl commented Jun 30, 2020

I added psycogreen with the setup on https://github.com/match4everyone/match4everything/tree/longer_timeouts-psycogreen

TODO:

  • Do we need the setup for asgi and wsgi?
  •  I get an maybe unrelated socket.gaierror: [Errno -2] Name or service not known error
  • @bjrne isort and black are fighting

@bjrne
Copy link
Member

bjrne commented Jun 30, 2020

As before, this should easily be resolved by adding the dependency to .isort.cfg .If that does not fix it, ping me again :)

@Baschdl
Copy link
Contributor Author

Baschdl commented Jul 1, 2020

https://github.com/match4everyone/match4everything/tree/longer_timeouts-psycogreen starts for me. I can't get explain the socket.gaierror: [Errno -2] Name or service not known error but it's gone for me now. Did someone else witness it?

@maltezacharias With the lower timeout, I get pairs of those again:

[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:656)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:657)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:658)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:659)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:660)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:661)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:662)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:664)
[2020-07-01 06:49:50 +0000] [23] [CRITICAL] WORKER TIMEOUT (pid:665)
[2020-07-01 06:49:50 +0000] [664] [INFO] Worker exiting (pid: 664)
[2020-07-01 06:49:50 +0000] [665] [INFO] Worker exiting (pid: 665)
[2020-07-01 06:49:50 +0000] [657] [INFO] Worker exiting (pid: 657)
[2020-07-01 06:49:50 +0000] [656] [INFO] Worker exiting (pid: 656)
[2020-07-01 06:49:50 +0000] [658] [INFO] Worker exiting (pid: 658)
[2020-07-01 06:49:50 +0000] [662] [INFO] Worker exiting (pid: 662)
[2020-07-01 06:49:50 +0000] [660] [INFO] Worker exiting (pid: 660)
[2020-07-01 06:49:51 +0000] [661] [INFO] Worker exiting (pid: 661)
[2020-07-01 06:49:51 +0000] [659] [INFO] Worker exiting (pid: 659)

@bjrne Works, thx. Is there no better way?

@maltezacharias
Copy link
Contributor

I'll try to set it low enough so I can see the same, to reproduce just start the server or is there anything else I need to do?

@Baschdl
Copy link
Contributor Author

Baschdl commented Jul 1, 2020

@maltezacharias No. You should see a lot of CPU and disk load. Maybe it only happens for me because my machine is slower than yours but the server shouldn't be faster, right?

@Baschdl
Copy link
Contributor Author

Baschdl commented Jul 1, 2020

I narrowed it down: only the first request after setting up a new database takes so long but the first one doesn't finish if we use a shorter timeout

@maltezacharias
Copy link
Contributor

So to reproduce locally:
Create a completely new container
Set timeout ridiculously low
Start it, see the errors coming in?

I'll try that locally later today

@Baschdl Baschdl mentioned this pull request Jul 1, 2020
6 tasks
@Baschdl
Copy link
Contributor Author

Baschdl commented Jul 1, 2020

Create a completely new container

Create a completely new database container

Set timeout ridiculously low

Set timeout ridiculously low on your super-duber machine 😛

@maltezacharias
Copy link
Contributor

maltezacharias commented Jul 5, 2020

@Baschdl Can you please check out the easier deploy branch and try it out without changing the timeout. Do you still get the timeout error there? If not I would like to close this and keep timeout on the default.

If you still keep the timeout error with the new branch I will accept this change.

I just ran a completely fresh build with the easier deploy branch with a timeout set to 5 and didn't see any timeouts in the log:

➜  match4everything git:(easier-deploy) ✗ docker-compose -f docker-compose.yml -f docker-compose.prod.yml up --build
[...]
Creating match4everything_database_1 ... done
Creating match4everything_backend_1  ... done
Attaching to match4everything_database_1, match4everything_backend_1
backend_1   | Running in production mode, waiting for database to come up
database_1  | The files belonging to this database system will be owned by user "postgres".
database_1  | This user must also own the server process.
database_1  | 
database_1  | The database cluster will be initialized with locale "en_US.utf8".
database_1  | The default database encoding has accordingly been set to "UTF8".
database_1  | The default text search configuration will be set to "english".
database_1  | 
database_1  | Data page checksums are disabled.
database_1  | 
database_1  | fixing permissions on existing directory /var/lib/postgresql/data ... ok
database_1  | creating subdirectories ... ok
database_1  | selecting dynamic shared memory implementation ... posix
database_1  | selecting default max_connections ... 100
database_1  | selecting default shared_buffers ... 128MB
database_1  | selecting default time zone ... Etc/UTC
database_1  | creating configuration files ... ok
database_1  | running bootstrap script ... ok
database_1  | performing post-bootstrap initialization ... ok
database_1  | syncing data to disk ... initdb: warning: enabling "trust" authentication for local connections
database_1  | You can change this by editing pg_hba.conf or using the option -A, or
database_1  | --auth-local and --auth-host, the next time you run initdb.
database_1  | ok
database_1  | 
database_1  | 
database_1  | Success. You can now start the database server using:
database_1  | 
database_1  |     pg_ctl -D /var/lib/postgresql/data -l logfile start
database_1  | 
database_1  | waiting for server to start....2020-07-05 01:38:05.841 UTC [46] LOG:  starting PostgreSQL 12.3 (Debian 12.3-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
database_1  | 2020-07-05 01:38:05.844 UTC [46] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
database_1  | 2020-07-05 01:38:05.896 UTC [47] LOG:  database system was shut down at 2020-07-05 01:38:05 UTC
database_1  | 2020-07-05 01:38:05.905 UTC [46] LOG:  database system is ready to accept connections
database_1  |  done
database_1  | server started
database_1  | CREATE DATABASE
database_1  | 
database_1  | 
database_1  | /usr/local/bin/docker-entrypoint.sh: sourcing /docker-entrypoint-initdb.d/init-db.sh
database_1  | ALTER ROLE
database_1  | ALTER ROLE
database_1  | ALTER ROLE
database_1  | 
database_1  | waiting for server to shut down...2020-07-05 01:38:06.150 UTC [46] LOG:  received fast shutdown request
database_1  | .2020-07-05 01:38:06.154 UTC [46] LOG:  aborting any active transactions
database_1  | 2020-07-05 01:38:06.155 UTC [46] LOG:  background worker "logical replication launcher" (PID 53) exited with exit code 1
database_1  | 2020-07-05 01:38:06.156 UTC [48] LOG:  shutting down
database_1  | 2020-07-05 01:38:06.185 UTC [46] LOG:  database system is shut down
database_1  |  done
database_1  | server stopped
database_1  | 
database_1  | PostgreSQL init process complete; ready for start up.
database_1  | 
database_1  | 2020-07-05 01:38:06.264 UTC [1] LOG:  starting PostgreSQL 12.3 (Debian 12.3-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
database_1  | 2020-07-05 01:38:06.264 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
database_1  | 2020-07-05 01:38:06.264 UTC [1] LOG:  listening on IPv6 address "::", port 5432
database_1  | 2020-07-05 01:38:06.269 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
database_1  | 2020-07-05 01:38:06.319 UTC [73] LOG:  database system was shut down at 2020-07-05 01:38:06 UTC
database_1  | 2020-07-05 01:38:06.325 UTC [1] LOG:  database system is ready to accept connections
backend_1   | Waiting for database...... OK
backend_1   | PYTHONPATH: /backend
backend_1   | Operations to perform:
backend_1   |   Apply all migrations: admin, auth, cms, contenttypes, djangocms_file, djangocms_link, djangocms_picture, djangocms_snippet, djangocms_style, djangocms_text_ckeditor, djangocms_video, easy_thumbnails, filer, matching, menus, sessions, sites
backend_1   | Running migrations:
backend_1   |   Applying contenttypes.0001_initial... OK
backend_1   |   Applying contenttypes.0002_remove_content_type_name... OK
backend_1   |   Applying auth.0001_initial... OK
backend_1   |   Applying auth.0002_alter_permission_name_max_length... OK
backend_1   |   Applying auth.0003_alter_user_email_max_length... OK
backend_1   |   Applying auth.0004_alter_user_username_opts... OK
backend_1   |   Applying auth.0005_alter_user_last_login_null... OK
backend_1   |   Applying auth.0006_require_contenttypes_0002... OK
backend_1   |   Applying auth.0007_alter_validators_add_error_messages... OK
backend_1   |   Applying auth.0008_alter_user_username_max_length... OK
backend_1   |   Applying auth.0009_alter_user_last_name_max_length... OK
backend_1   |   Applying auth.0010_alter_group_name_max_length... OK
backend_1   |   Applying auth.0011_update_proxy_permissions... OK
backend_1   |   Applying matching.0001_initial... OK
backend_1   |   Applying admin.0001_initial... OK
backend_1   |   Applying admin.0002_logentry_remove_auto_add... OK
backend_1   |   Applying admin.0003_logentry_add_action_flag_choices... OK
backend_1   |   Applying sites.0001_initial... OK
backend_1   |   Applying cms.0001_initial... OK
backend_1   |   Applying cms.0002_auto_20140816_1918... OK
backend_1   |   Applying cms.0003_auto_20140926_2347... OK
backend_1   |   Applying cms.0004_auto_20140924_1038... OK
backend_1   |   Applying cms.0005_auto_20140924_1039... OK
backend_1   |   Applying cms.0006_auto_20140924_1110... OK
backend_1   |   Applying cms.0007_auto_20141028_1559... OK
backend_1   |   Applying cms.0008_auto_20150208_2149... OK
backend_1   |   Applying cms.0008_auto_20150121_0059... OK
backend_1   |   Applying cms.0009_merge... OK
backend_1   |   Applying cms.0010_migrate_use_structure... OK
backend_1   |   Applying cms.0011_auto_20150419_1006... OK
backend_1   |   Applying cms.0012_auto_20150607_2207... OK
backend_1   |   Applying cms.0013_urlconfrevision... OK
backend_1   |   Applying cms.0014_auto_20160404_1908... OK
backend_1   |   Applying cms.0015_auto_20160421_0000... OK
backend_1   |   Applying cms.0016_auto_20160608_1535... OK
backend_1   |   Applying cms.0017_pagetype... OK
backend_1   |   Applying cms.0018_create_pagenode... OK
backend_1   |   Applying cms.0019_set_pagenode... OK
backend_1   |   Applying cms.0020_old_tree_cleanup... OK
backend_1   |   Applying cms.0021_auto_20180507_1432... OK
backend_1   |   Applying cms.0022_auto_20180620_1551... OK
backend_1   |   Applying filer.0001_initial... OK
backend_1   |   Applying filer.0002_auto_20150606_2003... OK
backend_1   |   Applying filer.0003_thumbnailoption... OK
backend_1   |   Applying filer.0004_auto_20160328_1434... OK
backend_1   |   Applying filer.0005_auto_20160623_1425... OK
backend_1   |   Applying filer.0006_auto_20160623_1627... OK
backend_1   |   Applying djangocms_file.0001_initial... OK
backend_1   |   Applying djangocms_file.0002_auto_20151202_1551... OK
backend_1   |   Applying djangocms_file.0003_remove_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_file.0004_set_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_file.0005_auto_20160119_1534... OK
backend_1   |   Applying djangocms_file.0006_migrate_to_filer... OK
backend_1   |   Applying djangocms_file.0007_adapted_fields... OK
backend_1   |   Applying djangocms_file.0008_add_folder... OK
backend_1   |   Applying djangocms_file.0009_fixed_null_fields... OK
backend_1   |   Applying djangocms_file.0010_removed_null_fields... OK
backend_1   |   Applying djangocms_file.0011_auto_20181211_0357... OK
backend_1   |   Applying filer.0007_auto_20161016_1055... OK
backend_1   |   Applying filer.0008_auto_20171117_1313... OK
backend_1   |   Applying filer.0009_auto_20171220_1635... OK
backend_1   |   Applying filer.0010_auto_20180414_2058... OK
backend_1   |   Applying filer.0011_auto_20190418_0137... OK
backend_1   |   Applying djangocms_link.0001_initial... OK
backend_1   |   Applying djangocms_link.0002_auto_20140929_1705... OK
backend_1   |   Applying djangocms_link.0003_auto_20150212_1310... OK
backend_1   |   Applying djangocms_link.0004_auto_20150708_1133... OK
backend_1   |   Applying djangocms_link.0005_auto_20151003_1710... OK
backend_1   |   Applying djangocms_link.0006_remove_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_link.0007_set_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_link.0008_link_attributes... OK
backend_1   |   Applying djangocms_link.0009_auto_20160705_1344... OK
backend_1   |   Applying djangocms_link.0010_adapted_fields... OK
backend_1   |   Applying djangocms_link.0011_fixed_null_values... OK
backend_1   |   Applying djangocms_link.0012_removed_null... OK
backend_1   |   Applying djangocms_link.0013_fix_hostname... OK
backend_1   |   Applying djangocms_link.0014_link_file_link... OK
backend_1   |   Applying djangocms_link.0015_auto_20190621_0407... OK
backend_1   |   Applying djangocms_picture.0001_initial... OK
backend_1   |   Applying djangocms_picture.0002_auto_20151018_1927... OK
backend_1   |   Applying djangocms_picture.0003_migrate_to_filer... OK
backend_1   |   Applying djangocms_picture.0004_adapt_fields... OK
backend_1   |   Applying djangocms_picture.0005_reset_null_values... OK
backend_1   |   Applying djangocms_picture.0006_remove_null_values... OK
backend_1   |   Applying djangocms_picture.0007_fix_alignment... OK
backend_1   |   Applying djangocms_picture.0008_picture_use_responsive_image... OK
backend_1   |   Applying djangocms_picture.0009_auto_20181212_1003... OK
backend_1   |   Applying djangocms_picture.0010_auto_20190627_0432... OK
backend_1   |   Applying djangocms_picture.0011_auto_20190314_1536... OK
backend_1   |   Applying djangocms_snippet.0001_initial... OK
backend_1   |   Applying djangocms_snippet.0002_snippet_slug... OK
backend_1   |   Applying djangocms_snippet.0003_auto_data_fill_slug... OK
backend_1   |   Applying djangocms_snippet.0004_auto_alter_slug_unique... OK
backend_1   |   Applying djangocms_snippet.0005_set_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_snippet.0006_auto_20160831_0729... OK
backend_1   |   Applying djangocms_snippet.0007_auto_alter_template_helptext... OK
backend_1   |   Applying djangocms_snippet.0008_auto_change_name... OK
backend_1   |   Applying djangocms_style.0001_initial... OK
backend_1   |   Applying djangocms_style.0002_set_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_style.0003_adapted_fields... OK
backend_1   |   Applying djangocms_style.0004_use_positive_small_integer_field... OK
backend_1   |   Applying djangocms_style.0005_reset_null_values... OK
backend_1   |   Applying djangocms_style.0006_removed_null_fields... OK
backend_1   |   Applying djangocms_style.0007_style_template... OK
backend_1   |   Applying djangocms_text_ckeditor.0001_initial... OK
backend_1   |   Applying djangocms_text_ckeditor.0002_remove_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_text_ckeditor.0003_set_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_text_ckeditor.0004_auto_20160706_1339... OK
backend_1   |   Applying djangocms_video.0001_initial... OK
backend_1   |   Applying djangocms_video.0002_set_related_name_for_cmsplugin_ptr... OK
backend_1   |   Applying djangocms_video.0003_field_adaptions... OK
backend_1   |   Applying djangocms_video.0004_move_to_attributes... OK
backend_1   |   Applying djangocms_video.0005_migrate_to_filer... OK
backend_1   |   Applying djangocms_video.0006_field_adaptions... OK
backend_1   |   Applying djangocms_video.0007_create_nested_plugin... OK
backend_1   |   Applying djangocms_video.0008_reset_null_values... OK
backend_1   |   Applying djangocms_video.0009_removed_null_values... OK
backend_1   |   Applying djangocms_video.0010_videoplayer_parameters... OK
backend_1   |   Applying easy_thumbnails.0001_initial... OK
backend_1   |   Applying easy_thumbnails.0002_thumbnaildimensions... OK
backend_1   |   Applying matching.0002_permission_group_creation... OK
backend_1   |   Applying menus.0001_initial... OK
backend_1   |   Applying sessions.0001_initial... OK
backend_1   |   Applying sites.0002_alter_domain_unique... OK
backend_1   | System check identified no issues (0 silenced).
backend_1   | [2020-07-05 01:38:21 +0000] [1] [INFO] Starting gunicorn 20.0.4
backend_1   | [2020-07-05 01:38:21 +0000] [1] [INFO] Listening at: http://172.20.0.3:8000 (1)
backend_1   | [2020-07-05 01:38:21 +0000] [1] [INFO] Using worker: gevent
backend_1   | [2020-07-05 01:38:21 +0000] [36] [INFO] Booting worker with pid: 36
backend_1   | [2020-07-05 01:38:21 +0000] [37] [INFO] Booting worker with pid: 37
backend_1   | [2020-07-05 01:38:21 +0000] [39] [INFO] Booting worker with pid: 39
backend_1   | [2020-07-05 01:38:21 +0000] [40] [INFO] Booting worker with pid: 40
backend_1   | [2020-07-05 01:38:22 +0000] [42] [INFO] Booting worker with pid: 42
backend_1   | [2020-07-05 01:38:22 +0000] [43] [INFO] Booting worker with pid: 43
backend_1   | [2020-07-05 01:38:22 +0000] [45] [INFO] Booting worker with pid: 45
backend_1   | [2020-07-05 01:38:22 +0000] [47] [INFO] Booting worker with pid: 47
backend_1   | [2020-07-05 01:38:22 +0000] [48] [INFO] Booting worker with pid: 48
^CGracefully stopping... (press Ctrl+C again to force)
Stopping match4everything_backend_1  ... done
Stopping match4everything_database_1 ... done

EDIT: And yes, I opened up the site after that and clicked on a few links. Before this test the old docker volumes were deleted, so everything was created from scratch

@Baschdl
Copy link
Contributor Author

Baschdl commented Jul 7, 2020

@maltezacharias It seems to work with easier-deploy. Shouldn't we still use psycogreen?

@Baschdl Baschdl mentioned this pull request Jul 8, 2020
@Baschdl
Copy link
Contributor Author

Baschdl commented Jul 8, 2020

Opened #98 for psycogreen

@Baschdl Baschdl closed this Jul 8, 2020
@maltezacharias maltezacharias deleted the longer_timeouts branch July 8, 2020 23:32
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants