Bug #9016

Fact import code consumes lot of memory

Added by Ohad Levy almost 3 years ago. Updated 6 months ago.

Status:Closed
Priority:Normal
Assigned To:Lukas Zapletal
Category:Importers
Target version:Team Daniel - iteration 3
Difficulty: Bugzilla link:1440825
Found in release: Pull request:https://github.com/theforeman/foreman/pull/3667, https://github.com/theforeman/foreman/pull/3896
Story points-
Velocity based estimate-
Release1.14.0Release relationshipAuto

Description

This was initially reported on discovery process, but I located performance bottleneck in fact importing.

When importing a large set of hosts, the avg response time is high:

Completed 201 Created in 8403.7ms (Views: 3.6ms | ActiveRecord: 0.0ms)
Completed 201 Created in 3546.0ms (Views: 27.6ms | ActiveRecord: 0.0ms)
Completed 201 Created in 3260.2ms (Views: 3.4ms | ActiveRecord: 0.0ms)
Completed 201 Created in 5449.5ms (Views: 3.1ms | ActiveRecord: 0.0ms)
Completed 201 Created in 5356.3ms (Views: 3.5ms | ActiveRecord: 0.1ms)
Completed 201 Created in 8333.2ms (Views: 3.7ms | ActiveRecord: 0.1ms)
Completed 201 Created in 5271.3ms (Views: 3.2ms | ActiveRecord: 0.1ms)
Completed 201 Created in 8462.4ms (Views: 3.2ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4223.7ms (Views: 3.2ms | ActiveRecord: 0.2ms)
Completed 201 Created in 8827.6ms (Views: 3.9ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4510.4ms (Views: 3.1ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4038.9ms (Views: 2.9ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4075.4ms (Views: 3.2ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4007.8ms (Views: 4.5ms | ActiveRecord: 0.2ms)
Completed 201 Created in 3886.1ms (Views: 3.6ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4845.1ms (Views: 3.5ms | ActiveRecord: 0.2ms)
Completed 201 Created in 4626.0ms (Views: 3.6ms | ActiveRecord: 0.1ms)
Completed 201 Created in 4751.8ms (Views: 3.7ms | ActiveRecord: 0.1ms)

Observation, the O(n) depends on amount of facts reported. These are performance tests on production installation of Satellite 6.2 RC1 (roughly Foreman 1.11) with five concurrent CURL processes in loop registering discovery hosts (it calls facts import basically):

With 10 facts:

2016-07-21 13:06:20 [app] [I] Completed 201 Created in 386ms (Views: 2.0ms | ActiveRecord: 66.4ms)
2016-07-21 13:06:20 [app] [I] Completed 201 Created in 353ms (Views: 1.9ms | ActiveRecord: 68.8ms)
2016-07-21 13:06:21 [app] [I] Completed 201 Created in 360ms (Views: 2.1ms | ActiveRecord: 72.6ms)
2016-07-21 13:06:21 [app] [I] Completed 201 Created in 316ms (Views: 1.7ms | ActiveRecord: 58.7ms)
2016-07-21 13:06:21 [app] [I] Completed 201 Created in 366ms (Views: 2.0ms | ActiveRecord: 68.5ms)
2016-07-21 13:06:21 [app] [I] Completed 201 Created in 331ms (Views: 1.7ms | ActiveRecord: 59.6ms)
2016-07-21 13:06:22 [app] [I] Completed 201 Created in 322ms (Views: 1.7ms | ActiveRecord: 58.8ms)
2016-07-21 13:06:22 [app] [I] Completed 201 Created in 380ms (Views: 1.9ms | ActiveRecord: 85.0ms)
2016-07-21 13:06:22 [app] [I] Completed 201 Created in 337ms (Views: 2.2ms | ActiveRecord: 61.8ms)
2016-07-21 13:06:22 [app] [I] Completed 201 Created in 385ms (Views: 2.4ms | ActiveRecord: 77.8ms)
2016-07-21 13:06:22 [app] [I] Completed 201 Created in 442ms (Views: 1.7ms | ActiveRecord: 70.3ms)
2016-07-21 13:06:22 [app] [I] Completed 201 Created in 388ms (Views: 1.9ms | ActiveRecord: 86.2ms)
2016-07-21 13:06:23 [app] [I] Completed 201 Created in 349ms (Views: 2.1ms | ActiveRecord: 66.0ms)
2016-07-21 13:06:23 [app] [I] Completed 201 Created in 346ms (Views: 1.7ms | ActiveRecord: 74.3ms)
2016-07-21 13:06:23 [app] [I] Completed 201 Created in 364ms (Views: 1.8ms | ActiveRecord: 61.6ms)
2016-07-21 13:06:23 [app] [I] Completed 201 Created in 488ms (Views: 2.4ms | ActiveRecord: 80.6ms)
2016-07-21 13:06:24 [app] [I] Completed 201 Created in 485ms (Views: 2.7ms | ActiveRecord: 74.3ms)
2016-07-21 13:06:24 [app] [I] Completed 201 Created in 577ms (Views: 2.8ms | ActiveRecord: 76.6ms)

With 500 facts:

2016-07-21 13:09:29 [app] [I] Completed 201 Created in 1666ms (Views: 1.8ms | ActiveRecord: 376.8ms)
2016-07-21 13:09:30 [app] [I] Completed 201 Created in 1688ms (Views: 1.8ms | ActiveRecord: 380.2ms)
2016-07-21 13:09:31 [app] [I] Completed 201 Created in 1775ms (Views: 1.8ms | ActiveRecord: 387.7ms)
2016-07-21 13:09:32 [app] [I] Completed 201 Created in 1732ms (Views: 1.8ms | ActiveRecord: 436.5ms)
2016-07-21 13:09:33 [app] [I] Completed 201 Created in 1767ms (Views: 1.8ms | ActiveRecord: 410.1ms)
2016-07-21 13:09:34 [app] [I] Completed 201 Created in 1749ms (Views: 1.9ms | ActiveRecord: 404.3ms)
2016-07-21 13:09:34 [app] [I] Completed 201 Created in 1777ms (Views: 1.9ms | ActiveRecord: 416.1ms)
2016-07-21 13:09:35 [app] [I] Completed 201 Created in 1702ms (Views: 1.7ms | ActiveRecord: 398.9ms)
2016-07-21 13:09:36 [app] [I] Completed 201 Created in 1650ms (Views: 1.8ms | ActiveRecord: 358.3ms)
2016-07-21 13:09:37 [app] [I] Completed 201 Created in 1647ms (Views: 1.8ms | ActiveRecord: 330.7ms)
2016-07-21 13:09:38 [app] [I] Completed 201 Created in 1761ms (Views: 1.8ms | ActiveRecord: 404.6ms)
2016-07-21 13:09:39 [app] [I] Completed 201 Created in 1629ms (Views: 1.8ms | ActiveRecord: 347.6ms)
2016-07-21 13:09:40 [app] [I] Completed 201 Created in 1735ms (Views: 1.8ms | ActiveRecord: 420.6ms)
2016-07-21 13:09:40 [app] [I] Completed 201 Created in 1616ms (Views: 2.1ms | ActiveRecord: 329.6ms)
2016-07-21 13:09:41 [app] [I] Completed 201 Created in 1792ms (Views: 2.0ms | ActiveRecord: 418.4ms)
2016-07-21 13:09:42 [app] [I] Completed 201 Created in 1794ms (Views: 1.8ms | ActiveRecord: 454.0ms)
2016-07-21 13:09:43 [app] [I] Completed 201 Created in 1779ms (Views: 2.5ms | ActiveRecord: 424.4ms)
2016-07-21 13:09:44 [app] [I] Completed 201 Created in 1735ms (Views: 1.8ms | ActiveRecord: 411.7ms)
2016-07-21 13:09:45 [app] [I] Completed 201 Created in 1912ms (Views: 1.9ms | ActiveRecord: 461.2ms)
2016-07-21 13:09:46 [app] [I] Completed 201 Created in 1781ms (Views: 1.9ms | ActiveRecord: 463.5ms)
2016-07-21 13:09:47 [app] [I] Completed 201 Created in 1682ms (Views: 1.7ms | ActiveRecord: 377.2ms)
2016-07-21 13:09:47 [app] [I] Completed 201 Created in 1645ms (Views: 2.2ms | ActiveRecord: 336.1ms)
2016-07-21 13:09:49 [app] [I] Completed 201 Created in 1843ms (Views: 2.0ms | ActiveRecord: 435.9ms)
2016-07-21 13:09:49 [app] [I] Completed 201 Created in 1900ms (Views: 2.3ms | ActiveRecord: 470.4ms)
2016-07-21 13:09:51 [app] [I] Completed 201 Created in 1841ms (Views: 1.7ms | ActiveRecord: 406.0ms)
2016-07-21 13:09:51 [app] [I] Completed 201 Created in 1949ms (Views: 2.5ms | ActiveRecord: 443.3ms)
2016-07-21 13:09:52 [app] [I] Completed 201 Created in 1773ms (Views: 1.8ms | ActiveRecord: 453.9ms)

And with 1000 facts reported in each call:

2016-07-21 13:11:12 [app] [I] Completed 201 Created in 3104ms (Views: 1.8ms | ActiveRecord: 764.2ms)
2016-07-21 13:11:14 [app] [I] Completed 201 Created in 3133ms (Views: 1.9ms | ActiveRecord: 667.6ms)
2016-07-21 13:11:15 [app] [I] Completed 201 Created in 3113ms (Views: 2.0ms | ActiveRecord: 732.8ms)
2016-07-21 13:11:17 [app] [I] Completed 201 Created in 3139ms (Views: 1.8ms | ActiveRecord: 752.2ms)
2016-07-21 13:11:18 [app] [I] Completed 201 Created in 3015ms (Views: 2.2ms | ActiveRecord: 730.2ms)
2016-07-21 13:11:20 [app] [I] Completed 201 Created in 3139ms (Views: 1.9ms | ActiveRecord: 646.0ms)
2016-07-21 13:11:21 [app] [I] Completed 201 Created in 2877ms (Views: 1.8ms | ActiveRecord: 620.0ms)
2016-07-21 13:11:23 [app] [I] Completed 201 Created in 3011ms (Views: 2.4ms | ActiveRecord: 611.1ms)
2016-07-21 13:11:24 [app] [I] Completed 201 Created in 3007ms (Views: 1.8ms | ActiveRecord: 614.2ms)
2016-07-21 13:11:26 [app] [I] Completed 201 Created in 3163ms (Views: 1.9ms | ActiveRecord: 661.9ms)
2016-07-21 13:11:27 [app] [I] Completed 201 Created in 2923ms (Views: 1.8ms | ActiveRecord: 641.7ms)
2016-07-21 13:11:29 [app] [I] Completed 201 Created in 2982ms (Views: 2.1ms | ActiveRecord: 657.7ms)
2016-07-21 13:11:30 [app] [I] Completed 201 Created in 3018ms (Views: 1.8ms | ActiveRecord: 706.9ms)
2016-07-21 13:11:32 [app] [I] Completed 201 Created in 3212ms (Views: 1.8ms | ActiveRecord: 726.9ms)
2016-07-21 13:11:33 [app] [I] Completed 201 Created in 2931ms (Views: 2.1ms | ActiveRecord: 602.9ms)
2016-07-21 13:11:35 [app] [I] Completed 201 Created in 2991ms (Views: 2.5ms | ActiveRecord: 638.4ms)
2016-07-21 13:11:36 [app] [I] Completed 201 Created in 3016ms (Views: 1.8ms | ActiveRecord: 728.8ms)
2016-07-21 13:11:39 [app] [I] Completed 201 Created in 3170ms (Views: 1.7ms | ActiveRecord: 744.1ms)
2016-07-21 13:11:40 [app] [I] Completed 201 Created in 3312ms (Views: 1.9ms | ActiveRecord: 823.8ms)
2016-07-21 13:11:42 [app] [I] Completed 201 Created in 3198ms (Views: 1.7ms | ActiveRecord: 820.9ms)

Width of fact name or value does not matter, what's the bottleneck is our code that does fact importing. It does this in a loop over all facts merging them with database. We need to optimize that.


Related issues

Related to Foreman - Bug #16576: Structured facts importer is extremely slow Closed 09/15/2016
Related to Salt - Bug #17202: Tests failing again against foreman core Closed 11/03/2016
Related to Foreman - Bug #18561: Slow exec of delete_removed_facts on MySQL 5.6 Closed 02/19/2017

Associated revisions

Revision 46e1ea9f
Added by Lukas Zapletal about 1 year ago

Fixes #9016 - improved fact loading performance

This change improves fact loading performance by order of magnitude on
SQLite mostly thanks to explicit transaction. An extra optimization was
done for the most important "update" method call which is mostly used
during fact uploads.

Updating of 500 existing facts is faster from 14.8 seconds to 2.7
seconds with this patch.

Revision b3ffcbd4
Added by Dominic Cleal about 1 year ago

refs #9016 - remove unnecessary condition, fix comment location

Corrects rubocop error raised for one-line conditional.

History

#1 Updated by Lukas Zapletal over 1 year ago

  • Category set to Discovery plugin
  • Priority changed from Normal to High
  • Target version set to Plugin 6.0

#2 Updated by Lukas Zapletal over 1 year ago

  • Subject changed from bulk discovery fact reporting should be async to Discovery fact reporting is slow

I'd rather investigate why this is slow than making it async.

#3 Updated by Lukas Zapletal over 1 year ago

  • Project changed from Discovery to Foreman
  • Subject changed from Discovery fact reporting is slow to Fact import code is O(n^2)
  • Description updated (diff)
  • Category deleted (Discovery plugin)
  • Priority changed from High to Normal
  • Target version deleted (Plugin 6.0)

Switching from Discovery to Core.

#4 Updated by Lukas Zapletal over 1 year ago

I got same results with both one and two passenger worker processes.

#5 Updated by Dominic Cleal over 1 year ago

  • Category set to Importers

#6 Updated by Lukas Zapletal over 1 year ago

I tried to add FactImporter#import! method into SQL transaction and there was no measurable difference.

I think the problem is that facts are stored in normal form, which is in this case sub-optimal. Most fact names are short enough to be able to create string index though them, I'd simply store them in denormalized table:

id, host_id, name, value

#7 Updated by Ohad Levy over 1 year ago

Lukas Zapletal wrote:

I think the problem is that facts are stored in normal form, which is in this case sub-optimal. Most fact names are short enough to be able to create string index though them, I'd simply store them in denormalized table:

id, host_id, name, value

Are you suggesting to searlize the values? in that case that would break search.

#8 Updated by Lukas Zapletal over 1 year ago

Are you suggesting to searlize the values? in that case that would break search.

Well that's just an idea. If there's no way of integrating this with scoped_search, I think we should be able to optimize some portions using plain SQL batch inserts:

https://joinhandshake.com/engineering/2016/01/26/quickly-inserting-thousands-of-records-in-rails.html

I am not sure how folks like plain SQL in our codebase.

#9 Updated by Lukas Zapletal over 1 year ago

Another idea is to provide a separate stored procedure for PostgreSQL that will do the same thing but faster by order of magnitude. And an optional flag (opt-in) to use the procedure instead normal selects+inserts.

#10 Updated by Lukas Zapletal over 1 year ago

And third option is to use https://github.com/zdennis/activerecord-import gem which will allow bulk INSERTs for all our supported database using a simple DSL. It's a new dependency and it won't be as fast as the stored procedure as we need to iterate in Ruby, search for existing objects and add results into insert/update array, but will will be able to do insert/update in one DB call. Delete can be done via one call today already.

#11 Updated by Marek Hulán over 1 year ago

(Edit: I apologize, I accidentally edited instead replied, now fixed -- lzap)

I don't. It's easy to introduce some MySQL vs PostgreSQL vs sqlite incompatibility.

I'm also not sure whether this is the bottleneck, there are not that many values in facter output. But I admit I did zero research. Why are you against background processing? I know it would have to be optional since there are potentially users that rely on facts in matchers so it influences the ENC output but I think it would solve performance issues for most of users. Don't get me wrong, I don't object optimization, it's just that I'd like to see facts being optionally imported on background too.

#12 Updated by The Foreman Bot over 1 year ago

  • Status changed from New to Ready For Testing
  • Assigned To set to Lukas Zapletal
  • Pull request https://github.com/theforeman/foreman/pull/3667 added

#13 Updated by Lukas Zapletal over 1 year ago

Marek Hulán wrote:

I'm also not sure whether this is the bottleneck, there are not that many values in facter >output.

Let me surprise you, DELL PowerEdge R810 is a standard server and it provides 260 facts. The more CPU cores you have the more facts (each core reports several values).

Why are you against background processing?

Because I prefer to write clean code than making workarounds around this. A web server must handle a JSON request of 1000 keys within milliseconds and not 2 seconds (my measurements from today). Without any workarounds.

Anyway, I slightly improved the area in the patch, it's not ideal, we could go further perhaps. Ohad, the initial paste you sent - was it PostgreSQL or MySQL instance?

#14 Updated by Marek Hulán over 1 year ago

All I'm saying is that we should perhaps combine both. And if we can't optimize further without pure SQL I think that would justify it, I'd just like to avoid it until really necessary.

#15 Updated by Daniel Lobato Garcia about 1 year ago

  • Target version set to Team Daniel - iteration 1

#16 Updated by Daniel Lobato Garcia about 1 year ago

  • Target version changed from Team Daniel - iteration 1 to Team Daniel - iteration 2

#17 Updated by Jon McKenzie about 1 year ago

Just chiming in here. The current fact importer (we use 1.10, but it seems similar in 1.11 and 1.12) creates a huge performance penalty in one of our environments, which has thousands of EC2 hosts. In EC2, as you may know, Facter creates lots of dynamic facts with names such as "ec2_network_interfaces_macs_00:00:00:00:00:00_device_number" (where the MAC address changes for each instance) -- it has lots of these types of dynamic facts. In the current implementation, when a host runs an import, the importer builds up a list of all unique fact names (cf https://github.com/theforeman/foreman/blob/c696f740e9b8551e0acbf9db9ec390294ee71560/app/services/fact_importer.rb#L73). In an EC2 environment, this means iterating through hundreds of thousands of rows and loading that data into memory for each new fact import. When you have 100-200 hosts checking in in any given 5 minutes period, this basically brings Foreman to a crawl. If I log into Postgres and look at the active queries in our environment, 9 times out of 10 all of the active connections are these select queries building up lists of fact names.

So, that being said.. can I help in any way? Or are there any mitigation suggestions?

I thought about simply disabling fact imports in the node.rb script as a temporary measure, but our ENC data uses smart parameters which rely on fact data.

#18 Updated by Jon McKenzie about 1 year ago

We ended up having to patch the fact importer code on all of our Foreman app servers. This could probably be a bit more concise, and is developed against 1.10.1, but here's our patch:

https://github.com/jcmcken/foreman/commit/efff5947167a2c58e46c91d345667f632ee07cda

#19 Updated by Lukas Zapletal about 1 year ago

We are almost done with our patch to solve this problem. Testing with production data would be very valuable for us. Could you please patch your instance and show us some numbers:

https://github.com/theforeman/foreman/pull/3667/files

#20 Updated by Jon McKenzie about 1 year ago

Hi Lukas,

I can tell by reading this code that this isn't going to solve our issue, or at the very least will cause different types of problems. Specifically this line is problematic, because it's still loading every fact name into memory (even fact names that the host doing the importing doesn't even have). We have 1,000,000+ distinct fact names in our fact_names table. Loading a hash of that size into memory for every host import (when we have 100-200 hosts checking in every 5 minutes) is very resource intensive.

#21 Updated by Jon McKenzie about 1 year ago

Changing this on L.81 in your referenced PR...

fact_names = fact_name_class.where(:type => fact_name_class).index_by(&:name)

...to this...

fact_names = fact_name_class.where(:type => fact_name_class, :name => facts_to_create).index_by(&:name)

...would I think solve our issue vis the large numbers of fact names.

#22 Updated by Lukas Zapletal about 1 year ago

Changing this on L.81 in your referenced PR...

Actually, I completely removed the list. I see no point in keeping this list in memory at all. We can just create fact names as we go. See the updated PR.

#23 Updated by Lukas Zapletal about 1 year ago

  • Subject changed from Fact import code is O(n^2) to Fact import code consumes lot of memory

I am changing the title because the patch does not solve complexity of our code (lots of Rails allocations because the logic is stored in Rails). We are able to rewrite some portions to consume less memory, but if we want to achieve better throughput, we'd need to change the design of our importers significantly.

#24 Updated by Jon McKenzie about 1 year ago

Lukas Zapletal wrote:

Changing this on L.81 in your referenced PR...

Actually, I completely removed the list. I see no point in keeping this list in memory at all. We can just create fact names as we go. See the updated PR.

Works for me. Thanks for this!

#25 Updated by Daniel Lobato Garcia about 1 year ago

  • Target version changed from Team Daniel - iteration 2 to Team Daniel - iteration 3

#26 Updated by Lukas Zapletal about 1 year ago

  • Related to Bug #16576: Structured facts importer is extremely slow added

#27 Updated by Lukas Zapletal about 1 year ago

  • Status changed from Ready For Testing to Closed
  • % Done changed from 0 to 100

#28 Updated by Dominic Cleal about 1 year ago

  • Release set to 1.14.0

#29 Updated by The Foreman Bot about 1 year ago

  • Pull request https://github.com/theforeman/foreman/pull/3896 added

#30 Updated by Stephen Benjamin 12 months ago

  • Related to Bug #17202: Tests failing again against foreman core added

#31 Updated by Michael Moll 8 months ago

  • Related to Bug #18561: Slow exec of delete_removed_facts on MySQL 5.6 added

#32 Updated by Chris Roberts 6 months ago

  • Bugzilla link set to 1440825

Also available in: Atom PDF