Actions
Defect #4733
closedSlow SQL Queries
Status:
Closed
Priority:
Normal
Assignee:
-
Category:
Database
Target version:
-
Start date:
2010-02-04
Due date:
% Done:
0%
Estimated time:
Resolution:
Affected version:
Description
Since updating to 0.9 Redmine has been showing up in my mySQL slow log every day. This is todays entry:
Count: 447 Time=0.94s (422s) Lock=0.00s (0s) Rows=2270.3 (1014805), redmine[redmine]@[192.168.0.2] SELECT `journals`.`id` AS t0_r0, `journals`.`journalized_id` AS t0_r1, `journals`.`journalized_type` AS t0_r2, `journals`.`user_id` AS t0_r3, `journals`.`notes` AS t0_r4, `journals`.`created_on` AS t0_r5, `issues`.`id` AS t1_r0, `issues`.`tracker_id` AS t1_r1, `issues`.`project_id` AS t1_r2, `issues`.`subject` AS t1_r3, `issues`.`description` AS t1_r4, `issues`.`due_date` AS t1_r5, `issues`.`category_id` AS t1_r6, `issues`.`status_id` AS t1_r7, `issues`.`assigned_to_id` AS t1_r8, `issues`.`priority_id` AS t1_r9, `issues`.`fixed_version_id` AS t1_r10, `issues`.`author_id` AS t1_r11, `issues`.`lock_version` AS t1_r12, `issues`.`created_on` AS t1_r13, `issues`.`updated_on` AS t1_r14, `issues`.`start_date` AS t1_r15, `issues`.`done_ratio` AS t1_r16, `issues`.`estimated_hours` AS t1_r17, `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, `journal_details`.`id` AS t3_r0, `journal_details`.`journal_id` AS t3_r1, `journal_details`.`property` AS t3_r2, `journal_details`.`prop_key` AS t3_r3, `journal_details`.`old_value` AS t3_r4, `journal_details`.`value` AS t3_r5, `users`.`id` AS t4_r0, `users`.`login` AS t4_r1, `users`.`hashed_password` AS t4_r2, `users`.`firstname` AS t4_r3, `users`.`lastname` AS t4_r4, `users`.`mail` AS t4_r5, `users`.`mail_notification` AS t4_r6, `users`.`admin` AS t4_r7, `users`.`status` AS t4_r8, `users`.`last_login_on` AS t4_r9, `users`.`language` AS t4_r10, `users`.`auth_source_id` AS t4_r11, `users`.`created_on` AS t4_r12, `users`.`updated_on` AS t4_r13, `users`.`type` AS t4_r14 FROM `journals` LEFT OUTER JOIN `issues` ON `issues`.id = `journals`.journalized_id LEFT OUTER JOIN `projects` ON `projects`.id!= `issues`.project_id LEFT OUTER JOIN `journal_details` ON journal_details.journal_id = journals.id LEFT OUTER JOIN `users` ON `users`.id = `journals`.user_id WHERE (journals.journalized_type = 'Issue' AND (journal_details.prop_key = 'status_id' OR journals.notes <> '')) AND (1=1 AND (journals.created_on BETWEEN '2010-01-04' AND '2010-02-03') AND (((projects.status=1 AND EXISTS (SELECT em.id FROM enabled_modules em WHERE em.name='issue_tracking' AND em.project_id=projects.id)) AND (1=0 OR projects.is_public = 1 OR projects.id IN (10,9,12,1,4,5,8,2,3)))));
Which is being run 447 times a day at about a second each.
Explain gives this:
+----+--------------------+-----------------+--------+---------------------------------------------------------------------------------------+------------------------------+---------+---------------------------------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+--------------------+-----------------+--------+---------------------------------------------------------------------------------------+------------------------------+---------+---------------------------------+------+-------------+ | 1 | PRIMARY | projects | ALL | PRIMARY | NULL | NULL | NULL | 29 | Using where | | 1 | PRIMARY | journals | range | journals_journalized_id,index_journals_on_journalized_id,index_journals_on_created_on | index_journals_on_created_on | 8 | NULL | 1095 | Using where | | 1 | PRIMARY | issues | eq_ref | PRIMARY | PRIMARY | 4 | redmine.journals.journalized_id | 1 | Using where | | 1 | PRIMARY | journal_details | ref | journal_details_journal_id | journal_details_journal_id | 4 | redmine.journals.id | 1 | Using where | | 1 | PRIMARY | users | eq_ref | PRIMARY,index_users_on_id_and_type | PRIMARY | 4 | redmine.journals.user_id | 1 | | | 2 | DEPENDENT SUBQUERY | em | ref | enabled_modules_project_id | enabled_modules_project_id | 5 | redmine.projects.id | 3 | Using where | +----+--------------------+-----------------+--------+---------------------------------------------------------------------------------------+------------------------------+---------+---------------------------------+------+-------------+ 6 rows in set (0.01 sec)
Apparently all tables except projects are using an index, and all but journals are only inspecting a small number of rows, so explain looks OK (except the large number of joins) - no filesorts ect.
Still Redmine never used to appear in my slow query log so I flag this now.
Actions