Hey All,
Currently running foreman 1.18.2 and seeing DB load (Mariadb) much higher than I did before upgrading. On an 8 core database server with 64 gb of RAM server 13,000 clients every 30 minutes our average load has gone from 3-4 to 8-16. This is causing occasional “backups” and nearly 100% cpu use of the database server 24/7.
I have a feeling this is related to: Bug #24712: Foreman (1.18?) slow API call against fact_values endpoint - Foreman but while that handles the API regression (and fixes it) - i believe I’m seeing the same behavior isolated to Report Uploads only.
Checking my Database using a “show full processlist” I always see between 2 and 12 “SELECT fact_values
.* FROM fact_values
…” LONG queries - all taking many seconds (10-20+) to process. An example is:
SELECT fact_values
.* FROM fact_values
WHERE fact_values
.host_id
= 44801 AND fact_values
.fact_name_id
IN (2, 3, 4, 5, 6, 7, 8, 9, 10, 12, 13, 14, 15, 16, 17, 18, 20, 22, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 45, 46, 47, 48, 49, 50, 52, 53, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 112, 114, 115, 116, 127, 128, 129, 130, 131, 141, 151, 331, 841, 5751, 5761, 36501, 42811, 42821, 42831, 42841, 42851, 42861, 42871, 42881, 42891, 48231, 76951, 76961, 76971, 76981, 77991, 78001, 202051, 202061, 231371, 231641, 232031, 240751, 240761, 273391, 273401, 273411, 273421, 273431, 273441, 273451, 273461, 273851, 273861, 274501, 274511, 274541, 274551, 274561, 311241, 311271, 336201, 336211, 343761, 347411, 393391, 395801, 435811, 498961, 616241, 634521, 634531, 634541, 634551, 634561, 640131, 640141, 730791, 767451, 774601, 797831, 797841, 797851, 797861, 797871, 797881, 797891, 797901, 797911, 797921, 797931, 797941, 797951, 797961, 797971, 797981, 797991, 798001, 798011, 798021, 798031, 798041, 798051, 798061, 798071, 798081, 798091, 798101, 798111, 798121, 798131, 798141, 798151, 798161, 798261, 798271, 798281, 798291, 798301, 798311, 798321, 798331, 798341, 798351, 798361, 798621, 798631, 798641, 798651, 798661, 798671, 798681, 798691, 798701, 798711, 798721, 798731, 798741, 798751, 798761, 798771, 798781, 798791, 798801, 798811, 798821, 798831, 798841, 798851, 824341, 824351, 1003471, 1008891, 1008901, 1008911, 1008921, 1008931, 1008941, 1008951, 1008961, 1008971, 1008981, 1008991, 1009001, 1009011, 1009021, 1009031, 1009041, 1009051, 1009061, 1009111, 1009121, 1009131, 1149511, 1149521, 1149531, 1149541, 1149551, 1279811, 1279821, 1279831, 1279841, 1279851, 1279861, 1279871, 1279911, 1279921, 1279931, 1279941, 1279951, 1279961, 1279971, 1279981, 1279991, 1280001, 1280011, 1280021, 1280031, 1280041, 1280051, 1280061, 1280071, 1280081, 1280091, 1280101, 1280111, 1280121, 1280131, 1280141, 1280151, 1280161, 1280171, 1280181, 1280191, 1280201, 1280211, 1280221, 1280231, 1280241, 1280251, 1280261, 1280271, 1280281, 1280301, 1280311, 1280321, 1280331, 1280341, 1280351, 1280361, 1280371, 1280381, 1280391, 1280401, 1280411, 1280421, 1280431, 1280441, 1280451, 1280461, 1280471, 1280481, 1280491, 1280501, 1280511, 1280521, 1280531, 1280541, 1280551, 1280561, 1280571, 1280581, 1280591, 1280601, 1280611, 1280621, 1280631, 1280641, 1280651, 1280661, 1280671, 1280681, 1280691, 1280701, 1280711, 1280721, 1280731, 1280741, 1280751, 1280761, 1280771, 1280781, 1280791, 1280801, 1280811, 1280821, 1280831, 1280841, 1280851, 1280861, 1280871, 1280991, 1281001, 1281011, 1281021, 1281031, 1281041, 1281051, 1281061, 1281071, 1281081, 1281091, 1281101, 1281111, 1281121, 1281131, 1281141, 1281151, 1281161, 1281171, 1281181, 1281191, 1281201, 1281211, 1281221, 1281231, 1281241, 1281251, 1281261, 1281271, 1281281, 1281291, 1281301, 1281311, 1281541, 1281551, 1281561, 1281571, 1281581, 1281591, 1281601, 1281611, 1281621, 1281631, 1281641, 1281651, 1281661, 1281671, 1281681, 1281691, 1281701, 1281711, 1281721, 1281731, 1281741, 1281751, 1281761, 1281771, 1281781, 1281791, 1281801, 1281811, 1281821, 1281831, 1281841, 1281851, 1281861, 1281871, 1281881, 1281891, 1281901, 1281911, 1281921, 1281931, 1281941, 1281951, 1281961, 1281971, 1282011, 1282051, 1282061, 1282071, 1282081, 1282091, 1282101, 1282111, 1282121, 1282131, 1282141, 1282151, 1282161, 1282171, 1282191, 1282311, 1282321, 1282331, 1282341, 1282351, 1282371, 1282391, 1282401, 1282411, 1282421, 1282461, 1282491, 1282501, 1282511, 1282521, 1282531, 1282541, 1282551, 1282561, 1282571, 1282581, 1282591, 1282601, 1282671, 1282681, 1282691, 1282701, 1282711, 1282721, 1282731, 1282741, 1282751, 1282761, 1282771, 1282781, 1282791, 1282801, 1282811, 1282821, 1282831, 1282841, 1282851, 1282861, 1282871, 1282881, 1282891, 1282901, 1282911, 1282921, 1282931, 1282941, 1282951, 1283081, 1283091, 1283101, 1283111, 1283121, 1283131, 1283141, 1283151, 1283161, 1283171, 1283181, 1283191, 1283201, 1283211, 1283221, 1283231, 1283241, 1283251, 1283261, 1283271, 1283281, 1283291, 1283401, 1283411, 1283421, 1283431, 1283441, 1299801, 1299811, 1299821, 1299831, 1299841, 1299851, 1299861, 1299871, 1299881, 1299891, 1299901, 1299911, 1299921, 1299931, 1299941, 1299951, 1299961, 1299971, 1299981, 1299991, 1300001, 1300011, 1300021, 1300031, 1300041, 1300051, 1300171, 1300181, 1300191, 1300201, 1300211, 1367251, 1367261, 1367271, 1367281, 1367291, 1367301, 1367311, 1367321, 1367331, 1367341, 1367351, 1371776, 1374385, 1374386, 1374387, 1374388, 1374389, 1374390, 1589616, 1589617, 1589618, 1589619, 1589620, 1589621, 1589622, 1964413, 2799272, 3164276, 4522965, 5941761, 5941762, 7340338, 7349082, 7349093, 7349094, 7349095, 7349096, 7349097, 7349098, 7349099, 7349100, 7349101, 7349102, 7349103, 7349104, 7499774, 7499776, 7500214, 7500215, 7572161) ORDER BY fact_values
.id
ASC LIMIT 1000
These mirror what is reflected in Bug #24712: Foreman (1.18?) slow API call against fact_values endpoint - Foreman
I can manually re-run this query on my end and confirm its super slow and takes “forever” (10+ seconds) to return. Simplifying it to return all facts a-la: SELECT fact_values
.* FROM fact_values
WHERE fact_values
.host_id
= 44801 returns almost instantly for comparison.
Tracking down this host_id it always corresponds to a puppet run that happened - kicking off the query. Production.log output of an example of that below:
2018-09-26T11:24:56 [I|app|] Started GET “/node/idpdsn0w1.mydomain.com?format=yml” for 10.80.11.15 at 2018-09-26 11:24:56 -0400
2018-09-26T11:24:56 [I|app|fa6bd] Processing by HostsController#externalNodes as YML
2018-09-26T11:24:56 [I|app|fa6bd] Parameters: {“name”=>“idpdsn0w1.mydomain.com”}
2018-09-26T11:24:56 [I|app|fa6bd] Current user: foreman_api_admin (administrator)
2018-09-26T11:24:57 [I|app|fa6bd] Rendering text template
2018-09-26T11:24:57 [I|app|fa6bd] Rendered text template (0.0ms)
2018-09-26T11:24:57 [I|app|fa6bd] Completed 200 OK in 654ms (Views: 0.7ms | ActiveRecord: 222.1ms)
2018-09-26T11:25:03 [I|app|74f8b] Processing by Api::V2::HostsController#facts as JSON
2018-09-26T11:25:03 [I|app|74f8b] Parameters: {“facts”=>"[FILTERED]", “name”=>“idpdsn0w1.mydomain.com”, “certname”=>“idpdsn0w1.mydomain.com”, “apiv”=>“v2”, “host”=>{“certname”=>“idpdsn0w1.mydomain.com”, “name”=>“idpdsn0w1.mydomain.com”}}
2018-09-26T11:25:03 [I|app|74f8b] Current user: foreman_api_admin (administrator)
2018-09-26T11:25:30 [I|app|74f8b] Import facts for ‘idpdsn0w1.mydomain.com’ completed. Added: 0, Updated: 25, Deleted 0 facts
2018-09-26T11:25:30 [I|app|74f8b] Completed 201 Created in 26880ms (Views: 8.2ms | ActiveRecord: 25456.2ms)
2018-09-26T11:25:30 [I|app|4f0a6] Processing by HostsController#externalNodes as YML
2018-09-26T11:25:30 [I|app|4f0a6] Parameters: {“name”=>“idpdsn0w1.mydomain.com”}
2018-09-26T11:25:30 [I|app|4f0a6] Current user: foreman_api_admin (administrator)
2018-09-26T11:25:31 [I|app|4f0a6] Rendering text template
2018-09-26T11:25:31 [I|app|4f0a6] Rendered text template (0.0ms)
2018-09-26T11:25:31 [I|app|4f0a6] Completed 200 OK in 545ms (Views: 0.9ms | ActiveRecord: 229.5ms)
2018-09-26T11:25:52 [I|app|5b0ad] Processing by Api::V2::ConfigReportsController#create as JSON
2018-09-26T11:25:52 [I|app|5b0ad] Parameters: {“config_report”=>"[FILTERED]", “apiv”=>“v2”}
2018-09-26T11:25:52 [I|app|5b0ad] Current user: foreman_api_admin (administrator)
2018-09-26T11:25:53 [I|app|5b0ad] Scanning report with: Foreman::PuppetReportScanner, ForemanAnsible::AnsibleReportScanner
2018-09-26T11:25:53 [I|app|5b0ad] Imported report for idpdsn0w1.mydomain.com in 0.19 seconds, status refreshed in 0.06 seconds
2018-09-26T11:25:53 [I|app|5b0ad] Rendering api/v2/config_reports/create.json.rabl
2018-09-26T11:25:53 [I|app|5b0ad] Rendered api/v2/config_reports/create.json.rabl (34.8ms)
2018-09-26T11:25:53 [I|app|5b0ad] Completed 201 Created in 376ms (Views: 19.5ms | ActiveRecord: 212.5ms)
To compare - using the facts endpoint: https://foreman.mydomain.com/api/v2/hosts/idpdsn0w1.mydomain.com/facts returns in <1 second as expected using 1.18.2 - indicating the fix is properly applied and working as expected.
I “believe” based on looking at the Previous fix: Bug #24712: Foreman (1.18?) slow API call against fact_values endpoint - Foreman that this affected the regression in the API endpoint ONLY. and that based on the SQL query im seeing when i do a fact import on report upload, my issue is another manifestation of this specific to report uploads/fact importing.
I would surmise that others are seeing this as well - but it would only really be a “problem” if you have enough clients uploading reports simultaneously to where it can overwhelm your available database resources?
Or I could be totally barking up the wrong tree - but based on what I’m seeing , i feel like I’m at least on the right track…