QueryRecorder masks N+1 queries that are cached
I was looking at profiles for /api/v4/projects/13083/issues?per_page=100
in http://profiler.gitlap.com/20180518/505c725f-f40d-4bdb-ae91-a83dca7a944f.txt.gz and trying to understand why it totally missed this repeated stream of N+1 queries:
D, [2018-05-19T02:21:19.705060 #123864] DEBUG -- : CACHE (0.3ms) SELECT "projects".* FROM "projects" WHERE "projects"."id" = 13083 LIMIT 1 [["id", 13083]]
D, [2018-05-19T02:21:19.714581 #123864] DEBUG -- : ↳ ee/app/models/ee/issue.rb:68:in `supports_weight?'
D, [2018-05-19T02:21:19.714839 #123864] DEBUG -- : ↳ ee/lib/ee/api/entities.rb:56:in `block (2 levels) in <module:IssueBasic>'
D, [2018-05-19T02:21:19.715148 #123864] DEBUG -- : ↳ ee/lib/gitlab/jira/middleware.rb:15:in `call'
D, [2018-05-19T02:21:19.732358 #123864] DEBUG -- : CACHE (0.3ms) SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 9970 LIMIT 1 [["id", 9970]]
D, [2018-05-19T02:21:19.741905 #123864] DEBUG -- : ↳ ee/app/models/ee/project.rb:521:in `load_licensed_feature_available'
D, [2018-05-19T02:21:19.742187 #123864] DEBUG -- : ↳ ee/app/models/ee/project.rb:511:in `block (2 levels) in licensed_feature_available?'
D, [2018-05-19T02:21:19.742437 #123864] DEBUG -- : ↳ ee/app/models/ee/project.rb:515:in `licensed_feature_available?'
D, [2018-05-19T02:21:19.742655 #123864] DEBUG -- : ↳ ee/app/models/ee/project.rb:235:in `feature_available?'
D, [2018-05-19T02:21:19.742891 #123864] DEBUG -- : ↳ ee/app/models/ee/issue.rb:68:in `supports_weight?'
D, [2018-05-19T02:21:19.743110 #123864] DEBUG -- : ↳ ee/lib/ee/api/entities.rb:56:in `block (2 levels) in <module:IssueBasic>'
While these cached queries seem innocent, they actually lead to significant performance issues elsewhere. For example, see http://profiler.gitlap.com/20180518/505c725f-f40d-4bdb-ae91-a83dca7a944f.html.gz, 22% of the load time is spent just calling Issue#supports_weight?
on 100 issues for the same project:
If we had simply preloaded the project, this problem would have gone away:
iff --git a/lib/api/issues.rb b/lib/api/issues.rb
index 6d75e8817c..b64f465ce5 100644
--- a/lib/api/issues.rb
+++ b/lib/api/issues.rb
@@ -16,7 +16,7 @@ module API
args[:scope] = args[:scope].underscore if args[:scope]
issues = IssuesFinder.new(current_user, args).execute
- .preload(:assignees, :labels, :notes, :timelogs)
+ .preload(:assignees, :labels, :notes, :timelogs, :project)
issues.reorder(args[:order_by] => args[:sort])
end
The N+1 spec didn't catch this because these queries were cached.
Ideally we should just get rid of the QueryRecorder code that ignores cached queries, but an interim step may be to provide an option to toggle this on or off.
/cc: @jamedjo, @smcgivern, @yorickpeterse