Redmine very slow on first page load after some time of inactivity

user_4420878 0
Viewed 234

Every morning, the first person that tries to access Redmine at my work is waiting almost one minute for redmine to load the page. After that, the rest of the team have no problem and almost every page are loading in less than 200ms.

Here is the log between the last "good" loading and the first "bad" loading of this morning:

App 103 output: I, [2021-04-16T00:19:24.965247 #103]  INFO -- : Completed 200 OK in 829ms (Views: 553.2ms | ActiveRecord: 1.8ms)
App 103 output: I, [2021-04-16T03:09:12.511395 #103]  INFO -- : Started GET "/login?back_url=https%3A%2F%2Fmyapp.com%2F" for WWW.XXX.YYY.ZZZ at 2021-04-16 03:09:12 +0000
App 103 output: I, [2021-04-16T03:09:12.532015 #103]  INFO -- : Processing by AccountController#login as HTML
App 103 output: I, [2021-04-16T03:09:12.532084 #103]  INFO -- :   Parameters: {"back_url"=>"https://myapp.com/"}
App 103 output: I, [2021-04-16T03:09:12.694146 #103]  INFO -- : Redirected to https://myapp.com/login?back_url=https%3A%2F%2Fmyapp.com%2Flogin%3Fback_url%3Dhttps%253A%252F%252Fmyapp.com%252F
App 103 output: I, [2021-04-16T03:09:12.694280 #103]  INFO -- : Filter chain halted as :session_expiration rendered or redirected
App 103 output: I, [2021-04-16T03:09:12.694473 #103]  INFO -- : Completed 302 Found in 162ms (ActiveRecord: 2.7ms)
App 103 output: I, [2021-04-16T03:09:13.201746 #103]  INFO -- : Started GET "/login?back_url=https%3A%2F%2Fmyapp.com%2Flogin%3Fback_url%3Dhttps%253A%252F%252Fmyapp.com%252F" for WWW.XXX.YYY.ZZZ at 2021-04-16 03:09:13 +0000
App 103 output: I, [2021-04-16T03:09:13.205997 #103]  INFO -- : Processing by AccountController#login as HTML
App 103 output: I, [2021-04-16T03:09:13.206088 #103]  INFO -- :   Parameters: {"back_url"=>"https://myapp.com/login?back_url=https%3A%2F%2Fmyapp.com%2F"}
App 103 output: I, [2021-04-16T03:09:13.283815 #103]  INFO -- :   Current user: anonymous
App 103 output: I, [2021-04-16T03:09:13.300562 #103]  INFO -- :   Rendering account/login.html.erb within layouts/base
App 103 output: I, [2021-04-16T03:09:13.304521 #103]  INFO -- :   Rendered account/login.html.erb within layouts/base (3.8ms)
App 103 output: I, [2021-04-16T03:09:13.526917 #103]  INFO -- : Completed 200 OK in 321ms (Views: 242.1ms | ActiveRecord: 50.2ms)
App 103 output: I, [2021-04-16T03:09:15.396901 #103]  INFO -- : Started POST "/login" for WWW.XXX.YYY.ZZZ at 2021-04-16 03:09:15 +0000
App 103 output: I, [2021-04-16T03:09:15.400666 #103]  INFO -- : Processing by AccountController#login as HTML
App 103 output: I, [2021-04-16T03:09:15.400741 #103]  INFO -- :   Parameters: {"utf8"=>"✓", "authenticity_token"=>"*********************************", "username"=>"myuser", "password"=>"[FILTERED]", "login"=>"Connexion"}
App 103 output: I, [2021-04-16T03:09:15.461825 #103]  INFO -- :   Current user: anonymous
App 103 output: I, [2021-04-16T03:09:16.117981 #103]  INFO -- : Successful authentication for 'myuser' from WWW.XXX.YYY.ZZZ at 2021-04-16 03:09:16 UTC
App 103 output: I, [2021-04-16T03:09:16.454431 #103]  INFO -- : Redirected to https://myapp.com/my/page
App 103 output: I, [2021-04-16T03:09:16.454677 #103]  INFO -- : Completed 302 Found in 1054ms (ActiveRecord: 778.5ms)
App 103 output: I, [2021-04-16T03:09:16.929227 #103]  INFO -- : Started GET "/my/page" for WWW.XXX.YYY.ZZZ at 2021-04-16 03:09:16 +0000
App 103 output: I, [2021-04-16T03:09:17.650222 #103]  INFO -- : Processing by MyController#page as HTML
App 103 output: I, [2021-04-16T03:09:18.625577 #103]  INFO -- :   Current user: myuser (id=208)
App 103 output: I, [2021-04-16T03:09:18.923542 #103]  INFO -- :   Rendering my/page.html.erb within layouts/base
App 103 output: I, [2021-04-16T03:09:35.622052 #103]  INFO -- :   Rendered queries/_columns.html.erb (509.9ms)
App 103 output: I, [2021-04-16T03:09:39.698459 #103]  INFO -- :   Rendered issues/_list.html.erb (3990.1ms)
App 103 output: I, [2021-04-16T03:09:39.736960 #103]  INFO -- :   Rendered my/blocks/_issues.erb (5549.7ms)
App 103 output: I, [2021-04-16T03:09:44.899092 #103]  INFO -- :   Rendered queries/_columns.html.erb (1643.8ms)
App 103 output: I, [2021-04-16T03:09:48.195990 #103]  INFO -- :   Rendered issues/_list.html.erb (3114.5ms)
App 103 output: I, [2021-04-16T03:09:48.238683 #103]  INFO -- :   Rendered my/blocks/_issues.erb (5564.4ms)
App 103 output: I, [2021-04-16T03:09:48.271494 #103]  INFO -- :   Rendered my/page.html.erb within layouts/base (29347.8ms)
App 103 output: I, [2021-04-16T03:10:17.568436 #103]  INFO -- : Completed 200 OK in 59918ms (Views: 57311.4ms | ActiveRecord: 2235.3ms)
App 103 output: I, [2021-04-16T03:11:32.073474 #103]  INFO -- : Started GET "/projects/myapp-v2?jump=my" for WWW.XXX.YYY.ZZZ at 2021-04-16 03:11:32 +0000
App 103 output: I, [2021-04-16T03:11:32.075240 #103]  INFO -- : Processing by ProjectsController#show as HTML
App 103 output: I, [2021-04-16T03:11:32.075285 #103]  INFO -- :   Parameters: {"jump"=>"my", "id"=>"myapp-v2"}
App 103 output: I, [2021-04-16T03:11:32.083287 #103]  INFO -- :   Current user: myuser (id=208)
App 103 output: I, [2021-04-16T03:11:34.636170 #103]  INFO -- :   Rendering projects/show.html.erb within layouts/base
App 103 output: I, [2021-04-16T03:11:36.682491 #103]  INFO -- :   Rendered projects/_members_box.html.erb (157.3ms)
App 103 output: I, [2021-04-16T03:11:36.684234 #103]  INFO -- :   Rendered projects/show.html.erb within layouts/base (2048.0ms)
App 103 output: I, [2021-04-16T03:11:37.452800 #103]  INFO -- : Completed 200 OK in 5377ms (Views: 2762.9ms | ActiveRecord: 620.0ms)

At 2021-04-16T03:10:17.568436 you can see a 200 OK response in 59918ms.

I run Remdine docker with a docker-compose file. Redmine is connecting to the host MySQL server and uses the host mail server too (no problem with that).

Here is the redmine-docker-compose.yml file content:

version: '3.1'
services:
  redmine:
    image: redmine:4.2-passenger
    user: "$UID:$GID"
    logging:
      driver: "journald"
      options:
        tag: "redmine-docker"
        mode: "non-blocking"
        max-buffer-size: "4m"
    ports:
      - 8792:3000
    environment:
      REDMINE_DB_MYSQL: 172.17.0.1
      REDMINE_DB_DATABASE: redmine
      REDMINE_DB_PORT: 3306
      REDMINE_DB_USERNAME: redmine
      REDMINE_DB_PASSWORD: ***************
      REDMINE_DB_ENCODING: utf8
      REDMINE_SECRET_KEY_BASE: *************************
    volumes:
    - ./redmine/files:/usr/src/redmine/files
    - ./redmine/themes/PurpleMine2-master:/usr/src/redmine/public/themes/PurpleMine2-master
    - ./redmine/config/configuration.yml:/usr/src/redmine/config/configuration.yml
    - ./redmine/repos:/usr/src/redmine/repos
    - ./redmine/etc/passwd:/etc/passwd:ro
    - ./redmine/usr/src/redmine/Passengerfile.json:/usr/src/redmine/Passengerfile.json
networks:
  default:
    external:
      name: br-redmine-docker

Here is the configuration.yml content:

production:
  email_delivery:
    delivery_method: :smtp
    smtp_settings:
      address: 172.17.0.1
      port: 25
      enable_starttls_auto: false

And the Passengerfile.json content:

{
  "max_pool_size": 15,
  "pool_idle_time": 60,
  "min_instances": 4
}

Note that I created the Passengerfile.json because of this exact same problem but it did not resolve it at all.

Here is the content of passwd file (it is just a copy of the file present in the docker image with one more line at the end):

root:x:0:0:root:/root:/bin/bash
daemon:x:1:1:daemon:/usr/sbin:/usr/sbin/nologin
bin:x:2:2:bin:/bin:/usr/sbin/nologin
sys:x:3:3:sys:/dev:/usr/sbin/nologin
sync:x:4:65534:sync:/bin:/bin/sync
games:x:5:60:games:/usr/games:/usr/sbin/nologin
man:x:6:12:man:/var/cache/man:/usr/sbin/nologin
lp:x:7:7:lp:/var/spool/lpd:/usr/sbin/nologin
mail:x:8:8:mail:/var/mail:/usr/sbin/nologin
news:x:9:9:news:/var/spool/news:/usr/sbin/nologin
uucp:x:10:10:uucp:/var/spool/uucp:/usr/sbin/nologin
proxy:x:13:13:proxy:/bin:/usr/sbin/nologin
www-data:x:33:33:www-data:/var/www:/usr/sbin/nologin
backup:x:34:34:backup:/var/backups:/usr/sbin/nologin
list:x:38:38:Mailing List Manager:/var/list:/usr/sbin/nologin
irc:x:39:39:ircd:/var/run/ircd:/usr/sbin/nologin
gnats:x:41:41:Gnats Bug-Reporting System (admin):/var/lib/gnats:/usr/sbin/nologin
nobody:x:65534:65534:nobody:/nonexistent:/usr/sbin/nologin
_apt:x:100:65534::/nonexistent:/usr/sbin/nologin
redmine:x:999:999::/home/redmine:/bin/sh
hostuser:x:998:996::/home/hostuser:/bin/sh

And I created a .env file with this:

UID=998
GID=996

hostuser is a user that exists on my host (it's name is redmine on the host but I only needed to assign the right UID and GID in order to keep ownership of the redmine files to this user).

I also checked the wait_timeout MySQL variable that closes connections after a period of inactivity but it is on the default value which is 8 hours and my problem appears within approximately 4 hours so it can't be the cause. I also wanted to disable tini in case it was that but I can't find any way to do that. Any help is appreciated.

Thank you.

docker redmine
1 Answers

As a workaround, I ended up with writing a cron task that keep redmine awake with the curl command launched every hour. Here is a sample of my crontab:

0 */1 * * * /usr/bin/curl "https://my.redmine.com/login?keep-redmine-awake-cron" >/dev/null 2>&1
  • The URL parameter ?keep-redmine-awake-cron is only here to identify these requests in the web server logs.
  • The output of the command is ignored with >/dev/null 2>&1 because I don't want cron to send an email containing this useless output.

Though, I was not able to spot the real cause of those long requests after some inactivity.

user_44208780
Related