D4Science Infrastructure

Accessing the system from a commercial internet provider (home connection) is frustrating.
Response time are extremely variable and create/update operations sometimes get non response, even if the operations are correctly executed.
These could be a major issue when partners will start using the system.
Please run some test from home or "non GARR" connections.

I'm working at home and the system the performances are quite the same of the one I experience at CNR.
Seems that the performances degrades significantly with workload.

Do you have any specific example? The only problematic URL that I see now is the /projects one, that needs a bit more than 7 seconds to be composed. If I select or comment an issue I always get an answer in under 2 seconds.

Note that from the logs most of the time is spent building the web page view, while the time spent querying the DB is a small fraction of the total.

And please note that each plugin adds an overhead that can be significant. Here is the log from my last edit (the PUT action that inserted my comment, followed by the GET that updated the ticket page view on my browser), with the time detail of every plugin involved:

Started PUT "/issues/578" for 146.48.48.113 at 2015-09-14 17:24:36 +0200
Processing by IssuesController#update as HTML
  Parameters: {"utf8"=>"✓", "issue"=>{"is_private"=>"0", "project_id"=>"1", "tracker_id"=>"5", "subject"=>"Redmine Installation is slowing down", "description"=>"We should investigate why the installation is slowing down (to load a page takes up to 10 seconds): database response time, memory consumption, CPU load.\r\nIf possible we should try to provide more resources to the bottleneck", "status_id"=>"1", "priority_id"=>"2", "assigned_to_id"=>"746", "category_id"=>"7", "fixed_version_id"=>"34", "parent_issue_id"=>"", "start_date"=>"2015-09-10", "due_date"=>"2015-09-30", "estimated_hours"=>"", "done_ratio"=>"0", "custom_field_values"=>{"3"=>"Production"}, "notes"=>"Do you have any specific example? The only problematic URL that I see now is the /projects one, that needs a bit more than 7 seconds to be composed. If I select or comment an issue I always get an answer in under 2 seconds.\r\n\r\nNote that from the logs most of the time is spent building the web page view, while the time spent querying the DB is a small fraction of the total.", "private_notes"=>"0", "lock_version"=>"2"}, "time_entry"=>{"hours"=>"", "activity_id"=>"", "comments"=>""}, "last_journal_id"=>"2385", "commit"=>"Submit", "id"=>"578"}
  Current user: andrea.dellamico (id=37)
  Rendered mailer/_issue.text.erb (15.6ms)
  Rendered mailer/issue_edit.text.erb within layouts/mailer (19.2ms)
  Rendered mailer/_issue.html.erb (1.7ms)
  Rendered mailer/issue_edit.html.erb within layouts/mailer (4.4ms)
Redirected to http://support.d4science.org/issues/578
Completed 302 Found in 830.1ms (ActiveRecord: 124.2ms)
Started GET "/issues/578" for 146.48.48.113 at 2015-09-14 17:24:37 +0200
Processing by IssuesController#show as HTML
  Parameters: {"id"=>"578"}
  Current user: andrea.dellamico (id=37)
  Rendered issues/_action_menu.html.erb (7.4ms)
  Rendered plugins/advanced_roadmap_v2/app/views/hooks/issues/_show.html.erb (9.3ms)
  Rendered plugins/redmine_code_review/app/views/code_review/_issues_show_details_bottom.html.erb (0.1ms)
  Rendered plugins/unread_issues/app/views/hooks/unread_isues/_issue_bottom_details.html.erb (0.1ms)
  Rendered plugins/redmine_better_gantt_chart/app/views/issues/_show_estimated_duration.html.erb (0.8ms)
  Rendered plugins/recurring_tasks/app/views/issues/_show_recurrence.html.erb (7.0ms)
  Rendered issue_relations/_form.html.erb (3.8ms)
  Rendered issues/_relations.html.erb (6.6ms)
  Rendered issues/_history.html.erb (37.3ms)
  Rendered issues/_action_menu.html.erb (6.2ms)
  Rendered issues/_form_custom_fields.html.erb (1.9ms)
  Rendered issues/_attributes.html.erb (234.3ms)
