(Self-answered already)
I'm fighting poor performance of my redmine of about 100 users. To test it, I've set up a simple scenario to update "Percent done" on five different example issues. All the updates start at exactly the same second, using curl
. To my amazement, the updates in redmine seem serialized (I mean not multithreaded) with timings like this:
real 0m1.122s
real 0m1.404s
real 0m2.258s
real 0m2.782s
real 0m3.151s
real 0m3.336s
Or another try, when some processing by other sessions gets in the way too:
real 0m7.492s
real 0m7.803s
real 0m8.045s
real 0m8.246s
real 0m8.597s
real 0m8.825s
The key moment in the production.log
after processing zilliards of SQL queries is the COMMIT phase. Note how COMMITs are done in milliseconds, but something mysterious goes on between COMMITs that not only serializes them but takes seconds to take to Completed status. This log excerpt is intact - I didn't delete any lines in-between.
(0.6ms) SELECT COUNT(*) FROM `custom_workflows` WHERE `custom_workflows`.`active` = 1 AND `custom_workflows`.`observable` = 'issue' AND (is_for_all OR EXISTS (SELECT * FROM custom_workflows_projects WHERE project_id=123 AND custom_workflow_id=id))
(30.1ms) COMMIT
Redirected to http://redmine.mydomain.local/issues/11973
Completed 302 Found in 7418.4ms (ActiveRecord: 135.8ms)
(0.6ms) SELECT COUNT(*) FROM `custom_workflows` WHERE `custom_workflows`.`active` = 1 AND `custom_workflows`.`observable` = 'issue' AND (is_for_all OR EXISTS (SELECT * FROM custom_workflows_projects WHERE project_id=123 AND custom_workflow_id=id))
(24.8ms) COMMIT
Redirected to http://redmine.mydomain.local/issues/9240
Completed 302 Found in 7738.3ms (ActiveRecord: 57.4ms)
(0.4ms) SELECT COUNT(*) FROM `custom_workflows` WHERE `custom_workflows`.`active` = 1 AND `custom_workflows`.`observable` = 'issue' AND (is_for_all OR EXISTS (SELECT * FROM custom_workflows_projects WHERE project_id=123 AND custom_workflow_id=id))
(25.9ms) COMMIT
Redirected to http://redmine.mydomain.local/issues/9614
Completed 302 Found in 7949.0ms (ActiveRecord: 135.7ms)
(0.5ms) SELECT COUNT(*) FROM `custom_workflows` WHERE `custom_workflows`.`active` = 1 AND `custom_workflows`.`observable` = 'issue' AND (is_for_all OR EXISTS (SELECT * FROM custom_workflows_projects WHERE project_id=123 AND custom_workflow_id=id))
(24.6ms) COMMIT
Redirected to http://redmine.mydomain.local/issues/12016
Completed 302 Found in 8058.5ms (ActiveRecord: 102.5ms)
(0.5ms) SELECT COUNT(*) FROM `custom_workflows` WHERE `custom_workflows`.`active` = 1 AND `custom_workflows`.`observable` = 'issue' AND (is_for_all OR EXISTS (SELECT * FROM custom_workflows_projects WHERE project_id=123 AND custom_workflow_id=id))
(21.2ms) COMMIT
Redirected to http://redmine.mydomain.local/issues/8853
Completed 302 Found in 8472.5ms (ActiveRecord: 90.4ms)
(0.5ms) SELECT COUNT(*) FROM `custom_workflows` WHERE `custom_workflows`.`active` = 1 AND `custom_workflows`.`observable` = 'issue' AND (is_for_all OR EXISTS (SELECT * FROM custom_workflows_projects WHERE project_id=123 AND custom_workflow_id=id))
(27.9ms) COMMIT
Redirected to http://redmine.mydomain.local/issues/10007
Completed 302 Found in 8700.4ms (ActiveRecord: 137.4ms)
What I've already checked:
- passenger-status has more threads than enough
- apache2 httpd has more processes than enough
- mysql 5.1 uses innodb
- innotop doesn't show locks
- innotop doesn't excessive I/O
- iostat doesn't show excessive I/O (about 10-15 IOPS, disk max 17% time usage)
- top doesn't show excessive CPU usage (max 70% of possible 400%).
OK it was SMTP serializing things; it is somehow unlogged by default.
I've changed
/var/www/html/redmine/config/configuration.yml
: