Redmine 0.8.7 -> 0.9.3 now very slow to display an issue

Added by Anonymous about 4 years ago

Running our 0.8.7 installation vs our 0.9.3 (upgraded from the 0.8.7 one), the time to display an issue has gone from 1.8s to 11.2s according to the redmine development log.

The change seems to be due to how changesets our now looked up for an issue. Looking in the log for 0.8.7, I see the following when showing an issue:

Changeset Load (0.579000)   SELECT * FROM "changesets" INNER JOIN "changesets_issues" ON "changesets".id = "changesets_issues".changeset_id WHERE ("changesets_issues".issue_id = 4213 ) ORDER BY changesets.committed_on ASC, changesets.id ASC

But with 0.9.3, the time for the changeset query has gone up to 10.125s (from 0.579s). The new query is much more complicated:

Changeset Load Including Associations (10125.3ms)   SELECT "changesets"."id" AS t0_r0, "changesets"."repository_id" AS t0_r1, "changesets"."revision" AS t0_r2, "changesets"."committer" AS t0_r3, "changesets"."committed_on" AS t0_r4, "changesets"."comments" AS t0_r5, "changesets"."commit_date" AS t0_r6, "changesets"."scmid" AS t0_r7, "changesets"."user_id" AS t0_r8, "repositories"."id" 
AS t1_r0, "repositories"."project_id" AS t1_r1, "repositories"."url" AS t1_r2, "repositories"."login" AS t1_r3, "repositories"."password" AS t1_r4, "repositories"."root_url" AS t1_r5, "repositories"."type" AS t1_r6, "projects"."id" AS t2_r0, "projects"."name" AS t2_r1, "projects"."description" AS t2_r2, "projects"."homepage" AS t2_r3, "projects"."is_public" AS t2_r4, "projects"."parent_id" AS t2_r5, "projects"."created_on" AS t2_r6, "projects"."updated_on" AS t2_r7, "projects"."identifier" AS t2_r8, "projects"."status" AS t2_r9, "projects"."lft" AS t2_r10, "projects"."rgt" AS t2_r11 FROM "changesets" LEFT OUTER JOIN "repositories" ON "repositories".id = "changesets".repository_id LEFT OUTER JOIN "projects" ON "projects".id = "repositories".project_id INNER JOIN "changesets_issues" ON "changesets".id = "changesets_issues".changeset_id WHERE (((((projects.status=1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='repository')) AND (1=0 OR projects.id IN (2,32,13,7,38,42,1,36,37)))) AND ("changesets_issues".issue_id = 4213 )) AND ("changesets_issues".issue_id = 4213 )) ORDER BY changesets.committed_on ASC, changesets.id ASC

We're using an sqlite backend and our changeset table has 300,000 rows in it and the DB file size is ~225MB. But performed fine under 0.8.7. Is there a way to get 0.9.3 to perform as 0.8.7 did or do we have to revert back to 0.8.7 and stick with that?

Any help greatly appreciated as this is making our Redmine installation feel unusable.

Cheers

Russell

Replies (14)

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Felix Schäfer about 4 years ago

"Development log"? "SQLite"? No kidding it's slow. Other than: either dump humongous amounts of RAM in the box and give each of your redmine processes 500MB of RAM or install a DB instead of SQLite and run it in production mode? No, can't think of anything else than downgrading.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Anonymous about 4 years ago

I was running in production mode. I changed to development mode to track down why the 0.9.3 installation was running so slowly.

Development vs production seems to make no visible difference for this issue.

Yes a different DB may be the answer, but it ran absolutely fine as 0.8.7, but after upgrading to 0.9.3, its now getting on for 10x as slow to show an issue.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Felix Schäfer about 4 years ago

As far as I can tell, the second query gets more information more precisely, i.e. I suppose the first query was hand-crafted and refined and completed afterwards in the redmine code and subsequent queries, the second query is ActiveRecord-generated and contains information about what information exactly is needed. It is admitted that specifying high-level ActiveRecord relationships leads to better readability at the code level and better optimization at the query-level, which then offloads the bulk of the sorting out work to the DB, which in general is better/faster at this sort of stuff than ruby/rails, especially because the optimizer of the DB might also be able to get more juice out of one specific query rather than several general-purpose ones.

Anyway, there is big work being done on the redmine code to get rid of custom SQL and to replace it with expressive ActiveRecord relationships, so the DB might and will get more to chew on over time. That might be the problem you are facing with the SQLite DB, because you get no caching between the different concurrent rails processes or even consecutive rails processes, and each rails process has to load and deal with a complete DB and associated DB engine, which in general is slower when getting less memory (as opposed to only having to allocate memory to your DB once and be done with it). Anyway, I'd wager the "new" request hits some kind of memory limit or whatever that makes the whole thing go haywire, or SQLite is just plain bad with OUTER JOINs.