DEPRECATION WARNING: Passing a template handler in the template name is deprecated. You can simply remove the handler name or pass render :handlers => [:erb] instead. (called from block in render_on at /srv/redmine/redmine-2.6.3/lib/redmine/hook.rb:111)
  Rendered plugins/redmine_didyoumean/app/views/issues/_didyoumean_injected.html.erb (8.7ms)
  Rendered plugins/redmine_issues_sorting/app/views/issues/_issues_sorting.html.erb (1.4ms)
  Rendered plugins/redmine_mentions/app/views/hooks/redmine_mentions/_edit_mentionable.html.erb (15.7ms)
  Rendered issues/_form.html.erb (296.7ms)
  Rendered plugins/redmine_mentions/app/views/hooks/redmine_mentions/_edit_mentionable.html.erb (3.4ms)
  Rendered attachments/_form.html.erb (3.3ms)
  Rendered issues/_edit.html.erb (325.4ms)
  Rendered plugins/redmine_default_custom_query/app/views/issues/_sidebar_issues_bottom.html.erb (6.1ms)
  Rendered plugins/redmine_graphs/app/views/hooks/redmine_graphs/_view_issues_sidebar_issues_bottom.html.erb (2.6ms)
  Rendered plugins/advanced_roadmap_v2/app/views/hooks/_milestones.html.erb (6.7ms)
  Rendered issues/_sidebar.html.erb (32.8ms)
  Rendered watchers/_watchers.html.erb (13.2ms)
  Rendered issues/show.html.erb within layouts/base (524.0ms)
  Rendered plugins/advanced_roadmap_v2/app/views/hooks/_stylesheet.html.erb (0.8ms)
  Rendered plugins/global_roles/app/views/hooks/global_roles/_head.html.erb (0.2ms)
  Rendered plugins/quick_edit/app/views/hooks/_quick_edit_base_head.html.erb (0.1ms)
  Rendered plugins/quick_view/app/views/hooks/_quick_view_base_head.html.erb (0.1ms)
  Rendered plugins/redmine_code_review/app/views/code_review/_html_header.html.erb (0.2ms)
  Rendered plugins/unread_issues/app/views/hooks/unread_isues/_add_css.html.erb (0.6ms)
  Rendered plugins/usability/app/views/hooks/usability/_html_head.html.erb (4.3ms)
  Rendered plugins/clipboard_image_paste/app/views/clipboard_image_paste/_headers.html.erb (2.2ms)
  Rendered plugins/progressive_projects_list/app/views/application/_progressive_sidebar.html.erb (0.1ms)
  Rendered plugins/progressive_projects_list/app/views/application/_progressive_recent_projects.html.erb (5.6ms)
  Rendered plugins/global_roles/app/views/hooks/global_roles/_view_layouts_base_body_bottom.html.erb (0.1ms)
  Rendered plugins/quick_edit/app/views/hooks/_quick_edit_base_bottom.html.erb (0.6ms)
  Rendered plugins/quick_view/app/views/hooks/_quick_view_base_bottom_tooltip.html.erb (0.6ms)
  Rendered plugins/quick_view/app/views/hooks/_quick_view_base_bottom.html.erb (1.1ms)
  Rendered plugins/quick_view/app/views/hooks/_quick_view_base_bottom_worktime_ext.html.erb (0.2ms)
  Rendered plugins/redmine_code_review/app/views/code_review/_body_bottom.html.erb (0.1ms)
  Rendered plugins/usability/app/views/hooks/usability/_body_bottom.html.erb (0.2ms)
  Rendered plugins/clipboard_image_paste/app/views/clipboard_image_paste/_add_form.html.erb (4.8ms)
Completed 200 OK in 840.8ms (Views: 505.6ms | ActiveRecord: 205.4ms)

Note that the /projects URL spends most of the time rendering the base layer, so we should take into account that the theme can make a difference.

Started GET "/projects" for 146.48.48.113 at 2015-09-14 17:28:23 +0200
Processing by ProjectsController#index as HTML
  Current user: andrea.dellamico (id=37)
  Rendered projects/index.html.erb within layouts/base (7973.8ms)

Thanks for your feedback. I noticed that is slowing down when many people work together on Redmine. I know that this means nothing.
I'll update this ticket with more accurate info.

We really need to setup a stress session, on the test instance after the authentication tasks will be solved, because the response times from the logs always give a different picture than those alarming reports.
I see a couple of times when a page is created in more than 10 seconds, some time there are peaks where the pages are rendered in 3/4 seconds, usually a page is offered to the browser in less than a second. I'm reporting here the worst sequence I've found in the logs:

