Bug #24712
Foreman (1.18?) slow API call against fact_values endpoint
Description
Problem:
Foreman API call after upgrade now takes over 8 seconds which previously was under 1 second, I’m not sure if it’s isolated to the fact_values endpoint, yet.
Tomer Brisker asked me to link a ref to another ticket which he thinks is the cause of this issue: https://projects.theforeman.org/issues/21871
Expected outcome:
Previous releases (1.16.*) returned the results in under 1 second
Foreman and Proxy versions:
Debian Stretch with:
ii foreman 1.18.1-1 amd64 Systems management web interface
ii foreman-cli 1.18.1-1 all metapackage providing hammer CLI for Foreman
ii foreman-debug 1.18.1-1 all provides support utility foreman-debug.
ii foreman-libvirt 1.18.1-1 all metapackage providing libvirt dependencies for Foreman
ii foreman-postgresql 1.18.1-1 all metapackage providing PostgreSQL dependencies for Foreman
ii foreman-proxy 1.18.1-1 all RESTful proxies for DNS, DHCP, TFTP, and Puppet
ii ruby-foreman-deface 1.2.0-1 all Foreman Deface Plugin Dependency
ii ruby-foreman-dhcp-browser 0.0.8-1 all Foreman DHCP browser Plugin
ii ruby-foreman-discovery 12.0.2-1 all Foreman Discovery Plugin
ii ruby-foreman-hooks 0.3.14-1 all Foreman Hooks Plugin
ii ruby-foreman-templates 6.0.3-1 all Foreman Templates Plugin
ii ruby-hammer-cli-foreman 0.13.0-1 all Foreman commands for Hammer
Other relevant data:
Example curl command:
time curl -k -u admin:admin -H “Accept: version=2, application/json” -H “Content-Type: application/json” -X GET “https://theforeman.example.net/api/fact_values?per_page=5&search=name=ipmi_macaddress”
{
“total”: 432656,
“subtotal”: 5,
“page”: 1,
“per_page”: 5,
“search”: “name=ipmi_macaddress”,
“sort”: {
“by”: null,
“order”: null
},
“results”: {“kr1000.example.net”:{“ipmi_macaddress”:“00:25:90:0b:24:dc”},“kr110e.example.net”:{“ipmi_macaddress”:“00:25:90:3f:4c:2c”},“kr1207.example.net”:{“ipmi_macaddress”:“00:25:90:4d:15:49”},“rb1404.example.net”:{“ipmi_macaddress”:“00:25:90:52:48:67”},“kr1204.example.net”:{“ipmi_macaddress”:“00:25:90:6d:f8:cf”}}
}
real 0m10.244s
user 0m0.028s
sys 0m0.000s
I had some issues getting SQL debug logging working - but when I did, I got this in the logs ( I snipped the list of IDs in the last query as it was many, many lines!):
2018-08-22T10:02:45 [I|app|ddca7] Processing by Api::V2::FactValuesController#index as JSON
2018-08-22T10:02:45 [I|app|ddca7] Parameters: {“per_page”=>“5”, “search”=>“name=ipmi_macaddress”, “apiv”=>“v2”, “fact_value”=>{}}
2018-08-22T10:02:45 [D|sql|ddca7] Setting Load (0.6ms) SELECT “settings”.* FROM “settings” WHERE “settings”.“name” = $1 ORDER BY “settings”.“name” ASC LIMIT $2 [[“name”, “authorize_login_delegation_api”], [“LIMIT”, 1]]
2018-08-22T10:02:45 [D|sql|ddca7] User Load (0.3ms) SELECT “users”.* FROM “users” WHERE “users”.“lower_login” = $1 LIMIT $2 [[“lower_login”, “admin”], [“LIMIT”, 1]]
2018-08-22T10:02:45 [D|sql|ddca7] PersonalAccessToken Load (0.5ms) SELECT “personal_access_tokens”.* FROM “personal_access_tokens” WHERE “personal_access_tokens”.“revoked” = $1 AND (expires_at >= ‘2018-08-22 10:02:45.931186’ OR expires_at IS NULL) AND “personal_access_tokens”.“user_id” = 3 AND “personal_access_tokens”.“token” = $2 LIMIT $3 [[“revoked”, “f”], [“token”, “7ea0bb43659d7fe52511a090115b3048b0fa14fe”], [“LIMIT”, 1]]
2018-08-22T10:02:45 [D|sql|ddca7] AuthSource Load (0.5ms) SELECT “auth_sources”.* FROM “auth_sources” WHERE “auth_sources”.“id” = $1 LIMIT $2 [[“id”, 1], [“LIMIT”, 1]]
2018-08-22T10:02:45 [D|sql|ddca7] (0.2ms) SELECT “users”.“id” FROM “users”
2018-08-22T10:02:45 [D|sql|ddca7] CACHE (0.0ms) SELECT “users”.“id” FROM “users”
2018-08-22T10:02:45 [D|sql|ddca7] CACHE User Load (0.0ms) SELECT “users”.* FROM “users” WHERE “users”.“lower_login” = $1 LIMIT $2 [[“lower_login”, “admin”], [“LIMIT”, 1]]
2018-08-22T10:02:45 [D|sql|ddca7] Authenticated user admin against INTERNAL authentication source
2018-08-22T10:02:45 [D|sql|ddca7] User Load (0.3ms) SELECT “users”.* FROM “users” WHERE “users”.“lower_login” = $1 LIMIT $2 [[“lower_login”, “foreman_admin”], [“LIMIT”, 1]]
2018-08-22T10:02:45 [I|app|ddca7] Current user: foreman_admin (administrator)
2018-08-22T10:02:45 [D|sql|ddca7] (0.2ms) SELECT auth_sources.id FROM “auth_sources” WHERE “auth_sources”.“type” IN (‘AuthSourceHidden’)
2018-08-22T10:02:45 [D|sql|ddca7] User Load (0.3ms) SELECT “users”.* FROM “users” WHERE (“users”.“auth_source_id” NOT IN (2)) AND “users”.“lower_login” = $1 LIMIT $2 [[“lower_login”, “admin”], [“LIMIT”, 1]]
2018-08-22T10:02:45 [I|app|ddca7] Authorized user admin(Admin User)
2018-08-22T10:02:45 [I|app|ddca7] Current user: admin (administrator)
2018-08-22T10:02:45 [D|sql|ddca7] (0.1ms) BEGIN
2018-08-22T10:02:45 [D|sql|ddca7] SQL (0.2ms) DELETE FROM “sessions” WHERE “sessions”.“id” = $1 “id”, 21634422
2018-08-22T10:02:45 [D|sql|ddca7] (0.3ms) COMMIT
2018-08-22T10:02:45 [D|sql|ddca7] Setting Load (0.5ms) SELECT “settings”.* FROM “settings” WHERE “settings”.“name” = $1 ORDER BY “settings”.“name” ASC LIMIT $2 [[“name”, “idle_timeout”], [“LIMIT”, 1]]
2018-08-22T10:02:46 [D|sql|ddca7] SQL (3.6ms) SELECT “fact_values”.“id” AS t0_r0, “fact_values”.“value” AS t0_r1, “fact_values”.“fact_name_id” AS t0_r2, “fact_values”.“host_id” AS t0_r3, “fact_values”.“updated_at” AS t0_r4, “fact_values”.“created_at” AS t0_r5, “fact_names”.“id” AS t1_r0, “fact_names”.“name” AS t1_r1, “fact_names”.“updated_at” AS t1_r2, “fact_names”.“created_at” AS t1_r3, “fact_names”.“compose” AS t1_r4, “fact_names”.“short_name” AS t1_r5, “fact_names”.“type” AS t1_r6, “fact_names”.“ancestry” AS t1_r7 FROM “fact_values” INNER JOIN “fact_names” ON “fact_names”.“id” = “fact_values”.“fact_name_id” WHERE (fact_names.name <> ‘_timestamp’) AND ((“fact_names”.“name” = ‘ipmi_macaddress’)) ORDER BY “fact_values”.“value” ASC NULLS FIRST LIMIT $1 OFFSET $2 [[“LIMIT”, 5], [“OFFSET”, 0]]
2018-08-22T10:02:46 [D|sql|ddca7] Host::Base Load (0.5ms) SELECT “hosts”.* FROM “hosts” WHERE “hosts”.“id” IN (1218, 517, 612, 687, 586)
2018-08-22T10:02:46 [D|sql|ddca7] Host::Managed Load (0.4ms) SELECT “hosts”.* FROM “hosts” WHERE “hosts”.“type” IN (‘Host::Managed’) AND “hosts”.“id” IN (1218, 517, 612, 687, 586)
2018-08-22T10:02:46 [I|app|ddca7] Rendering api/v2/fact_values/index.json.rabl within api/v2/layouts/index_layout
2018-08-22T10:02:46 [I|app|ddca7] Rendered api/v2/fact_values/index.json.rabl within api/v2/layouts/index_layout (0.8ms)
2018-08-22T10:02:46 [D|sql|ddca7] (135.5ms) SELECT “fact_values”.“id” FROM “fact_values”
2018-08-22T10:02:46 [D|sql|ddca7] CACHE (0.0ms) SELECT “fact_values”.“id” FROM “fact_values”
2018-08-22T10:02:54 [D|sql|ddca7] (2122.9ms) SELECT COUNT FROM “fact_values” WHERE “fact_values”.“id” IN (199210, 199211, 199212, 199213, 199214, 199215, 199216, 199217, 199218, 199219, 199220, 199221, 199222, 199223, 199224, 199225, 199226, 199227, 199228, 199229,.,.,.)
2018-08-22T10:02:54 [I|app|ddca7] Completed 200 OK in 8837ms (Views: 6473.6ms | ActiveRecord: 2280.8ms)
Related issues
Associated revisions
History
#1
Updated by Luke Alexander over 4 years ago
- Related to Bug #21871: [Hammer] PG::Error while non-admin user listing entities in default location added
#2
Updated by Luke Alexander over 4 years ago
Luke Alexander wrote:
Problem:
Foreman API call after upgrade now takes over 8 seconds which previously was under 1 second, I’m not sure if it’s isolated to the fact_values endpoint, yet.
Tomer Brisker asked me to link a ref to another ticket which he thinks is the cause of this issue: https://projects.theforeman.org/issues/21871
I noticed a section in the commit: https://github.com/theforeman/foreman/pull/5071/commits/ff3ea42394e9201ec25bef4a41388709509a844f which looked interesting, I reverted that change and then re-ran the curl:
time curl -k -u admin:admin -H "Accept: version=2, application/json" -H "Content-Type: application/json" -X GET "https://theforeman.example.net/api/fact_values?per_page=5&search=name=ipmi_macaddress" { "total": 407845, "subtotal": 5, "page": 1, "per_page": 5, "search": "name=ipmi_macaddress", "sort": { "by": null, "order": null }, "results": {"kr1000.example.net":{"ipmi_macaddress":"00:25:90:0b:24:dc"},"kr110e.example.net":{"ipmi_macaddress":"00:25:90:3f:4c:2c"},"kr1207.example.net":{"ipmi_macaddress":"00:25:90:4d:15:49"},"rb1404.example.net":{"ipmi_macaddress":"00:25:90:52:48:67"},"kr1204.example.net":{"ipmi_macaddress":"00:25:90:6d:f8:cf"}} } real 0m0.166s user 0m0.024s sys 0m0.004s
#3
Updated by Daniel Helgenberger over 4 years ago
I can confirm this issue. An icinga2 check querying facts takes:
4.67 s
After reverting #21871:
0.59s
I have several checks running, using search and dashboard methods. Only the fact method was affected.
#4
Updated by Tomer Brisker over 4 years ago
- Found in Releases 1.18.0, 1.18.1, 1.19.0-RC1, 1.19.0-RC2, 1.19.0-RC3 added
#5
Updated by Tomer Brisker over 4 years ago
- Bugzilla link set to 1622343
#6
Updated by The Foreman Bot over 4 years ago
- Assignee set to Tomer Brisker
- Status changed from New to Ready For Testing
- Pull request https://github.com/theforeman/foreman/pull/5993 added
#7
Updated by Luke Alexander over 4 years ago
Yep, this PR looks good to me, I've applied the diff and the api response is back to similar response time as prior to the upgrade... Thanks for this! Tomer Brisker
#8
Updated by Tomer Brisker over 4 years ago
- Fixed in Releases 1.19.0 added
#9
Updated by The Foreman Bot over 4 years ago
- Pull request https://github.com/theforeman/foreman/pull/6011 added
#10
Updated by Tomer Brisker over 4 years ago
- Status changed from Ready For Testing to Closed
Applied in changeset e65038056d56257b32d20b61e2c683fe4b8f3c3a.
#11
Updated by Ondřej Pražák over 4 years ago
- Fixed in Releases 1.18.2, 1.20.0 added
#12
Updated by Tomer Brisker over 4 years ago
- Fixed in Releases deleted (
1.20.0)
#13
Updated by Tomer Brisker over 4 years ago
- Related to Bug #25487: 'subtotal' is incorrect in API responses added
Fixes #24712 - Fix performance regression on API
This commit improves on the fix in 01809199 which has been found to
cause significant performance regressions. It also adds several other
improvements to the API scope performance, the most significant one
being only checking that the scope work in `parent_scope` rather than
loading all of it into an in-memory array which can be very heavy.
The original fix was needed because of a bug in the way Rails merges
scopes, which will be fixed in Rails 5.2 by
https://github.com/rails/rails/pull/29413. Once we upgrade to Rails 5.2
the workaround can be removed since it still comes with worse
performance compared to the previous implementation.