Long story short: the request might have been quick, it isn't anymore, and I'd blame it on SQLite. If you somehow feel this is a problem with redmine, please file a bug to discuss with one of the devs why the queries have been changed, or that you think there is a bug in this query.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Anonymous about 4 years ago

Thanks Felix, that explains why the query is now so complex. Looking at http://sqlite.org/omitted.html it states that RIGHT and FULL OUTER JOIN aren't supported in sqlite3 so perhaps this is the issue.

sqlite3 is performing perfectly for our needs (where not a huge number of users) so have never seen the need to set up a separate database server such as mysql. I am now looking in to moving to mysql. Initial testing shows that even with our large number of changes (well I've got it to 240,000 so not quite the 300,000 we had in sqlite) and it is taking 0ms for the query.

The downside is there doesn't appear to be a full-proof way of moving from sqlite to mysql. I've tried yaml_db but am getting seq-faults when loading the yaml file back in to the new database (I stripped all repositories from our sqlite db and got it down to 11MB so it isn't huge by yaml still doesn't seem to be able to deal with it).

And mysql won't import the sqlite SQL dump directly as they use slightly different syntax. Global search and replace on certain text fixes most of this (such as AUTO_INCREMENT for AUTOINCREMENT and ` for ") but there are escaping issues. For example our LDAP auth user name contains a '\' as it includes a domain. This comes out in the SQL as a single back-slash but mysql sees this as an escape and just removes it.

So it then comes down to all the text inside tickets/forum posts etc may get corrupted slightly.

So I think I will report this as a performance bug as it certainly is a performance issue when using 0.9 vs 0.8 and if sqlite doesn't support outer joins well, then they ought to be worked around, but I assume this will just be passed off as an issue with ActiveRecord rather than Redmine.

If anyone has a good way of migrating from an sqlite3 db to mysql 5.0.x (looks like the mysql gem only supports 5.0.x not 5.1.x) then that would be very useful.

Cheers

Russell

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Alan Liu about 4 years ago

I have same problem with MySQL 5.1 on Windows Server 2003 R2 Standard Edition.
Any further information I can provide to help tracing the problem?

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Anonymous about 4 years ago

Alan Liu wrote:

I have same problem with MySQL 5.1 on Windows Server 2003 R2 Standard Edition.
Any further information I can provide to help tracing the problem?

To trace it, run in development mode and your log will contain the SQL and timings for all queries for a page render so you can see which query is running slowly.

But for me, moving from sqlite3 to mysql has solved the issue entirely.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Felix Schäfer about 4 years ago

Please not that MySQL 5.1 is not supported by the mysql gem used by rails to connect to the DB, so you might have problems with or because of that.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Anonymous about 4 years ago

Felix Schäfer wrote:

Please not that MySQL 5.1 is not supported by the mysql gem used by rails to connect to the DB, so you might have problems with or because of that.

It could be. I'm running on 5.0.90 without issues.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Alan Liu about 4 years ago

Unlucky to me. DB is MySQL 5.0.90 now. UI doesn't display although log file tells that DB query completes (in seconds). Any comment is appreciated.

development.log (11.5 KB)

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Anonymous about 4 years ago

Alan Liu wrote:

Unlucky to me. DB is MySQL 5.0.90 now. UI doesn't display although log file tells that DB query completes (in seconds). Any comment is appreciated.

Looking at that log it isn't your db thats slow, just Redmine. Look at the completed lines, e.g. for WelcomeController#Index:

Completed in 1532ms (View: 1391, DB: 31)

Db access 31ms but Redmine too 1391ms to do the render, total of 1532ms. So I'd say msql is in the clear. It would be good to try and get some comparative stats from your 0.8.x install if you have a backup and then perhaps posting a performance degradation bug.

Cheers

Russell

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Alan Liu about 4 years ago

After performing 'gem update', 0.9.3 works well on localhost.
The problem now is page displaying is very slow if accessing from other machines.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Anonymous about 4 years ago

Are you sure it isn't a network issue then? I doesn't sound like a Redmine issue anyway, more of an issue with your webserver/network setup if accessing from localhost works fine.

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Alan Liu about 4 years ago

I think it isn't a network issue 'cause 0.8.7 works perfactly in the same environment. And it might not be a pure Redmine issue either. Seems somebody met similiar problem too (http://www.redmine.org/boards/2/topics/10708?r=11519#message-11519). After swithing to mongrel, the performance problem is gone. Thanks, Russell.

  • gem install mongrel
  • mongrel_rails start -e production -p 3000

RE: Redmine 0.8.7 -> 0.9.3 now very slow to display an issue - Added by Felix Schäfer about 4 years ago

I'll go out on a limb here, but (seemingly) excessive network latency for website lookups from "outside" are often related to a webserver misconfiguration, i.e. apache is sometimes configured per default to log not only the IP but also the hostname of the requester, which causes latency if the (reverse) DNS is slow or not reachable.

(1-14/14)