Redmine

Please describe all relevant software versions, redmine, ruby, rails, application server, ...
It's also important to know what hardware you're running on.

I'm running this:
Software
Redmine 1.4.3
Ruby 1.8.7
Rails 2.3.14
Passenger 2.2.11
Apache 2.2.16

Hardware
Virtual machine, 2GB RAM, 1 virtual processor @ 2,6GHz

I do not have the strings "Processing by" or "Rendered queries" in my production.log.
Nevertheless, just to have some numbers for you (Anzahl means "count", Durchschnitt means "Average"):

Avg. duration for listing tickets
grep IssuesController#index production3.log -A 4|grep -i completed|cut -d " " -f3 |sed -e 's/ms//g'|awk ' { loadsum += $1; anzahl ++; } END { print "Anzahl, Durchschnitt: " anzahl " - " loadsum/anzahl ; }'
Anzahl, Durchschnitt: 1698 - 278.423

This shows that the analyzed logfile "production3.log" contains 1698 calls to "IssuesController#index" and the average duration was 278.4ms. For me, that's snappy enough :-)

Avg. duration for creating new tickets
Call similar to the above one (IssuesController#new), avg. duration is 132ms.

Perhaps you have a configuration issue, or your database is slow, or... there are 100s of potential reasons...

Jan

• Redmine 2.0.3
• Ruby 1.9.2p320
• Rails 3.2.6
• Passenger 3.0.15
• Apache 2.2.15

• VM
• 4GB RAM
• 2 Cores at 2.6GHz

Some log output:

Started GET "/projects/system/issues?page=3" for 10.29.96.11 at 2012-08-13 09:36:26 -0400
Processing by IssuesController#index as HTML
  Parameters: {"page"=>"3", "project_id"=>"system"}
  Rendered queries/_filters.html.erb (145.0ms)
  Rendered queries/_columns.html.erb (1.9ms)
  Rendered issues/_list.html.erb (33.0ms)
  Rendered issues/_sidebar.html.erb (5.9ms)
  Rendered issues/index.html.erb within layouts/base (249.9ms)
Completed 200 OK in 394ms (Views: 352.9ms | ActiveRecord: 5.1ms)

Started GET "/projects/system/issues?page=4" for 10.29.96.11 at 2012-08-13 09:36:28 -0400
Processing by IssuesController#index as HTML
  Parameters: {"page"=>"4", "project_id"=>"system"}
  Rendered queries/_filters.html.erb (196.6ms)
  Rendered queries/_columns.html.erb (3.3ms)
  Rendered issues/_list.html.erb (127.0ms)
  Rendered issues/_sidebar.html.erb (9.5ms)
  Rendered issues/index.html.erb within layouts/base (354.1ms)
Completed 200 OK in 504ms (Views: 431.7ms | ActiveRecord: 9.4ms)

Started GET "/projects/system/issues" for 10.29.96.11 at 2012-08-13 09:36:33 -0400
Processing by IssuesController#index as HTML
  Parameters: {"project_id"=>"system"}
  Rendered queries/_filters.html.erb (126.3ms)
  Rendered queries/_columns.html.erb (71.4ms)
  Rendered issues/_list.html.erb (54.4ms)
  Rendered issues/_sidebar.html.erb (9.4ms)
  Rendered issues/index.html.erb within layouts/base (277.3ms)
Completed 200 OK in 571ms (Views: 432.5ms | ActiveRecord: 4.1ms)

Started GET "/projects/system/issues/new" for 10.29.96.11 at 2012-08-13 09:36:55 -0400
Processing by IssuesController#new as HTML
  Parameters: {"project_id"=>"system"}
  Rendered issues/_form_custom_fields.html.erb (16.7ms)
  Rendered issues/_attributes.html.erb (75.8ms)
  Rendered issues/_form.html.erb (93.1ms)
  Rendered attachments/_form.html.erb (2.3ms)
  Rendered issues/new.html.erb within layouts/base (181.1ms)
Completed 200 OK in 309ms (Views: 257.4ms | ActiveRecord: 18.0ms)

Here is my mysql my.cnf. Very minor updates from what was originally there, basically just added the key buffer size and query cache

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
key_buffer_size=512M
query_cache_type = 1
query_cache_limit = 1M
query_cache_size = 32M

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

I am sure I could have not configured something somewhere, this was my first install like this in a while.

This setup also has about 6600 issues, and a lot of projects, possibly close to 100 or more. 116 users, but probably only 5-10 max on at a time. On this new install, its only me on there, and I am seeing these speeds. The machine is also mostly calm when anything is going on, I see apache/ruby jump to the top but no more than 20% when clicking through the issues pages.

I logged several of the queries that were being run through mysql, and I really don't think mysql is the slow part here. While Redmine does seem to bring back a little more than needed, the queries ran rather fast through a remote connection. I was also running a tail on the queries, and while it seemed to continuously interact with MySQL (it runs several queries for each thing), those on the whole were not the whole slowdown.

Where should one look next?

Perhaps I'm misunderstanding the situation, but I don't see anything "slow" in your log. I don't know other installs but my own, but 394ms, 504ms, 571ms isn't what I'd call slow.

You create a new ticket in 309ms... that's 1/3rd of a second... and you call that "slow"?
But, as stated above, perhaps I just don't grok it.

It would be interesting to see your apache logs. Maybe you're sending all the css/js on each request, this could be avoided by settings some expires headers for these assets in your apache conf.

BTW, the issue list should render faster with Redmine 2.1.0 (will be released next month).

Jan Niggemann (redmine.org team member) - no, half a second or less isn't slow per se - but if you look at how fast redmine.org is, and some other peoples numbers, this can usually be around > 100ms. Around 300ms it seems to be 'noticeable', but nothing bad by far. I just want to tune it to get as fast as possible.

@Jean-Philippe Lang - I ran some of Chrome's debugger tools, and it still is dramatically on the redmine side - as in, if you look at the redmine log, or Chrome's profile, its 'waiting' ~500ms on the page, then pulls up the static files. Some example logs:

192.168.1.11 - - [14/Aug/2012:08:02:40 -0400] "GET /issues/6364 HTTP/1.1" 200 57502 "http://redmine/issues/6361" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.77 Safari/537.1" 
192.168.1.11 - - [14/Aug/2012:08:02:41 -0400] "GET /issues/6365 HTTP/1.1" 200 56168 "http://redmine/issues/6364" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.77 Safari/537.1" 
192.168.1.11 - - [14/Aug/2012:08:02:42 -0400] "GET /issues/6238 HTTP/1.1" 200 57658 "http://redmine/issues/6365" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.77 Safari/537.1" 

At first I thought something similar, but also since this is on a new setup, many people need to 're-cache' this. These logs are from my machine accessing it though, which has it already cached. Also, from the logs at the top, you can see that its the redmine.log mentioning most of the processing time.

Seeing the issues list get faster would be very nice. I was just wondering what we can even do now to fine tune it. For example, it seems like we have a really decent server setup, and would expect a bit more speed from this config. Following all of the howto's available here and elsewhere to help with installing Redmine on RHEL 6, this setup is what we have. There doesn't seem to be many posts on how to fine-tune this to particular setups, where there seems to be plenty of people who do have very speedy setups on even less powerful hardware.

Looking at the log of your issue list, rendering queries/_filters.html.erb takes 100~200ms. Maybe you have a lot of members/categories/versions in your project and rails is pretty slow at rendering large select tags. This specific partial renders faster in the next release.

Also, I've noticed that psych (the yaml parser) can be really slow on some platform. Could you run the following line under the rails console:

Benchmark.ms {100.times {YAML.load("a: 1")}}

Yes, we do have quite a few versions, and even nested versions (like a version shared across a project). There are also quite a few users too (not online, but as in users in the system).

I am not familiar with rails console. When I try to do 'rails console', I get an odd error:

/usr/local/lib/ruby/gems/1.9.1/gems/bundler-1.1.5/lib/bundler/rubygems_integration.rb:147:in `block in replace_gem': Please install the mysql adapter: `gem install activerecord-mysql-adapter` (mysql is not part of the bundle. Add it to Gemfile.) (LoadError)
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/connection_adapters/mysql_adapter.rb:5:in `<top (required)>'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:251:in `require'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:251:in `block in require'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:236:in `load_dependency'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:251:in `require'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_specification.rb:48:in `resolve_hash_connection'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_specification.rb:39:in `resolve_string_connection'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_specification.rb:23:in `spec'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_specification.rb:127:in `establish_connection'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/railtie.rb:82:in `block (2 levels) in <class:Railtie>'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/lazy_load_hooks.rb:36:in `instance_eval'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/lazy_load_hooks.rb:36:in `execute_hook'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/lazy_load_hooks.rb:43:in `block in run_load_hooks'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/lazy_load_hooks.rb:42:in `each'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/lazy_load_hooks.rb:42:in `run_load_hooks'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activerecord-3.2.6/lib/active_record/base.rb:721:in `<top (required)>'
        from /var/www/redmine/lib/plugins/acts_as_activity_provider/init.rb:2:in `block in <top (required)>'
        from /var/www/redmine/config/initializers/00-core_plugins.rb:12:in `eval'
        from /var/www/redmine/config/initializers/00-core_plugins.rb:12:in `block in <top (required)>'
        from /var/www/redmine/config/initializers/00-core_plugins.rb:2:in `each'
        from /var/www/redmine/config/initializers/00-core_plugins.rb:2:in `<top (required)>'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:245:in `load'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:245:in `block in load'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:236:in `load_dependency'
        from /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.6/lib/active_support/dependencies.rb:245:in `load'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/engine.rb:588:in `block (2 levels) in <class:Engine>'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/engine.rb:587:in `each'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/engine.rb:587:in `block in <class:Engine>'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/initializable.rb:30:in `instance_exec'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/initializable.rb:30:in `run'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/initializable.rb:55:in `block in run_initializers'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/initializable.rb:54:in `each'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/initializable.rb:54:in `run_initializers'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/application.rb:136:in `initialize!'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/railtie/configurable.rb:30:in `method_missing'
        from /var/www/redmine/config/environment.rb:14:in `<top (required)>'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/application.rb:103:in `require'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/application.rb:103:in `require_environment!'
        from /usr/local/lib/ruby/gems/1.9.1/gems/railties-3.2.6/lib/rails/commands.rb:40:in `<top (required)>'
        from script/rails:6:in `require'
        from script/rails:6:in `<main>'

Try: `script/rails c production`

I get 1.6326904296875.

I don't lucky as you.

Log Following is a log of issue view.

• is in attached **
  Completed 200 OK in *25070ms (Views: 22293.6ms | ActiveRecord: 371.1ms)

Total proccess is about 25 second.

The are ~1000 issue records, 170 users (10 are active user, others from Active Directory)

Hardware:
Bitnami redmine stack running on 4GB RAM with 8 Core virtual machine. There is no any performance problems other virtual machines on the same physical server.

Environment:
Redmine version 2.1.4.stable
Ruby version 1.8.7 (x86_64-linux)
Rails version 3.2.8
Environment production
Database adapter MySQL
Redmine plugins:
due_date_reminder 0.3.2
extended_fields 0.2.0b
redmine_assets_plugin 0.0.1
redmine_banner 0.0.8
redmine_boards_watchers 0.2.5
redmine_changeauthor 1.0.0
redmine_contacts 3.0.1-pro
redmine_contacts_helpdesk 2.0.1
redmine_favourite_projects 0.6
redmine_information 1.0.2
redmine_inline_attach_screenshot 0.4.2
redmine_issue_checklist 2.0.0
redmine_ldap_sync 1.3.0
redmine_logs 0.0.5
redmine_meetings 0.2.3
redmine_milestones 1.0.0-pro-alpha1
redmine_monitoring_controlling 0.1.1
redmine_private_wiki 0.2.2
redmine_release_notes 1.2.0
redmine_reorder_links_arbitrary 0.0.7
redmine_smart_issues_sort 0.3.1
redmine_stealth 0.6.0
redmine_textilizable_custom_fields 0.0.1
redmine_theme_changer 0.1.0
redmine_wiki_extensions 0.6.0
redmine_wiki_toc 0.0.4
redmine_wktime 1.1
redmine_work_time 0.2.6

in my case, Views is 22293.6 ms and ActiveRecord is 371.1 ms.
What is the mean of this biggest time?
views is related to apache/php, ActiveRecord is related to ruby. Is it correct?
I need help to fix this problem. We will buy service. Is there a professional guys to fix this?

Regards,
Adnan Topcu
1165@ug78.com

I ran the benchmark test and got 1.3120174407959. I'm not a Ruby developer (I'm an IT guy who can get himself into trouble), so I don't know what to make of that result.

I'm also trying to troubleshoot a slow Redmine 2.3.1 instance and am just flummoxed about why my site is so slow. I'm running on a M1.large linux instance on AWS EC2 (GovCloud), and I really would expect this to be faster. I've got the same site running on a Rackspace small instance and it's nearly twice as fast (and that's still no speed demon).

Here's a sample from production.log


Started GET "/projects/sig?jump=issues" for 174.109.213.196 at Sat Jul 06 19:34:03 +0000 2013
Processing by ProjectsController#show as HTML
Parameters: {"id"=>"sig", "jump"=>"issues"}
Current user: jamie (id=4)
Redirected to https://xxx.xxx.xxx/projects/sig/issues
Completed 302 Found in 9ms (ActiveRecord: 0.6ms)
Started GET "/projects/sig/issues" for 174.109.213.196 at Sat Jul 06 19:34:03 +0000 2013
Processing by IssuesController#index as HTML
Parameters: {"project_id"=>"sig"}
Current user: jamie (id=4)
Rendered queries/_filters.html.erb (104.7ms)
Rendered queries/_columns.html.erb (3.8ms)
Rendered issues/_list.html.erb (1625.0ms)
Rendered issues/_sidebar.html.erb (11.9ms)
Rendered issues/index.html.erb within layouts/base (1762.7ms)
Completed 200 OK in 2588ms (Views: 2247.0ms | ActiveRecord: 38.7ms)


Any suggestions for me to try?