Project

General

Profile

Defect #37539 » redmine_4_2_7.log

slow log - Onur Küçük, 2022-08-02 23:44

 
1
[2022-08-03 00:18:05.678 +0300] (7919)  INFO  Started GET "/issues?utf8=%E2%9C%93&set_filter=1&sort=id%3Adesc&f%5B%5D=status_id&op%5Bstatus_id%5D=o&f%5B%5D=cf_105&op%5Bcf_105%5D=%3D&v%5Bcf_105%5D%5B%5D=1&f%5B%5D=&c%5B%5D=project&c%5B%5D=tracker&c%5B%5D=status&c%5B%5D=subject&c%5B%5D=assigned_to&c%5B%5D=category&c%5B%5D=fixed_version&group_by=&t%5B%5D=" for 127.0.0.1 at 2022-08-03 00:18:05 +0300
2
[2022-08-03 00:18:05.683 +0300] (7919)  INFO  Processing by IssuesController#index as HTML
3
[2022-08-03 00:18:05.683 +0300] (7919)  INFO    Parameters: {"utf8"=>"✓", "set_filter"=>"1", "sort"=>"id:desc", "f"=>["status_id", "cf_105", ""], "op"=>{"status_id"=>"o", "cf_105"=>"="}, "v"=>{"cf_105"=>["1"]}, "c"=>["project", "tracker", "status", "subject", "assigned_to", "category", "fixed_version"], "group_by"=>"", "t"=>[""]}
4
[2022-08-03 00:18:05.685 +0300] (7919) DEBUG user.rb:492:in `verify_session_token'   Token Update All (0.6ms)  UPDATE "tokens" SET "updated_on" = '2022-08-03 00:18:05.684378' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3  [["user_id", 16], ["value", "defd0ab80d11e890cf4c54799a6879462ae23ba3"], ["action", "session"]]
5
[2022-08-03 00:18:05.686 +0300] (7919) DEBUG setting.rb:270:in `check_cache'    (0.3ms)  SELECT MAX("settings"."updated_on") FROM "settings"
6
[2022-08-03 00:18:05.688 +0300] (7919) DEBUG application_controller.rb:114:in `find_current_user'   User Load (0.4ms)  SELECT  "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3  [["status", 1], ["id", 16], ["LIMIT", 1]]
7
[2022-08-03 00:18:05.688 +0300] (7919)  INFO application_controller.rb:102:in `user_setup'   Current user: onur (id=16)
8
[2022-08-03 00:18:05.692 +0300] (7919) DEBUG issue_query.rb:135:in `collect'   Tracker Load (2.3ms)  SELECT DISTINCT "trackers".* FROM "trackers" INNER JOIN "projects_trackers" ON "projects_trackers"."tracker_id" = "trackers"."id" INNER JOIN "projects" ON "projects"."id" = "projects_trackers"."project_id" WHERE (projects.status <> 9 AND EXISTS (SELECT 1 AS one FROM enabled_modules em WHERE em.project_id = projects.id AND em.name='issue_tracking')) ORDER BY "trackers"."position" ASC
9
[2022-08-03 00:18:05.695 +0300] (7919) DEBUG issue_query.rb:139:in `collect'   IssuePriority Load (0.5ms)  SELECT "enumerations".* FROM "enumerations" WHERE "enumerations"."type" IN ('IssuePriority') ORDER BY "enumerations"."position" ASC
10
[2022-08-03 00:18:05.698 +0300] (7919) DEBUG query.rb:1494:in `add_custom_fields_filters'   IssueCustomField Load (0.6ms)  SELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('IssueCustomField') AND "custom_fields"."is_filter" = $1 ORDER BY "custom_fields"."position" ASC  [["is_filter", true]]
11
[2022-08-03 00:18:05.700 +0300] (7919) DEBUG query.rb:1471:in `add_chained_custom_field_filters'   CustomField Load (0.3ms)  SELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."is_filter" = $1 AND "custom_fields"."type" = $2  [["is_filter", true], ["type", "UserCustomField"]]
12
[2022-08-03 00:18:05.701 +0300] (7919) DEBUG query.rb:1471:in `add_chained_custom_field_filters'   CACHE CustomField Load (0.0ms)  SELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."is_filter" = $1 AND "custom_fields"."type" = $2  [["is_filter", true], ["type", "UserCustomField"]]
13
[2022-08-03 00:18:05.702 +0300] (7919) DEBUG query.rb:1521:in `group_by'   CustomField Load (0.3ms)  SELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."is_filter" = $1  [["is_filter", true]]
14
[2022-08-03 00:18:05.704 +0300] (7919) DEBUG issue_query.rb:256:in `collect'   IssueCustomField Load (0.2ms)  SELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('IssueCustomField') ORDER BY "custom_fields"."position" ASC
15
[2022-08-03 00:18:05.709 +0300] (7919) DEBUG user.rb:414:in `pref'   UserPreference Load (0.3ms)  SELECT  "user_preferences".* FROM "user_preferences" WHERE "user_preferences"."user_id" = $1 LIMIT $2  [["user_id", 16], ["LIMIT", 1]]
16
[2022-08-03 00:19:27.610 +0300] (7919) DEBUG issue_query.rb:329:in `issue_count'    (81900.8ms)  SELECT COUNT(*) FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" INNER JOIN "issue_statuses" ON "issue_statuses"."id" = "issues"."status_id" WHERE (projects.status <> 9 AND EXISTS (SELECT 1 AS one FROM enabled_modules em WHERE em.project_id = projects.id AND em.name='issue_tracking')) AND ((issues.status_id IN (SELECT id FROM issue_statuses WHERE is_closed=FALSE)) AND issues.id  IN (SELECT issues.id FROM issues LEFT OUTER JOIN custom_values ON custom_values.customized_type='Issue' AND custom_values.customized_id=issues.id AND custom_values.custom_field_id=105 WHERE (custom_values.value IN ('1')) AND (((1=1) AND (issues.tracker_id IN (SELECT tracker_id FROM custom_fields_trackers WHERE custom_field_id = 105)) AND (EXISTS (SELECT 1 FROM custom_fields ifa WHERE ifa.is_for_all = TRUE AND ifa.id = 105) OR issues.project_id IN (SELECT project_id FROM custom_fields_projects WHERE custom_field_id = 105)) AND (projects.status <> 9 AND EXISTS (SELECT 1 AS one FROM enabled_modules em WHERE em.project_id = projects.id AND em.name='issue_tracking'))))))
17
[2022-08-03 00:19:31.352 +0300] (7919) DEBUG issue_query.rb:377:in `issues'   SQL (3739.0ms)  SELECT  "issues"."id" AS t0_r0, "issues"."tracker_id" AS t0_r1, "issues"."project_id" AS t0_r2, "issues"."subject" AS t0_r3, "issues"."description" AS t0_r4, "issues"."due_date" AS t0_r5, "issues"."category_id" AS t0_r6, "issues"."status_id" AS t0_r7, "issues"."assigned_to_id" AS t0_r8, "issues"."priority_id" AS t0_r9, "issues"."fixed_version_id" AS t0_r10, "issues"."author_id" AS t0_r11, "issues"."lock_version" AS t0_r12, "issues"."created_on" AS t0_r13, "issues"."updated_on" AS t0_r14, "issues"."start_date" AS t0_r15, "issues"."done_ratio" AS t0_r16, "issues"."estimated_hours" AS t0_r17, "issues"."parent_id" AS t0_r18, "issues"."root_id" AS t0_r19, "issues"."lft" AS t0_r20, "issues"."rgt" AS t0_r21, "issues"."is_private" AS t0_r22, "issues"."closed_on" AS t0_r23, "issues"."rim_package_report_id" AS t0_r24, "issues"."rw_box_id" AS t0_r25, "issues"."rw_box_position" AS t0_r26, "issue_statuses"."id" AS t1_r0, "issue_statuses"."name" AS t1_r1, "issue_statuses"."is_closed" AS t1_r2, "issue_statuses"."position" AS t1_r3, "issue_statuses"."default_done_ratio" AS t1_r4, "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, "projects"."inherit_members" AS t2_r12, "projects"."default_version_id" AS t2_r13, "projects"."default_assigned_to_id" AS t2_r14 FROM "issues" INNER JOIN "projects" ON "projects"."id" = "issues"."project_id" INNER JOIN "issue_statuses" ON "issue_statuses"."id" = "issues"."status_id" WHERE (projects.status <> 9 AND EXISTS (SELECT 1 AS one FROM enabled_modules em WHERE em.project_id = projects.id AND em.name='issue_tracking')) AND ((issues.status_id IN (SELECT id FROM issue_statuses WHERE is_closed=FALSE)) AND issues.id  IN (SELECT issues.id FROM issues LEFT OUTER JOIN custom_values ON custom_values.customized_type='Issue' AND custom_values.customized_id=issues.id AND custom_values.custom_field_id=105 WHERE (custom_values.value IN ('1')) AND (((1=1) AND (issues.tracker_id IN (SELECT tracker_id FROM custom_fields_trackers WHERE custom_field_id = 105)) AND (EXISTS (SELECT 1 FROM custom_fields ifa WHERE ifa.is_for_all = TRUE AND ifa.id = 105) OR issues.project_id IN (SELECT project_id FROM custom_fields_projects WHERE custom_field_id = 105)) AND (projects.status <> 9 AND EXISTS (SELECT 1 AS one FROM enabled_modules em WHERE em.project_id = projects.id AND em.name='issue_tracking')))))) ORDER BY issues.id DESC LIMIT $1 OFFSET $2  [["LIMIT", 25], ["OFFSET", 0]]
18
[2022-08-03 00:19:31.355 +0300] (7919) DEBUG issue_query.rb:377:in `issues'   IssuePriority Load (0.5ms)  SELECT "enumerations".* FROM "enumerations" WHERE "enumerations"."type" IN ('IssuePriority') AND "enumerations"."id" = $1 ORDER BY "enumerations"."position" ASC  [["id", 13]]
19
[2022-08-03 00:19:31.356 +0300] (7919) DEBUG issue_query.rb:377:in `issues'   Tracker Load (0.3ms)  SELECT "trackers".* FROM "trackers" WHERE "trackers"."id" IN ($1, $2)  [["id", 2], ["id", 1]]
20
[2022-08-03 00:19:31.357 +0300] (7919) DEBUG issue_query.rb:377:in `issues'   Principal Load (0.4ms)  SELECT "users".* FROM "users" WHERE "users"."id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)  [["id", 824], ["id", 951], ["id", 950], ["id", 971], ["id", 685], ["id", 834], ["id", 923], ["id", 863], ["id", 966], ["id", 952]]
21
[2022-08-03 00:19:31.358 +0300] (7919) DEBUG issue_query.rb:377:in `issues'   Version Load (0.3ms)  SELECT "versions".* FROM "versions" WHERE "versions"."id" = $1  [["id", 1805]]
22
[2022-08-03 00:19:31.359 +0300] (7919) DEBUG issue_query.rb:377:in `issues'   IssueCategory Load (0.4ms)  SELECT "issue_categories".* FROM "issue_categories" WHERE "issue_categories"."id" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11)  [["id", 490], ["id", 672], ["id", 612], ["id", 669], ["id", 494], ["id", 493], ["id", 629], ["id", 576], ["id", 670], ["id", 574], ["id", 667]]
23
[2022-08-03 00:19:31.360 +0300] (7919)  INFO issues_controller.rb:54:in `block (2 levels) in index'   Rendering issues/index.html.erb within layouts/base
24
[2022-08-03 00:19:31.364 +0300] (7919) DEBUG query.rb:635:in `collect'   IssueStatus Load (0.3ms)  SELECT "issue_statuses".* FROM "issue_statuses" ORDER BY "issue_statuses"."position" ASC
25
[2022-08-03 00:19:31.373 +0300] (7919)  INFO _query_form.html.erb:10:in `_app_views_queries__query_form_html_erb___3739772912959596206_83160'   Rendered queries/_filters.html.erb (10.4ms)
26
[2022-08-03 00:19:31.375 +0300] (7919)  INFO queries_helper.rb:136:in `render_query_columns_selection'   Rendered queries/_columns.html.erb (1.6ms)
27
[2022-08-03 00:19:31.378 +0300] (7919)  INFO index.html.erb:24:in `block in _app_views_issues_index_html_erb__4153315814078676898_83140'   Rendered queries/_query_form.html.erb (15.4ms)
28
[2022-08-03 00:19:31.382 +0300] (7919) DEBUG issue.rb:1456:in `css_classes'   Group Load (0.5ms)  SELECT "users".* FROM "users" INNER JOIN "groups_users" ON "users"."id" = "groups_users"."group_id" WHERE "users"."type" IN ('Group', 'GroupBuiltin', 'GroupAnonymous', 'GroupNonMember') AND "groups_users"."user_id" = $1  [["user_id", 16]]
29
[2022-08-03 00:19:31.387 +0300] (7919) DEBUG version.rb:190:in `visible?'   Project Load (0.2ms)  SELECT  "projects".* FROM "projects" WHERE "projects"."id" = $1 LIMIT $2  [["id", 249], ["LIMIT", 1]]
30
[2022-08-03 00:19:31.387 +0300] (7919) DEBUG project.rb:1279:in `allowed_permissions'    (0.2ms)  SELECT "enabled_modules"."name" FROM "enabled_modules" WHERE "enabled_modules"."project_id" = $1  [["project_id", 249]]
31
[2022-08-03 00:19:31.397 +0300] (7919)  INFO index.html.erb:32:in `_app_views_issues_index_html_erb__4153315814078676898_83140'   Rendered issues/_list.html.erb (18.6ms)
32
[2022-08-03 00:19:31.398 +0300] (7919) DEBUG user.rb:439:in `rss_key'   Token Load (0.2ms)  SELECT  "tokens".* FROM "tokens" WHERE "tokens"."user_id" = $1 AND (action='feeds') LIMIT $2  [["user_id", 16], ["LIMIT", 1]]
33
[2022-08-03 00:19:31.400 +0300] (7919) DEBUG queries_helper.rb:438:in `sidebar_queries'   IssueQuery Load (0.5ms)  SELECT "queries".* FROM "queries" LEFT OUTER JOIN projects ON queries.project_id = projects.id WHERE "queries"."type" IN ('IssueQuery') AND (queries.project_id IS NULL OR (projects.status <> 9 AND EXISTS (SELECT 1 AS one FROM enabled_modules em WHERE em.project_id = projects.id AND em.name='issue_tracking'))) AND (queries.visibility <> 0 OR queries.user_id = 16) AND "queries"."project_id" IS NULL ORDER BY "queries"."name" ASC, "queries"."id" ASC
34
[2022-08-03 00:19:31.401 +0300] (7919)  INFO index.html.erb:77:in `block in _app_views_issues_index_html_erb__4153315814078676898_83140'   Rendered issues/_sidebar.html.erb (1.6ms)
35
[2022-08-03 00:19:31.402 +0300] (7919)  INFO issues_controller.rb:54:in `block (2 levels) in index'   Rendered issues/index.html.erb within layouts/base (41.2ms)
36
[2022-08-03 00:19:31.404 +0300] (7919) DEBUG user.rb:185:in `mail'   EmailAddress Load (0.2ms)  SELECT  "email_addresses".* FROM "email_addresses" WHERE "email_addresses"."user_id" = $1 AND "email_addresses"."is_default" = $2 LIMIT $3  [["user_id", 16], ["is_default", true], ["LIMIT", 1]]
37
[2022-08-03 00:19:31.406 +0300] (7919) DEBUG application_helper.rb:510:in `projects_for_jump_box'   Project Load (0.4ms)  SELECT "projects"."id", "projects"."name", "projects"."identifier", "projects"."lft", "projects"."rgt" FROM "projects" INNER JOIN "members" ON "projects"."id" = "members"."project_id" WHERE "members"."user_id" = $1 AND "projects"."status" != $2 AND "projects"."status" = $3  [["user_id", 16], ["status", 9], ["status", 1]]
38
[2022-08-03 00:19:31.407 +0300] (7919) DEBUG project_jump_box.rb:41:in `bookmarked_projects'   Project Load (0.2ms)  SELECT "projects".* FROM "projects" WHERE 1=0 AND (projects.status <> 9)
39
[2022-08-03 00:19:31.408 +0300] (7919) DEBUG project_jump_box.rb:35:in `recently_used_projects'   Project Load (0.5ms)  SELECT "projects".* FROM "projects" WHERE "projects"."id" IN ($1, $2, $3) AND (projects.status <> 9)  [["id", 61], ["id", 132], ["id", 170]]
40
[2022-08-03 00:19:31.413 +0300] (7919) DEBUG redmine.rb:238:in `block (2 levels) in <top (required)>'   EnabledModule Exists (0.4ms)  SELECT  1 AS one FROM "enabled_modules" WHERE "enabled_modules"."project_id" IN (SELECT "projects"."id" FROM "projects" WHERE (projects.status <> 9)) AND "enabled_modules"."name" = $1 LIMIT $2  [["name", "issue_tracking"], ["LIMIT", 1]]
41
[2022-08-03 00:19:31.414 +0300] (7919) DEBUG redmine.rb:248:in `block (2 levels) in <top (required)>'   EnabledModule Exists (0.3ms)  SELECT  1 AS one FROM "enabled_modules" WHERE "enabled_modules"."project_id" IN (SELECT "projects"."id" FROM "projects" WHERE (projects.status <> 9)) AND "enabled_modules"."name" = $1 LIMIT $2  [["name", "time_tracking"], ["LIMIT", 1]]
42
[2022-08-03 00:19:31.415 +0300] (7919) DEBUG redmine.rb:259:in `block (2 levels) in <top (required)>'   EnabledModule Exists (0.4ms)  SELECT  1 AS one FROM "enabled_modules" WHERE "enabled_modules"."project_id" IN (SELECT "projects"."id" FROM "projects" WHERE (projects.status <> 9)) AND "enabled_modules"."name" = $1 LIMIT $2  [["name", "gantt"], ["LIMIT", 1]]
43
[2022-08-03 00:19:31.416 +0300] (7919) DEBUG redmine.rb:269:in `block (2 levels) in <top (required)>'   EnabledModule Exists (0.4ms)  SELECT  1 AS one FROM "enabled_modules" WHERE "enabled_modules"."project_id" IN (SELECT "projects"."id" FROM "projects" WHERE (projects.status <> 9)) AND "enabled_modules"."name" = $1 LIMIT $2  [["name", "calendar"], ["LIMIT", 1]]
44
[2022-08-03 00:19:31.417 +0300] (7919) DEBUG redmine.rb:278:in `block (2 levels) in <top (required)>'   EnabledModule Exists (0.4ms)  SELECT  1 AS one FROM "enabled_modules" WHERE "enabled_modules"."project_id" IN (SELECT "projects"."id" FROM "projects" WHERE (projects.status <> 9)) AND "enabled_modules"."name" = $1 LIMIT $2  [["name", "news"], ["LIMIT", 1]]
45
[2022-08-03 00:19:31.417 +0300] (7919)  INFO  Completed 200 OK in 85734ms (Views: 52.2ms | ActiveRecord: 85652.5ms)
46

    
(1-1/2)