Add Memoization to LogProxy.prefix results

[NickLaMuro]

This is a more generic form of #17355 that ends up being a little more risky, and doesn't help as well in the specific use case of miq_request_workflow.rb.

It is worth noting, though, that I have see LogProxy#prefix show up a lot in memory profiled results in other situations in the past, so this is a sore spot for extraneous allocations that wouldn't hurt from being addressed platform wide (since we log a lot...). That said, this is something that should more be considered in the future, but not necessarily immediately.

Benchmarks

The benchmark script used here basically runs the following:

ManageIQ::Providers::Vmware::InfraManager::ProvisionWorkflow.new.init_from_dialog

And is targeting a fairly large EMS, with about 600 hosts.

	ms	queries	rows
before	15023	1961	48395
after	13676	1961	48395

Before                                                     After
------                                                     -----

Total allocated: 2069091751 bytes (23226536 objects)   |   Total allocated: 1882630774 bytes (21824382 objects)
                                                       |   
allocated objects by gem                               |   allocated objects by gem
-----------------------------------                    |   -----------------------------------
   9665227  pending                                    |      9665227  pending
   5561668  manageiq/app                               |      5561668  manageiq/app
   3513258  manageiq/lib  <<<<<<<<<<                   |      2512007  activerecord-5.0.7
   2512007  activerecord-5.0.7                         |      2111094  manageiq/lib  <<<<<<<<<<
    861270  activesupport-5.0.7                        |       861280  activesupport-5.0.7
    418737  ancestry-2.2.2                             |       418737  ancestry-2.2.2
    278793  activemodel-5.0.7                          |       278793  activemodel-5.0.7
    178419  ruby-2.3.3/lib                             |       178419  ruby-2.3.3/lib
    165577  arel-7.1.4                                 |       165577  arel-7.1.4
     52875  manageiq-providers-vmware-0be2f13a0dc9     |        52875  manageiq-providers-vmware-0be2f13a0dc9
     14424  fast_gettext-1.2.0                         |        14424  fast_gettext-1.2.0
       ...                                             |          ...

Note: The benchmarks for this change do NOT include the changes from other PRs (#17354 for example). Benchmarks of all changes can be found here.

Links

• Partially addresses https://bugzilla.redhat.com/show_bug.cgi?id=1569626
• Full collection of proposed changes: git compare
• • Document keeping track of overall improvements for this effort: gist
• Related PRs:
  • Prevents N+1 SQL queries in miq_request_workflow.rb #17354
    • Extracted PRs: Add MiqPreloader.polymorphic_preload_for_child_classes #17457, Use MiqPreloader.polymorphic_preload_for_child_classes in RelationshipMixin#fulltree_arranged #17460, Use MiqPreloader/Relationship improvements in MiqRequestWorkflow #17461
  • Memoize _log.prefix calls #17355

[miq-bot]

Checked commit NickLaMuro@cf040e3 with ruby 2.3.3, rubocop 0.52.1, haml-lint 0.20.0, and yamllint 1.10.0
1 file checked, 3 offenses detected

lib/vmdb/logging.rb

• ❗ - Line 4, Col 20 - Style/StructInheritance - Don't extend an instance initialized by Struct.new.
• ❗ - Line 51, Col 52 - Style/EmptyLiteral - Use hash literal {} instead of Hash.new.
• ❗ - Line 55, Col 41 - Style/EmptyLiteral - Use hash literal {} instead of Hash.new.

[NickLaMuro]

@miq-bot assign @gmcculloug
@miq-bot add_label performance

[NickLaMuro]

cc @Fryguy @bdunne incase either of you have an opinion on this.

Also, #17355 is probably what we should favor for this BZ, but put this one together as well to show it does help on it's own.

[bdunne]

I think I prefer #17355

[NickLaMuro]

@bdunne Thanks for merging #17355 !

Just to clarify though:

I think I prefer #17355

Are you saying you would prefer that in the context of the bugfix I am addressing, or period (as in, we should never merge this). I agree with you on the former, but would argue that we should consider this for master at least, though curious if you have any specific objections to that.

[bdunne]

I don't think I'm opposed to building the string cache, but I don't think meth is specific enough key, is it?

[NickLaMuro]

I think it is (incoming long explanation...):

Both the instance and class methods of _log basically are defined on the class level, and so there is a @instance_logger for instance methods and a @_log for class methods (clearly less descriptive of a name...) defined just below all of this code here.
Of what we pass in to it on instantiation, we pass in the klass and separator as effectively constants for that instance.

When generating the prefix string, it takes klass, separator, and meth, and of those three the only thing that is derived in this method is meth, which should work just fine in the cache since it is the only unique thing per instance.

---

The only concern I have is that this is a shared class variable, and there might be some weirdness with threads, but I don't think that should be an issue since they should be basically writing to the same values to the cache regardless... but I might be missing something.

Also, this will now not be garbage collected, so this might add some bloat to the application which we are already guilty of having at this point.