From 9ee8a4413238be9f8abdd4bc9c264e98b398d951 Mon Sep 17 00:00:00 2001 From: Justin Stoller Date: Fri, 20 Sep 2024 14:21:59 -0700 Subject: [PATCH 1/3] (PE-38408) Remove expensive Regexes from puppet profiler Java impl We have triggered a nasty performance regression in the JVM[1] with some of our Regex usage in the MetricsPuppetProfiler (particularly the PuppetDB Patterns). Regardless of the performance regression, our Regex usage is unnecessary and unneedlessly expensive (I believe it was taking up ~3% of samples from JFR in an unrelated support escalation). This patch moves from iterating over all metrics and doing regex matches to pull out only those that match the desired pattern when metrics are requested, to caching references to desired metrics in maps as they are recorded. The keys of these maps should be the same as the match group from the previous patterns. --- .../puppetserver/MetricsPuppetProfiler.java | 125 ++++++++++++++---- 1 file changed, 99 insertions(+), 26 deletions(-) diff --git a/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java b/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java index 32079ee7c..34774ce16 100644 --- a/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java +++ b/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java @@ -5,6 +5,7 @@ import org.apache.commons.lang.StringUtils; import java.util.ArrayList; +import java.util.Arrays; import java.util.HashMap; import java.util.List; import java.util.Map; @@ -21,17 +22,21 @@ public class MetricsPuppetProfiler implements PuppetProfiler { private final MetricRegistry registry; private final Set metric_ids; - private static final Pattern FUNCTION_PATTERN = Pattern.compile(".*\\.functions\\.([\\w\\d_]+)$"); - private static final Pattern RESOURCE_PATTERN = Pattern.compile(".*\\.compiler\\.evaluate_resource\\.([\\w\\d_]+\\[([\\w\\d_]+::)*[\\w\\d_]+\\])$"); - private static final Pattern CATALOG_PATTERN = Pattern.compile(".*\\.compiler\\.(static_compile_postprocessing|static_compile|compile|find_node)$"); - private static final Pattern INLINING_PATTERN = Pattern.compile(".*\\.compiler\\.static_compile_inlining\\.(.*)$"); - private static final Pattern PUPPETDB_PATTERN = Pattern.compile(".*\\.puppetdb\\.(resource\\.search|facts\\.encode|command\\.submit\\.replace facts|catalog\\.munge|command\\.submit\\.replace catalog|report\\.convert_to_wire_format_hash|command\\.submit\\.store report|query)$"); - + private final Map function_timers; + private final Map resource_timers; + private final Map catalog_timers; + private final Map inlining_timers; + private final Map puppetdb_timers; public MetricsPuppetProfiler(String hostname, MetricRegistry registry) { this.hostname = hostname; this.registry = registry; this.metric_ids = Collections.newSetFromMap(new ConcurrentHashMap()); + this.function_timers = new ConcurrentHashMap(); + this.resource_timers = new ConcurrentHashMap(); + this.catalog_timers = new ConcurrentHashMap(); + this.inlining_timers = new ConcurrentHashMap(); + this.puppetdb_timers = new ConcurrentHashMap(); } @Override @@ -43,9 +48,12 @@ public Object start(String message, String[] metric_id) { public void finish(Object context, String message, String[] metric_id) { if (shouldTime(metric_id)) { Long elapsed = System.currentTimeMillis() - (Long)context; - for (Timer t : getTimers(metric_id)) { + Map metricsByID = getOrCreateTimersByIDs(metric_id); + for (Timer t : metricsByID.values()) { t.update(elapsed, TimeUnit.MILLISECONDS); } + + updateMetricsTrackers(metric_id, metricsByID); } } @@ -54,29 +62,105 @@ public Set getAllMetricIds() { } public Map getFunctionTimers() { - return getTimers(FUNCTION_PATTERN); + return this.function_timers; } public Map getResourceTimers() { - return getTimers(RESOURCE_PATTERN); + return this.resource_timers; } public Map getCatalogTimers() { - return getTimers(CATALOG_PATTERN); + return this.catalog_timers; } public Map getInliningTimers() { - return getTimers(INLINING_PATTERN); + return this.inlining_timers; } public Map getPuppetDBTimers() { - return getTimers(PUPPETDB_PATTERN); + return this.puppetdb_timers; } @Override public void shutdown() { } + private List sliceOfArrayToList(String[] idSegments, int lengthOfID) { + // Callers expect a mutable List returned, but Arrays.asList() returns a + // fix length array, which is why we have to create a List and then add to it. + List idList = new ArrayList(); + idList.addAll(Arrays.asList(Arrays.copyOf(idSegments, lengthOfID))); + + return idList; + } + + private String safeGet(String[] collection, int i) { + try { + return collection[i]; + } catch (IndexOutOfBoundsException _ex) { + return ""; + } + } + + private void updateMetricsTrackers(String[] metricId, Map metricsByID) { + String firstElement = safeGet(metricId, 0); + String secondElement = safeGet(metricId, 1); + + if ("functions".equals(firstElement)) { + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 2))); + this.function_timers.put(secondElement, metric); + + } else if ("compiler".equals(firstElement)) { + String thirdElemet = safeGet(metricId, 2); + + if ("evaluate_resource".equals(secondElement)) { + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 3))); + this.resource_timers.put(thirdElemet, metric); + + } else if ("static_compile_inlining".equals(secondElement)) { + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 3))); + this.inlining_timers.put(thirdElemet, metric); + + } else { + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 2))); + this.catalog_timers.put(secondElement, metric); + } + + } else if ("puppetdb".equals(firstElement)) { + if ("query".equals(secondElement)) { + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 2))); + this.puppetdb_timers.put(secondElement, metric); + + } else { + String thirdElemet = safeGet(metricId, 2); + + if ( + ("resource".equals(secondElement) && "search".equals(thirdElemet)) || + ("facts".equals(secondElement) && "encode".equals(thirdElemet)) || + ("catalog".equals(secondElement) && "munge".equals(thirdElemet)) || + ("report".equals(secondElement) && "convert_to_wire_format_hash".equals(thirdElemet)) + ) { + String key = String.join(".", secondElement, thirdElemet); + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 3))); + this.puppetdb_timers.put(key, metric); + + } else if ("command".equals(secondElement) && "submit".equals(thirdElemet)) { + String fourthElement = safeGet(metricId, 3); + + if ( + "store report".equals(fourthElement) || + "replace facts".equals(fourthElement) || + "replace catalog".equals(fourthElement) + ) { + String key = String.join(".", secondElement, thirdElemet, fourthElement); + Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 4))); + this.puppetdb_timers.put(key, metric); + } + } + } + } + } + private boolean shouldTime(String[] metric_id) { if (metric_id == null) { return false; @@ -90,8 +174,8 @@ private boolean shouldTime(String[] metric_id) { return true; } - private List getTimers(String[] metric_id) { - List timers = new ArrayList(); + private Map getOrCreateTimersByIDs(String[] metric_id) { + Map timers = new HashMap(); // If this is turns out to be a performance hit, we could cache these in a // map or something. for (int i = 0; i < metric_id.length; i++) { @@ -101,7 +185,7 @@ private List getTimers(String[] metric_id) { } String metric_name = getMetricName(current_id); registerMetricName(metric_name); - timers.add(registry.timer(metric_name)); + timers.put(metric_name, registry.timer(metric_name)); } return timers; } @@ -114,15 +198,4 @@ private String getMetricName(List metric_id) { private void registerMetricName(String metric_name) { this.metric_ids.add(metric_name); } - - private Map getTimers(Pattern pattern) { - Map rv = new HashMap<>(); - for (String metric_id : this.metric_ids) { - Matcher matcher = pattern.matcher(metric_id); - if (matcher.matches()) { - rv.put(matcher.group(1), registry.timer(metric_id)); - } - } - return rv; - } } From b995e129462bf4ccd6151453b2aabf168f482371 Mon Sep 17 00:00:00 2001 From: Justin Stoller Date: Fri, 27 Sep 2024 10:02:41 -0700 Subject: [PATCH 2/3] (PE-38408) Add additional PuppetDB metrics Based on discussion with Austin Blatt these additional metrics could be helpful in diagnosing issues with PuppetDB. > The reports.process, catalog.save and facts.save metrics would likely be > useful as they are the highest level metrics closest to "how long did the > puppetdb terminus take?". > > puppetdb.payload.format would be good to include as well in case our json > conversion is slow. We do have to do some string manipulation there, so it > isn't just Ruby's to_json function. > > I'm less familiar with the terminus's use for querying, but I imagine > puppetdb.query, puppetdb.facts.find, and puppetdb.facts.search would be > good to include assuming those terminus functions are used somewhere. --- .../puppetlabs/puppetserver/MetricsPuppetProfiler.java | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java b/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java index 34774ce16..8b32a731b 100644 --- a/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java +++ b/src/java/com/puppetlabs/puppetserver/MetricsPuppetProfiler.java @@ -136,9 +136,11 @@ private void updateMetricsTrackers(String[] metricId, Map metrics if ( ("resource".equals(secondElement) && "search".equals(thirdElemet)) || - ("facts".equals(secondElement) && "encode".equals(thirdElemet)) || - ("catalog".equals(secondElement) && "munge".equals(thirdElemet)) || - ("report".equals(secondElement) && "convert_to_wire_format_hash".equals(thirdElemet)) + ("payload".equals(secondElement) && "format".equals(thirdElemet)) || + // Set.of would be preferrable but 7.x still support Java 8, which does not have Set.of + ("facts".equals(secondElement) && Arrays.asList("save", "find", "search", "encode").contains(thirdElemet)) || + ("catalog".equals(secondElement) && Arrays.asList("save", "munge").contains(thirdElemet)) || + ("report".equals(secondElement) && Arrays.asList("convert_to_wire_format_hash", "process").contains(thirdElemet)) ) { String key = String.join(".", secondElement, thirdElemet); Timer metric = metricsByID.get(getMetricName(sliceOfArrayToList(metricId, 3))); From f85021c4c0bde3dff31ac74a456abe8e5f0ebfc2 Mon Sep 17 00:00:00 2001 From: Justin Stoller Date: Fri, 27 Sep 2024 11:37:36 -0700 Subject: [PATCH 3/3] (maint) Address new clj-kondo issues clj-kondo version 2024.03.05 fixed a bug which suppressed the :java-static-field-call warning in some cases. Linting is now erroring in CI and this patch should resolve that issue. --- .../puppetlabs/services/jruby/jruby_metrics_core.clj | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/clj/puppetlabs/services/jruby/jruby_metrics_core.clj b/src/clj/puppetlabs/services/jruby/jruby_metrics_core.clj index 6fdd44ba4..16606e075 100644 --- a/src/clj/puppetlabs/services/jruby/jruby_metrics_core.clj +++ b/src/clj/puppetlabs/services/jruby/jruby_metrics_core.clj @@ -269,7 +269,7 @@ (do (.update wait-timer (- (System/currentTimeMillis) (:time ta)) - (TimeUnit/MILLISECONDS)) + TimeUnit/MILLISECONDS) (swap! requested-instances dissoc requested-event)) (log/warn (trs "Unable to find request event for borrowed JRuby instance: {0}" event)))) @@ -281,8 +281,8 @@ (if-let [ta (get @borrowed-instances worker-id)] (let [elapsed-time (- (System/currentTimeMillis) (:time ta)) per-reason-timer (timer-for-borrow-reason metrics ta)] - (.update borrow-timer elapsed-time (TimeUnit/MILLISECONDS)) - (.update per-reason-timer elapsed-time (TimeUnit/MILLISECONDS)) + (.update borrow-timer elapsed-time TimeUnit/MILLISECONDS) + (.update per-reason-timer elapsed-time TimeUnit/MILLISECONDS) (MDC/put "jruby.borrow-time" (Long/toString elapsed-time)) (swap! borrowed-instances dissoc worker-id)) (log/warn (trs "JRuby instance ''{0}'' returned, but no record of when it was borrowed!" worker-id))))) @@ -314,7 +314,7 @@ (do (.update lock-wait-timer (- (System/currentTimeMillis) (:time lock-request)) - (TimeUnit/MILLISECONDS)) + TimeUnit/MILLISECONDS) (swap! lock-requests assoc lock-request-id {:state :acquired @@ -330,7 +330,7 @@ (do (.update lock-held-timer (- (System/currentTimeMillis) (:time lock-request)) - (TimeUnit/MILLISECONDS)) + TimeUnit/MILLISECONDS) (swap! lock-requests dissoc lock-request-id)) (log/warn (trs "Lock request ''{0}'' released, but no record of when it was acquired!" lock-request-id)))