Completed 200 OK in 110.3ms (Views: 41.4ms | ActiveRecord: 60.8ms)
Completed 200 OK in 1686.5ms (Views: 925.2ms | ActiveRecord: 551.4ms)
Completed 200 OK in 4393.1ms (Views: 1300.0ms | ActiveRecord: 970.3ms)
Completed 200 OK in 2037.0ms (Views: 1522.0ms | ActiveRecord: 323.5ms)
Completed 200 OK in 1985.2ms (Views: 1365.6ms | ActiveRecord: 410.1ms)
Completed 200 OK in 3272.8ms (Views: 2038.9ms | ActiveRecord: 723.8ms)
Completed 200 OK in 3410.5ms (Views: 2529.7ms | ActiveRecord: 724.0ms)
Completed 200 OK in 4413.8ms (Views: 3382.8ms | ActiveRecord: 925.1ms)
Completed 200 OK in 795.1ms (Views: 603.4ms | ActiveRecord: 147.9ms)
Completed 200 OK in 1106.2ms (Views: 655.9ms | ActiveRecord: 231.1ms)
Completed 200 OK in 1044.8ms (Views: 514.1ms | ActiveRecord: 408.9ms)
Completed 200 OK in 1379.9ms (Views: 281.2ms | ActiveRecord: 905.7ms)
Completed 200 OK in 1444.5ms (Views: 843.6ms | ActiveRecord: 207.6ms)
Completed 200 OK in 766.2ms (Views: 489.3ms | ActiveRecord: 161.2ms)
Completed 200 OK in 293.6ms (Views: 209.5ms | ActiveRecord: 55.7ms)
Completed 200 OK in 1029.7ms (Views: 618.6ms | ActiveRecord: 280.8ms)
Completed 200 OK in 291.7ms (Views: 1.1ms | ActiveRecord: 66.0ms)
Completed 200 OK in 631.9ms (Views: 296.4ms | ActiveRecord: 317.7ms)
Completed 200 OK in 53.4ms (Views: 31.9ms | ActiveRecord: 13.3ms)
Completed 200 OK in 1367.9ms (Views: 884.2ms | ActiveRecord: 297.1ms)
Completed 200 OK in 1364.5ms (Views: 938.9ms | ActiveRecord: 251.9ms)
Completed 302 Found in 18.7ms (ActiveRecord: 4.7ms)
Completed 200 OK in 1328.6ms (Views: 923.0ms | ActiveRecord: 242.8ms)
Completed 200 OK in 12233.9ms (Views: 7837.5ms | ActiveRecord: 2394.6ms)
Completed 200 OK in 2091.3ms (Views: 1.4ms | ActiveRecord: 1.3ms)
Completed 200 OK in 3182.0ms (Views: 184.5ms | ActiveRecord: 13.7ms)
Completed 200 OK in 965.2ms (Views: 5.6ms | ActiveRecord: 5.8ms)
Completed 200 OK in 94.6ms (Views: 63.8ms | ActiveRecord: 22.3ms)
Completed 200 OK in 2186.6ms (Views: 1964.9ms | ActiveRecord: 186.5ms)
Completed 200 OK in 1595.4ms (Views: 913.6ms | ActiveRecord: 330.2ms)
Completed 200 OK in 377.3ms (Views: 208.5ms | ActiveRecord: 140.0ms)
Completed 200 OK in 1318.3ms (Views: 675.2ms | ActiveRecord: 380.3ms)
Completed 200 OK in 323.2ms (Views: 293.5ms | ActiveRecord: 15.1ms)
Completed 200 OK in 1640.6ms (Views: 182.7ms | ActiveRecord: 116.4ms)
Completed 302 Found in 196.1ms (ActiveRecord: 148.8ms)
Completed 200 OK in 10775.9ms (Views: 1.3ms | ActiveRecord: 96.7ms)
Completed 200 OK in 1586.6ms (Views: 954.1ms | ActiveRecord: 500.6ms)
Completed 200 OK in 1383.4ms (Views: 547.1ms | ActiveRecord: 714.8ms)
Completed 200 OK in 1560.5ms (Views: 1103.6ms | ActiveRecord: 269.6ms)
Completed 200 OK in 1506.8ms (Views: 986.8ms | ActiveRecord: 276.7ms)
Completed 200 OK in 317.6ms (Views: 1.3ms | ActiveRecord: 68.4ms)
Completed 200 OK in 1362.2ms (Views: 965.6ms | ActiveRecord: 242.2ms)
Completed 200 OK in 388.2ms (Views: 55.2ms | ActiveRecord: 62.5ms)
Completed 200 OK in 308.0ms (Views: 1.4ms | ActiveRecord: 87.8ms)
Completed 200 OK in 5731.1ms (Views: 1088.4ms | ActiveRecord: 1925.0ms)
Completed 200 OK in 6439.8ms (Views: 61.5ms | ActiveRecord: 72.9ms)
Completed 200 OK in 95.4ms (Views: 62.9ms | ActiveRecord: 24.9ms)
Completed 200 OK in 55.8ms (Views: 34.3ms | ActiveRecord: 13.2ms)
Completed 404 Not Found in 19.2ms (Views: 12.7ms | ActiveRecord: 1.6ms)
Completed 200 OK in 79.4ms (Views: 60.8ms | ActiveRecord: 7.2ms)
Completed 302 Found in 15.7ms (ActiveRecord: 3.6ms)
Completed 200 OK in 1219.7ms (Views: 724.0ms | ActiveRecord: 289.5ms)
Completed 200 OK in 492.1ms (Views: 256.3ms | ActiveRecord: 87.6ms)
Completed 302 Found in 825.0ms (ActiveRecord: 182.9ms)
Completed 200 OK in 804.0ms (Views: 427.0ms | ActiveRecord: 198.1ms)
Completed 200 OK in 971.1ms (Views: 611.6ms | ActiveRecord: 142.5ms)
Completed 200 OK in 2197.0ms (Views: 1436.4ms | ActiveRecord: 410.2ms)
Completed 200 OK in 1244.1ms (Views: 724.1ms | ActiveRecord: 276.4ms)
Completed 200 OK in 1164.7ms (Views: 778.4ms | ActiveRecord: 222.9ms)
Completed 200 OK in 1571.5ms (Views: 1093.4ms | ActiveRecord: 257.5ms)
Completed 200 OK in 1077.8ms (Views: 648.6ms | ActiveRecord: 235.1ms)
Completed 200 OK in 516.5ms (Views: 334.5ms | ActiveRecord: 99.9ms)
Completed 200 OK in 236.2ms (Views: 0.6ms | ActiveRecord: 191.6ms)
Completed 200 OK in 4002.3ms (Views: 237.0ms | ActiveRecord: 105.3ms)
Completed 200 OK in 2540.4ms (Views: 721.0ms | ActiveRecord: 28.3ms)
Completed 200 OK in 2095.1ms (Views: 173.9ms | ActiveRecord: 64.2ms)
Completed 200 OK in 1509.1ms (Views: 972.7ms | ActiveRecord: 261.7ms)
Completed 200 OK in 1268.6ms (Views: 685.2ms | ActiveRecord: 373.5ms)
Completed 200 OK in 1051.6ms (Views: 151.0ms | ActiveRecord: 11.5ms)
Completed 200 OK in 1002.3ms (Views: 572.1ms | ActiveRecord: 160.3ms)
Completed 302 Found in 15.6ms (ActiveRecord: 4.0ms)

This is not what I experienced using it. Can you past either the Munin link or the Ganglia link to see the statistics about CPUs, network, disk I/O, etc. Thanks

I've just seen that apache is running in prefork mode. I'm going to try and install the threaded one on the dev machine.

Andrea Dell'Amico wrote:

I've just seen that apache is running in prefork mode. I'm going to try and install the threaded one on the dev machine.

It works. I'm switching to the threaded model on the production instance too.

Done. No performance changes should be noticed under normal use.

Can you provide me munin and ganglia links?

http://munin.isti.cnr.it/d4science.org/redmine.d4science.org.html
http://monitoring.research-infrastructures.eu/ganglia/?c=NeMIS%20infrastructure%20services&h=redmine.d4science.org&m=load_one&r=hour&s=by%20name&hc=4&mc=2

thank you

@pasquale.pagano@isti.cnr.it in the last week I did not experienced any slow pages. Did you? Can we close this ticket or do you want to provide more resources?