From 1275e0027f0db3b7681a460dc8ab4d49d6e9032c Mon Sep 17 00:00:00 2001 From: Jack Berg Date: Thu, 21 Sep 2023 16:38:41 -0500 Subject: [PATCH 1/7] Prototype implementation working --- gradle.properties | 3 + .../agent/service/ServiceManagerImpl.java | 7 + .../SlowTransactionService.java | 122 ++++++++++++++++++ 3 files changed, 132 insertions(+) create mode 100644 newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java diff --git a/gradle.properties b/gradle.properties index 2ac10207fa..9fe94469bd 100644 --- a/gradle.properties +++ b/gradle.properties @@ -6,3 +6,6 @@ newrelicDebug=false org.gradle.jvmargs=-Xmx2048m org.gradle.caching=true file.encoding=utf-8 + +java8=/Users/jberg/.sdkman/candidates/java/8.0.332-zulu/bin/java +jdk8=/Users/jberg/.sdkman/candidates/java/8.0.332-zulu/bin/java diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java index e5fb9ebe5c..e9accadddc 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java @@ -71,6 +71,7 @@ import com.newrelic.agent.service.module.JarCollectorServiceProcessor; import com.newrelic.agent.service.module.JarData; import com.newrelic.agent.service.module.TrackedAddSet; +import com.newrelic.agent.slowtransactions.SlowTransactionService; import com.newrelic.agent.sql.SqlTraceService; import com.newrelic.agent.sql.SqlTraceServiceImpl; import com.newrelic.agent.stats.StatsEngine; @@ -147,6 +148,7 @@ public class ServiceManagerImpl extends AbstractService implements ServiceManage private volatile SpanEventsService spanEventsService; private volatile SourceLanguageService sourceLanguageService; private volatile ExpirationService expirationService; + private volatile SlowTransactionService slowTransactionService; public ServiceManagerImpl(CoreService coreService, ConfigService configService) { super(ServiceManagerImpl.class.getSimpleName()); @@ -231,6 +233,7 @@ protected synchronized void doStart() throws Exception { rpmConnectionService = new RPMConnectionServiceImpl(); transactionService = new TransactionService(); + InfiniteTracing infiniteTracing = buildInfiniteTracing(configService); InfiniteTracingEnabledCheck infiniteTracingEnabledCheck = new InfiniteTracingEnabledCheck(configService); SpanEventCreationDecider spanEventCreationDecider = new SpanEventCreationDecider(configService); @@ -277,6 +280,8 @@ protected synchronized void doStart() throws Exception { harvestService.addHarvestListener(extensionService); harvestService.addHarvestListener(jarCollectorHarvestListener); + slowTransactionService = new SlowTransactionService(); + asyncTxService.start(); threadService.start(); statsService.start(); @@ -309,6 +314,7 @@ protected synchronized void doStart() throws Exception { circuitBreakerService.start(); distributedTraceService.start(); spanEventsService.start(); + slowTransactionService.start(); startServices(); @@ -379,6 +385,7 @@ protected synchronized void doStop() throws Exception { gcService.stop(); distributedTraceService.stop(); spanEventsService.stop(); + slowTransactionService.stop(); stopServices(); } diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java new file mode 100644 index 0000000000..69882d37ac --- /dev/null +++ b/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java @@ -0,0 +1,122 @@ +package com.newrelic.agent.slowtransactions; + +import com.newrelic.agent.ExtendedTransactionListener; +import com.newrelic.agent.Transaction; +import com.newrelic.agent.TransactionData; +import com.newrelic.agent.service.AbstractService; +import com.newrelic.agent.service.ServiceFactory; +import com.newrelic.agent.stats.TransactionStats; +import com.newrelic.agent.util.DefaultThreadFactory; +import com.newrelic.agent.util.StackTraces; +import com.newrelic.api.agent.NewRelic; + +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadInfo; +import java.lang.management.ThreadMXBean; +import java.util.HashMap; +import java.util.HashSet; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; + +public class SlowTransactionService extends AbstractService implements ExtendedTransactionListener { + + private final ScheduledExecutorService scheduler; + private final ConcurrentHashMap openTransactions = new ConcurrentHashMap<>(); + private final Set previouslyReportedTransactions = new HashSet<>(); + private final ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); + + public SlowTransactionService() { + super(SlowTransactionService.class.getSimpleName()); + this.scheduler = Executors.newSingleThreadScheduledExecutor(new DefaultThreadFactory("Slow Transactions Thread", true)); + } + + @Override + public void dispatcherTransactionStarted(Transaction transaction) { + getLogger().info("Transaction started with id " + transaction.getGuid()); + openTransactions.put(transaction.getGuid(), transaction); + } + + @Override + public void dispatcherTransactionCancelled(Transaction transaction) { + getLogger().info("Transaction cancelled with guid " + transaction.getGuid()); + openTransactions.remove(transaction.getGuid()); + } + + @Override + public void dispatcherTransactionFinished(TransactionData transactionData, TransactionStats transactionStats) { + getLogger().info("Transaction finished with guid " + transactionData.getGuid()); + openTransactions.remove(transactionData.getGuid()); + } + + @Override + protected void doStart() throws Exception { + // NewRelic.getAgent().getInsights().recordCustomEvent(); + ServiceFactory.getTransactionService().addTransactionListener(this); + scheduler.scheduleAtFixedRate(this::run, 10, 10, TimeUnit.SECONDS); + } + + @Override + protected void doStop() throws Exception { + ServiceFactory.getTransactionService().removeTransactionListener(this); + } + + @Override + public boolean isEnabled() { + return true; + } + + private void run() { + getLogger().info("Identifying slow threads. Open transactions: " + openTransactions.size()); + long slowThresholdMs = 1000; // Only consider transcations open longer than this + Transaction slowestOpen = null; + long slowestOpenMs = 0; + + // Identify the slowest open transaction we haven't yet reported + for (Transaction transaction : openTransactions.values()) { + // Ignore previously reported transactions + if (previouslyReportedTransactions.contains(transaction.getGuid())) { + continue; + } + + long openMs = System.currentTimeMillis() - transaction.getWallClockStartTimeMs(); + if (openMs > slowThresholdMs && openMs > slowestOpenMs) { + slowestOpen = transaction; + slowestOpenMs = openMs; + } + } + + if (slowestOpen == null) { + getLogger().info("No new slow transactions identified."); + return; + } + + String guid = slowestOpen.getGuid(); + Map attributes = new HashMap<>(); + // General + attributes.put("transaction.guid", guid); + attributes.put("transaction.open_ms", slowestOpenMs); + + // Transaction attributes + slowestOpen.getIntrinsicAttributes().forEach((key, value) -> attributes.put("intrinsic." + key, value)); + slowestOpen.getAgentAttributes().forEach((key, value) -> attributes.put("agent." + key, value)); + slowestOpen.getUserAttributes().forEach((key, value) -> attributes.put("user." + key, value)); + slowestOpen.getErrorAttributes().forEach((key, value) -> attributes.put("error." + key, value)); + + // Initiating thread info + long initiatingThreadId = slowestOpen.getInitiatingThreadId(); + attributes.put("initiating_thread.id", initiatingThreadId); + ThreadInfo threadInfo = threadMXBean.getThreadInfo(initiatingThreadId, 20); + if (threadInfo != null) { + attributes.put("initiating_thread.name", threadInfo.getThreadName()); + attributes.put("initiating_thread.stacktrace", StackTraces.stackTracesToStrings(threadInfo.getStackTrace())); + } + + getLogger().info("Transaction with guid " + guid + " has exceeded slow transaction threshold of " + slowThresholdMs + ", attributes: " + attributes); + NewRelic.getAgent().getInsights().recordCustomEvent("SlowTransaction", attributes); + previouslyReportedTransactions.add(guid); + } +} From b395732e7515c5553f2f795a2a8ee232f09b25aa Mon Sep 17 00:00:00 2001 From: Jack Berg Date: Thu, 21 Sep 2023 16:42:33 -0500 Subject: [PATCH 2/7] Add some notes --- .../agent/slowtransactions/SlowTransactionService.java | 3 +++ 1 file changed, 3 insertions(+) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java index 69882d37ac..c8fb3c9947 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java @@ -94,6 +94,8 @@ private void run() { return; } + // We've identified the slowest open transaction over the threshold. + // Extract some data about its state and emit as event. String guid = slowestOpen.getGuid(); Map attributes = new HashMap<>(); // General @@ -117,6 +119,7 @@ private void run() { getLogger().info("Transaction with guid " + guid + " has exceeded slow transaction threshold of " + slowThresholdMs + ", attributes: " + attributes); NewRelic.getAgent().getInsights().recordCustomEvent("SlowTransaction", attributes); + // TODO: remove old entries after a while to avoid unbounded memory usage previouslyReportedTransactions.add(guid); } } From 6722b40fe7933abd1cadadc278d38a5ccd3ca575 Mon Sep 17 00:00:00 2001 From: Jack Berg Date: Thu, 21 Sep 2023 18:07:20 -0500 Subject: [PATCH 3/7] Report slowest transaction each minute, align with transaction conventions --- .../SlowTransactionService.java | 92 +++++++++++++------ 1 file changed, 63 insertions(+), 29 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java index c8fb3c9947..a7d157066d 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java @@ -1,13 +1,13 @@ package com.newrelic.agent.slowtransactions; import com.newrelic.agent.ExtendedTransactionListener; +import com.newrelic.agent.HarvestListener; import com.newrelic.agent.Transaction; import com.newrelic.agent.TransactionData; import com.newrelic.agent.service.AbstractService; import com.newrelic.agent.service.ServiceFactory; +import com.newrelic.agent.stats.StatsEngine; import com.newrelic.agent.stats.TransactionStats; -import com.newrelic.agent.util.DefaultThreadFactory; -import com.newrelic.agent.util.StackTraces; import com.newrelic.api.agent.NewRelic; import java.lang.management.ManagementFactory; @@ -18,50 +18,54 @@ import java.util.Map; import java.util.Set; import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.Executors; -import java.util.concurrent.ScheduledExecutorService; -import java.util.concurrent.TimeUnit; +import java.util.logging.Level; -public class SlowTransactionService extends AbstractService implements ExtendedTransactionListener { +public class SlowTransactionService extends AbstractService implements ExtendedTransactionListener, HarvestListener { - private final ScheduledExecutorService scheduler; private final ConcurrentHashMap openTransactions = new ConcurrentHashMap<>(); private final Set previouslyReportedTransactions = new HashSet<>(); private final ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); public SlowTransactionService() { super(SlowTransactionService.class.getSimpleName()); - this.scheduler = Executors.newSingleThreadScheduledExecutor(new DefaultThreadFactory("Slow Transactions Thread", true)); } @Override public void dispatcherTransactionStarted(Transaction transaction) { - getLogger().info("Transaction started with id " + transaction.getGuid()); + if (getLogger().isLoggable(Level.FINEST)) { + getLogger().finest("Transaction started with id " + transaction.getGuid()); + } openTransactions.put(transaction.getGuid(), transaction); } @Override public void dispatcherTransactionCancelled(Transaction transaction) { - getLogger().info("Transaction cancelled with guid " + transaction.getGuid()); + if (getLogger().isLoggable(Level.FINEST)) { + getLogger().finest("Transaction cancelled with guid " + transaction.getGuid()); + } openTransactions.remove(transaction.getGuid()); + previouslyReportedTransactions.remove(transaction.getGuid()); } @Override public void dispatcherTransactionFinished(TransactionData transactionData, TransactionStats transactionStats) { - getLogger().info("Transaction finished with guid " + transactionData.getGuid()); + if (getLogger().isLoggable(Level.FINEST)) { + getLogger().finest("Transaction finished with guid " + transactionData.getGuid()); + } openTransactions.remove(transactionData.getGuid()); + previouslyReportedTransactions.remove(transactionData.getGuid()); } @Override protected void doStart() throws Exception { - // NewRelic.getAgent().getInsights().recordCustomEvent(); ServiceFactory.getTransactionService().addTransactionListener(this); - scheduler.scheduleAtFixedRate(this::run, 10, 10, TimeUnit.SECONDS); + ServiceFactory.getHarvestService().addHarvestListener(this); } @Override protected void doStop() throws Exception { ServiceFactory.getTransactionService().removeTransactionListener(this); + ServiceFactory.getHarvestService().removeHarvestListener(this); } @Override @@ -69,9 +73,19 @@ public boolean isEnabled() { return true; } + @Override + public void beforeHarvest(String appName, StatsEngine statsEngine) { + run(); + } + + @Override + public void afterHarvest(String appName) { + } + private void run() { - getLogger().info("Identifying slow threads. Open transactions: " + openTransactions.size()); - long slowThresholdMs = 1000; // Only consider transcations open longer than this + if (getLogger().isLoggable(Level.FINE)) { + getLogger().fine("Identifying slow threads. Open transactions: " + openTransactions.size()); + } Transaction slowestOpen = null; long slowestOpenMs = 0; @@ -83,7 +97,7 @@ private void run() { } long openMs = System.currentTimeMillis() - transaction.getWallClockStartTimeMs(); - if (openMs > slowThresholdMs && openMs > slowestOpenMs) { + if (openMs > slowestOpenMs) { slowestOpen = transaction; slowestOpenMs = openMs; } @@ -98,28 +112,48 @@ private void run() { // Extract some data about its state and emit as event. String guid = slowestOpen.getGuid(); Map attributes = new HashMap<>(); - // General - attributes.put("transaction.guid", guid); - attributes.put("transaction.open_ms", slowestOpenMs); - // Transaction attributes - slowestOpen.getIntrinsicAttributes().forEach((key, value) -> attributes.put("intrinsic." + key, value)); - slowestOpen.getAgentAttributes().forEach((key, value) -> attributes.put("agent." + key, value)); - slowestOpen.getUserAttributes().forEach((key, value) -> attributes.put("user." + key, value)); - slowestOpen.getErrorAttributes().forEach((key, value) -> attributes.put("error." + key, value)); + // Attributes + // Write attributes first so hardcoded attributes are prioritized + attributes.putAll(slowestOpen.getUserAttributes()); + attributes.putAll(slowestOpen.getErrorAttributes()); + attributes.putAll(slowestOpen.getAgentAttributes()); + attributes.putAll(slowestOpen.getIntrinsicAttributes()); + + // General + attributes.put("guid", guid); + attributes.put("name", slowestOpen.getPriorityTransactionName().getName()); + attributes.put("transactionType", slowestOpen.getPriorityTransactionName().getCategory()); + attributes.put("timestamp", slowestOpen.getWallClockStartTimeMs()); + attributes.put("elapsed_ms", slowestOpenMs); // Initiating thread info long initiatingThreadId = slowestOpen.getInitiatingThreadId(); - attributes.put("initiating_thread.id", initiatingThreadId); + attributes.put("thread.id", initiatingThreadId); ThreadInfo threadInfo = threadMXBean.getThreadInfo(initiatingThreadId, 20); if (threadInfo != null) { - attributes.put("initiating_thread.name", threadInfo.getThreadName()); - attributes.put("initiating_thread.stacktrace", StackTraces.stackTracesToStrings(threadInfo.getStackTrace())); + attributes.put("thread.name", threadInfo.getThreadName()); + attributes.put("thread.state", threadInfo.getThreadState().name()); + attributes.put("code.stacktrace", stackTraceString(threadInfo.getStackTrace())); } - getLogger().info("Transaction with guid " + guid + " has exceeded slow transaction threshold of " + slowThresholdMs + ", attributes: " + attributes); + if (getLogger().isLoggable(Level.FINE)) { + getLogger().fine("Slowest open transaction has guid " + guid + " has been open for " + slowestOpenMs + "ms, attributes: " + attributes); + } + // TODO: emit event such that stack trace isn't truncated so early NewRelic.getAgent().getInsights().recordCustomEvent("SlowTransaction", attributes); - // TODO: remove old entries after a while to avoid unbounded memory usage previouslyReportedTransactions.add(guid); } + + private static String stackTraceString(StackTraceElement[] stackTrace) { + if (stackTrace.length == 0) { + return ""; + } + StringBuilder stringBuilder = new StringBuilder(); + stringBuilder.append(stackTrace[0]); + for (int i = 1; i < stackTrace.length; i++) { + stringBuilder.append("\tat ").append(stackTrace[i]); + } + return stringBuilder.toString(); + } } From f99123ad0ecec4ff03a625fc7503ccdd320849e1 Mon Sep 17 00:00:00 2001 From: Jack Berg Date: Thu, 21 Sep 2023 18:08:33 -0500 Subject: [PATCH 4/7] Revert changes to gradle.properties --- gradle.properties | 3 --- 1 file changed, 3 deletions(-) diff --git a/gradle.properties b/gradle.properties index 9fe94469bd..2ac10207fa 100644 --- a/gradle.properties +++ b/gradle.properties @@ -6,6 +6,3 @@ newrelicDebug=false org.gradle.jvmargs=-Xmx2048m org.gradle.caching=true file.encoding=utf-8 - -java8=/Users/jberg/.sdkman/candidates/java/8.0.332-zulu/bin/java -jdk8=/Users/jberg/.sdkman/candidates/java/8.0.332-zulu/bin/java From b58cfd2eb5020bb763475c77972708503d54dd9d Mon Sep 17 00:00:00 2001 From: Jack Berg Date: Wed, 4 Oct 2023 09:25:40 -0500 Subject: [PATCH 5/7] Refine implementation, add configuration, add unit tests --- .../newrelic/agent/config/AgentConfig.java | 3 + .../agent/config/AgentConfigImpl.java | 13 + .../agent/config/SlowTransactionsConfig.java | 25 ++ .../config/SlowTransactionsConfigImpl.java | 41 +++ .../agent/service/ServiceManagerImpl.java | 4 +- .../SlowTransactionService.java | 161 ++++++++--- .../config/SlowTransactionsConfigTest.java | 91 ++++++ .../SlowTransactionServiceTest.java | 269 ++++++++++++++++++ 8 files changed, 558 insertions(+), 49 deletions(-) create mode 100644 newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfig.java create mode 100644 newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfigImpl.java rename newrelic-agent/src/main/java/com/newrelic/agent/{ => service}/slowtransactions/SlowTransactionService.java (50%) create mode 100644 newrelic-agent/src/test/java/com/newrelic/agent/config/SlowTransactionsConfigTest.java create mode 100644 newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfig.java b/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfig.java index 1b96ef399b..c9849fbacb 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfig.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfig.java @@ -350,4 +350,7 @@ public interface AgentConfig extends com.newrelic.api.agent.Config, DataSenderCo CommandParserConfig getCommandParserConfig(); InfiniteTracingConfig getInfiniteTracingConfig(); + + SlowTransactionsConfig getSlowTransactionsConfig(); + } diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfigImpl.java b/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfigImpl.java index a953f21321..ac50bb57c5 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfigImpl.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/config/AgentConfigImpl.java @@ -127,6 +127,7 @@ public class AgentConfigImpl extends BaseConfig implements AgentConfig { public static final String TRANSACTION_EVENTS = "transaction_events"; // replaces analytics_events public static final String TRANSACTION_SEGMENTS = "transaction_segments"; public static final String TRANSACTION_TRACER = "transaction_tracer"; + public static final String SLOW_TRANSACTIONS = "slow_transactions"; // defaults (alphabetized) public static final double DEFAULT_APDEX_T = 1.0; // 1 second @@ -265,6 +266,7 @@ public class AgentConfigImpl extends BaseConfig implements AgentConfig { private final OpenTracingConfig openTracingConfig; private final ReinstrumentConfig reinstrumentConfig; private final TransactionTracerConfigImpl requestTransactionTracerConfig; + private final SlowTransactionsConfig slowTransactionsConfig; private final SpanEventsConfig spanEventsConfig; private final SqlTraceConfig sqlTraceConfig; private final StripExceptionConfig stripExceptionConfig; @@ -367,6 +369,7 @@ private AgentConfigImpl(Map props) { transactionEventsConfig = initTransactionEvents(); commandParserConfig = initCommandParserConfig(); normalizationRuleConfig = new NormalizationRuleConfig(props); + slowTransactionsConfig = initSlowTransactionsConfig(); Map flattenedProps = new HashMap<>(); flatten("", props, flattenedProps); @@ -856,6 +859,11 @@ private CommandParserConfig initCommandParserConfig() { return new CommandParserConfigImpl(nestedProps(CommandParserConfigImpl.ROOT)); } + private SlowTransactionsConfig initSlowTransactionsConfig() { + Map props = nestedProps(SLOW_TRANSACTIONS); + return new SlowTransactionsConfigImpl(props); + } + @Override public long getApdexTInMillis() { return apdexTInMillis; @@ -1067,6 +1075,11 @@ public InfiniteTracingConfig getInfiniteTracingConfig() { return infiniteTracingConfig; } + @Override + public SlowTransactionsConfig getSlowTransactionsConfig() { + return slowTransactionsConfig; + } + private Object findPropertyInMap(String[] property, Map map) { Object result = map; for (String component : property) { diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfig.java b/newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfig.java new file mode 100644 index 0000000000..f117036276 --- /dev/null +++ b/newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfig.java @@ -0,0 +1,25 @@ +/* + * + * * Copyright 2020 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.newrelic.agent.config; + +import com.newrelic.agent.service.slowtransactions.SlowTransactionService; + +public interface SlowTransactionsConfig { + + /** + * True if the {@link SlowTransactionService} is enabled, else false. + */ + boolean isEnabled(); + + /** + * The minimum number of milliseconds a transaction must be running to be + * reported as slow. + */ + long getThresholdMillis(); + +} diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfigImpl.java b/newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfigImpl.java new file mode 100644 index 0000000000..bf318e53cf --- /dev/null +++ b/newrelic-agent/src/main/java/com/newrelic/agent/config/SlowTransactionsConfigImpl.java @@ -0,0 +1,41 @@ +/* + * + * * Copyright 2020 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.newrelic.agent.config; + +import java.util.Map; + +public class SlowTransactionsConfigImpl extends BaseConfig implements SlowTransactionsConfig { + + public static final String ROOT = "slow_transactions"; + public static final String SYSTEM_PROPERTY_ROOT = "newrelic.config." + ROOT + "."; + public static final String ENABLED = "enabled"; + public static final String THRESHOLD = "threshold"; + + public static final boolean DEFAULT_ENABLED = false; + public static final int DEFAULT_THRESHOLD_MILLIS = 1000; + + private final boolean isEnabled; + private final int thresholdMillis; + + public SlowTransactionsConfigImpl(Map pProps) { + super(pProps, SYSTEM_PROPERTY_ROOT); + isEnabled = getProperty(ENABLED, DEFAULT_ENABLED); + thresholdMillis = getIntProperty(THRESHOLD, DEFAULT_THRESHOLD_MILLIS); + } + + @Override + public boolean isEnabled() { + return isEnabled; + } + + @Override + public long getThresholdMillis() { + return thresholdMillis; + } + +} diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java index e9accadddc..a0b311e2f4 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/ServiceManagerImpl.java @@ -71,7 +71,7 @@ import com.newrelic.agent.service.module.JarCollectorServiceProcessor; import com.newrelic.agent.service.module.JarData; import com.newrelic.agent.service.module.TrackedAddSet; -import com.newrelic.agent.slowtransactions.SlowTransactionService; +import com.newrelic.agent.service.slowtransactions.SlowTransactionService; import com.newrelic.agent.sql.SqlTraceService; import com.newrelic.agent.sql.SqlTraceServiceImpl; import com.newrelic.agent.stats.StatsEngine; @@ -280,7 +280,7 @@ protected synchronized void doStart() throws Exception { harvestService.addHarvestListener(extensionService); harvestService.addHarvestListener(jarCollectorHarvestListener); - slowTransactionService = new SlowTransactionService(); + slowTransactionService = new SlowTransactionService(config); asyncTxService.start(); threadService.start(); diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java similarity index 50% rename from newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java rename to newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java index a7d157066d..a36f617f8a 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java @@ -1,20 +1,28 @@ -package com.newrelic.agent.slowtransactions; +package com.newrelic.agent.service.slowtransactions; import com.newrelic.agent.ExtendedTransactionListener; import com.newrelic.agent.HarvestListener; import com.newrelic.agent.Transaction; import com.newrelic.agent.TransactionData; +import com.newrelic.agent.config.AgentConfig; +import com.newrelic.agent.config.SlowTransactionsConfig; +import com.newrelic.agent.model.CustomInsightsEvent; import com.newrelic.agent.service.AbstractService; import com.newrelic.agent.service.ServiceFactory; +import com.newrelic.agent.service.analytics.InsightsService; import com.newrelic.agent.stats.StatsEngine; import com.newrelic.agent.stats.TransactionStats; -import com.newrelic.api.agent.NewRelic; +import com.newrelic.agent.tracing.DistributedTraceServiceImpl; +import com.newrelic.agent.util.StackTraces; +import javax.annotation.Nullable; import java.lang.management.ManagementFactory; import java.lang.management.ThreadInfo; import java.lang.management.ThreadMXBean; +import java.util.Collections; import java.util.HashMap; import java.util.HashSet; +import java.util.List; import java.util.Map; import java.util.Set; import java.util.concurrent.ConcurrentHashMap; @@ -24,10 +32,53 @@ public class SlowTransactionService extends AbstractService implements ExtendedT private final ConcurrentHashMap openTransactions = new ConcurrentHashMap<>(); private final Set previouslyReportedTransactions = new HashSet<>(); - private final ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); + private final ThreadMXBean threadMXBean; - public SlowTransactionService() { + private final boolean isEnabled; + private final long thresholdMillis; + private final int maxStackTraceLines; + + @Nullable + private InsightsService insightsService; + + public SlowTransactionService(AgentConfig agentConfig) { + this(agentConfig, ManagementFactory.getThreadMXBean()); + } + + // Visible for testing + SlowTransactionService(AgentConfig agentConfig, ThreadMXBean threadMXBean) { super(SlowTransactionService.class.getSimpleName()); + SlowTransactionsConfig slowTransactionsConfig = agentConfig.getSlowTransactionsConfig(); + this.isEnabled = slowTransactionsConfig.isEnabled(); + this.thresholdMillis = slowTransactionsConfig.getThresholdMillis(); + this.maxStackTraceLines = agentConfig.getMaxStackTraceLines(); + this.threadMXBean = threadMXBean; + } + + @Override + protected void doStart() throws Exception { + // Short circuit if disabled + if (!isEnabled) { + return; + } + ServiceFactory.getTransactionService().addTransactionListener(this); + ServiceFactory.getHarvestService().addHarvestListener(this); + insightsService = ServiceFactory.getServiceManager().getInsights(); + } + + @Override + protected void doStop() throws Exception { + // Short circuit if disabled + if (!isEnabled) { + return; + } + ServiceFactory.getTransactionService().removeTransactionListener(this); + ServiceFactory.getHarvestService().removeHarvestListener(this); + } + + @Override + public boolean isEnabled() { + return isEnabled; } @Override @@ -56,21 +107,14 @@ public void dispatcherTransactionFinished(TransactionData transactionData, Trans previouslyReportedTransactions.remove(transactionData.getGuid()); } - @Override - protected void doStart() throws Exception { - ServiceFactory.getTransactionService().addTransactionListener(this); - ServiceFactory.getHarvestService().addHarvestListener(this); - } - - @Override - protected void doStop() throws Exception { - ServiceFactory.getTransactionService().removeTransactionListener(this); - ServiceFactory.getHarvestService().removeHarvestListener(this); + // Visible for testing + Map getOpenTransactions() { + return Collections.unmodifiableMap(openTransactions); } - @Override - public boolean isEnabled() { - return true; + // Visible for testing + Set getPreviouslyReportedTransactions() { + return Collections.unmodifiableSet(previouslyReportedTransactions); } @Override @@ -82,12 +126,13 @@ public void beforeHarvest(String appName, StatsEngine statsEngine) { public void afterHarvest(String appName) { } - private void run() { + // Visible for testing + void run() { if (getLogger().isLoggable(Level.FINE)) { getLogger().fine("Identifying slow threads. Open transactions: " + openTransactions.size()); } Transaction slowestOpen = null; - long slowestOpenMs = 0; + long slowestOpenMillis = thresholdMillis; // Identify the slowest open transaction we haven't yet reported for (Transaction transaction : openTransactions.values()) { @@ -97,62 +142,84 @@ private void run() { } long openMs = System.currentTimeMillis() - transaction.getWallClockStartTimeMs(); - if (openMs > slowestOpenMs) { + if (openMs > slowestOpenMillis) { slowestOpen = transaction; - slowestOpenMs = openMs; + slowestOpenMillis = openMs; } } if (slowestOpen == null) { - getLogger().info("No new slow transactions identified."); + getLogger().fine("No new slow transactions identified."); return; } - // We've identified the slowest open transaction over the threshold. - // Extract some data about its state and emit as event. + // Construct and record SlowTransaction event + Map attributes = extractMetadata(slowestOpen, slowestOpenMillis); String guid = slowestOpen.getGuid(); + if (getLogger().isLoggable(Level.FINE)) { + getLogger().fine("Slowest open transaction has guid " + + guid + " has been open for " + slowestOpenMillis + "ms, attributes: " + attributes); + } + if (insightsService != null) { + logger.fine("Sending slow transaction"); + insightsService.storeEvent( + ServiceFactory.getRPMService().getApplicationName(), + new CustomInsightsEvent( + "SlowTransaction", + System.currentTimeMillis(), + attributes, + DistributedTraceServiceImpl.nextTruncatedFloat())); + //insightsService.recordCustomEvent("SlowTransaction", attributes); + } + addReportedTransaction(guid); + } + + // Visible for testing + void addReportedTransaction(String guid) { + previouslyReportedTransactions.add(guid); + } + + // Visible for testing + Map extractMetadata(Transaction transaction, long openMillis) { Map attributes = new HashMap<>(); // Attributes // Write attributes first so hardcoded attributes are prioritized - attributes.putAll(slowestOpen.getUserAttributes()); - attributes.putAll(slowestOpen.getErrorAttributes()); - attributes.putAll(slowestOpen.getAgentAttributes()); - attributes.putAll(slowestOpen.getIntrinsicAttributes()); + attributes.putAll(transaction.getUserAttributes()); + attributes.putAll(transaction.getErrorAttributes()); + attributes.putAll(transaction.getAgentAttributes()); + attributes.putAll(transaction.getIntrinsicAttributes()); // General - attributes.put("guid", guid); - attributes.put("name", slowestOpen.getPriorityTransactionName().getName()); - attributes.put("transactionType", slowestOpen.getPriorityTransactionName().getCategory()); - attributes.put("timestamp", slowestOpen.getWallClockStartTimeMs()); - attributes.put("elapsed_ms", slowestOpenMs); + attributes.put("guid", transaction.getGuid()); + attributes.put("name", transaction.getPriorityTransactionName().getName()); + attributes.put("transactionType", transaction.getPriorityTransactionName().getCategory()); + attributes.put("timestamp", transaction.getWallClockStartTimeMs()); + attributes.put("elapsed_ms", openMillis); // Initiating thread info - long initiatingThreadId = slowestOpen.getInitiatingThreadId(); + long initiatingThreadId = transaction.getInitiatingThreadId(); attributes.put("thread.id", initiatingThreadId); - ThreadInfo threadInfo = threadMXBean.getThreadInfo(initiatingThreadId, 20); + ThreadInfo threadInfo = threadMXBean.getThreadInfo(initiatingThreadId, maxStackTraceLines); if (threadInfo != null) { attributes.put("thread.name", threadInfo.getThreadName()); attributes.put("thread.state", threadInfo.getThreadState().name()); - attributes.put("code.stacktrace", stackTraceString(threadInfo.getStackTrace())); + List scrubbedStackTraceElements = StackTraces.scrubAndTruncate(threadInfo.getStackTrace()); + attributes.put("code.stacktrace", stackTraceString(scrubbedStackTraceElements)); } - if (getLogger().isLoggable(Level.FINE)) { - getLogger().fine("Slowest open transaction has guid " + guid + " has been open for " + slowestOpenMs + "ms, attributes: " + attributes); - } - // TODO: emit event such that stack trace isn't truncated so early - NewRelic.getAgent().getInsights().recordCustomEvent("SlowTransaction", attributes); - previouslyReportedTransactions.add(guid); + new IllegalArgumentException().printStackTrace(); + return attributes; } - private static String stackTraceString(StackTraceElement[] stackTrace) { - if (stackTrace.length == 0) { + private static String stackTraceString(List stackTrace) { + if (stackTrace.isEmpty()) { return ""; } StringBuilder stringBuilder = new StringBuilder(); - stringBuilder.append(stackTrace[0]); - for (int i = 1; i < stackTrace.length; i++) { - stringBuilder.append("\tat ").append(stackTrace[i]); + stringBuilder.append(stackTrace.get(0)).append("\n"); + for (int i = 1; i < stackTrace.size(); i++) { + stringBuilder.append("\tat ").append(stackTrace.get(i)).append("\n"); } return stringBuilder.toString(); } diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/config/SlowTransactionsConfigTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/config/SlowTransactionsConfigTest.java new file mode 100644 index 0000000000..fa0cb1532d --- /dev/null +++ b/newrelic-agent/src/test/java/com/newrelic/agent/config/SlowTransactionsConfigTest.java @@ -0,0 +1,91 @@ +/* + * + * * Copyright 2020 New Relic Corporation. All rights reserved. + * * SPDX-License-Identifier: Apache-2.0 + * + */ + +package com.newrelic.agent.config; + +import com.google.common.collect.ImmutableMap; +import org.junit.Before; +import org.junit.Test; + +import java.util.HashMap; +import java.util.Map; +import java.util.Properties; + +import static com.newrelic.agent.SaveSystemPropertyProviderRule.TestEnvironmentFacade; +import static com.newrelic.agent.SaveSystemPropertyProviderRule.TestSystemProps; +import static com.newrelic.agent.config.SlowTransactionsConfigImpl.DEFAULT_ENABLED; +import static com.newrelic.agent.config.SlowTransactionsConfigImpl.DEFAULT_THRESHOLD_MILLIS; +import static com.newrelic.agent.config.SlowTransactionsConfigImpl.ENABLED; +import static com.newrelic.agent.config.SlowTransactionsConfigImpl.THRESHOLD; +import static org.junit.Assert.assertEquals; + +public class SlowTransactionsConfigTest { + + private final Map configProps = new HashMap<>(); + private SlowTransactionsConfig config; + + @Before + public void setup() { + SystemPropertyFactory.setSystemPropertyProvider(new SystemPropertyProvider( + new TestSystemProps(), + new TestEnvironmentFacade())); + } + + @Test + public void defaultConfigValues() { + config = new SlowTransactionsConfigImpl(configProps); + + assertEquals(DEFAULT_ENABLED, config.isEnabled()); + assertEquals(DEFAULT_THRESHOLD_MILLIS, config.getThresholdMillis()); + } + + @Test + public void configValues() { + // Local config props + configProps.put(ENABLED, !DEFAULT_ENABLED); + configProps.put(THRESHOLD, 5); + + config = new SlowTransactionsConfigImpl(configProps); + + assertEquals(!DEFAULT_ENABLED, config.isEnabled()); + assertEquals(5, config.getThresholdMillis()); + } + + @Test + public void testEnvironmentVariables() { + TestEnvironmentFacade environmentFacade = new TestEnvironmentFacade(ImmutableMap.of( + "NEW_RELIC_SLOW_TRANSACTIONS_ENABLED", String.valueOf(!DEFAULT_ENABLED), + "NEW_RELIC_SLOW_TRANSACTIONS_THRESHOLD", "5" + )); + SystemPropertyFactory.setSystemPropertyProvider(new SystemPropertyProvider( + new TestSystemProps(), + environmentFacade + )); + + config = new SlowTransactionsConfigImpl(configProps); + + assertEquals(!DEFAULT_ENABLED, config.isEnabled()); + assertEquals(5, config.getThresholdMillis()); + } + + @Test + public void testSystemProperties() { + Properties props = new Properties(); + props.setProperty("newrelic.config.slow_transactions.enabled", String.valueOf(!DEFAULT_ENABLED)); + props.setProperty("newrelic.config.slow_transactions.threshold", "5"); + + SystemPropertyFactory.setSystemPropertyProvider(new SystemPropertyProvider( + new TestSystemProps(props), + new TestEnvironmentFacade() + )); + + config = new SlowTransactionsConfigImpl(configProps); + + assertEquals(!DEFAULT_ENABLED, config.isEnabled()); + assertEquals(5, config.getThresholdMillis()); + } +} diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java new file mode 100644 index 0000000000..bdd4fcb4fd --- /dev/null +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java @@ -0,0 +1,269 @@ +package com.newrelic.agent.service.slowtransactions; + +import com.google.common.collect.ImmutableMap; +import com.newrelic.agent.HarvestService; +import com.newrelic.agent.IRPMService; +import com.newrelic.agent.RPMService; +import com.newrelic.agent.RPMServiceManager; +import com.newrelic.agent.Transaction; +import com.newrelic.agent.TransactionData; +import com.newrelic.agent.TransactionService; +import com.newrelic.agent.bridge.TransactionNamePriority; +import com.newrelic.agent.config.AgentConfig; +import com.newrelic.agent.config.ConfigService; +import com.newrelic.agent.config.SlowTransactionsConfig; +import com.newrelic.agent.model.CustomInsightsEvent; +import com.newrelic.agent.service.ServiceFactory; +import com.newrelic.agent.service.ServiceManager; +import com.newrelic.agent.service.analytics.InsightsService; +import com.newrelic.agent.stats.StatsEngine; +import com.newrelic.agent.stats.TransactionStats; +import com.newrelic.agent.transaction.PriorityTransactionName; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.mockito.ArgumentCaptor; +import org.mockito.Mock; +import org.mockito.Mockito; +import org.mockito.junit.MockitoJUnitRunner; + +import java.lang.management.ThreadInfo; +import java.lang.management.ThreadMXBean; +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; +import java.util.UUID; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyLong; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.ArgumentMatchers.same; +import static org.mockito.Mockito.doReturn; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.spy; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; + +@RunWith(MockitoJUnitRunner.class) +public class SlowTransactionServiceTest { + + @Mock + private AgentConfig agentConfig; + + @Mock + private SlowTransactionsConfig slowTransactionsConfig; + + @Mock + private ServiceManager serviceManager; + + @Mock + private TransactionService transactionService; + + @Mock + private HarvestService harvestService; + + @Mock + private InsightsService insightsService; + + @Mock + private ThreadMXBean threadMXBean; + + private SlowTransactionService service; + + @Before + public void setup() throws Exception { + when(agentConfig.getSlowTransactionsConfig()).thenReturn(slowTransactionsConfig); + when(agentConfig.getMaxStackTraceLines()).thenReturn(5); + when(slowTransactionsConfig.isEnabled()).thenReturn(true); + when(slowTransactionsConfig.getThresholdMillis()).thenReturn(1000L); + + when(serviceManager.getTransactionService()).thenReturn(transactionService); + when(serviceManager.getHarvestService()).thenReturn(harvestService); + when(serviceManager.getInsights()).thenReturn(insightsService); + RPMServiceManager rpmServiceManager = mock(RPMServiceManager.class); + when(serviceManager.getRPMServiceManager()).thenReturn(rpmServiceManager); + IRPMService rpmService = mock(IRPMService.class); + when(rpmServiceManager.getRPMService()).thenReturn(rpmService); + when(rpmService.getApplicationName()).thenReturn("App name"); + + ConfigService configService = mock(ConfigService.class); + when(configService.getDefaultAgentConfig()).thenReturn(agentConfig); + when(serviceManager.getConfigService()).thenReturn(configService); + ServiceFactory.setServiceManager(serviceManager); + + service = spy(new SlowTransactionService(agentConfig, threadMXBean)); + service.start(); + } + + @Test + public void startAndStop_Enabled() throws Exception { + Mockito.reset(transactionService, harvestService); + service = new SlowTransactionService(agentConfig); + assertTrue(service.isEnabled()); + + service.start(); + + verify(transactionService).addTransactionListener(service); + verify(harvestService).addHarvestListener(service); + + service.stop(); + + verify(transactionService).removeTransactionListener(service); + verify(harvestService).removeHarvestListener(service); + } + + @Test + public void startAndStop_Disabled() throws Exception { + Mockito.reset(transactionService, harvestService); + when(slowTransactionsConfig.isEnabled()).thenReturn(false); + service = new SlowTransactionService(agentConfig); + + assertFalse(service.isEnabled()); + + service.start(); + + verify(transactionService, never()).addTransactionListener(any()); + verify(harvestService, never()).addHarvestListener(any()); + + service.stop(); + + verify(transactionService, never()).removeTransactionListener(any()); + verify(harvestService, never()).removeHarvestListener(any()); + } + + @Test + public void dispatcherTransactionStartedCancelledFinished() { + String t1Guid = UUID.randomUUID().toString(); + Transaction t1 = mockTransaction(t1Guid, 1); + String t2Guid = UUID.randomUUID().toString(); + Transaction t2 = mockTransaction(t2Guid, 1); + TransactionData t2Data = mock(TransactionData.class); + when(t2Data.getGuid()).thenReturn(t2Guid); + + // Start t1, verify added to open + service.dispatcherTransactionStarted(t1); + assertEquals(ImmutableMap.of(t1Guid, t1), service.getOpenTransactions()); + assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); + + // Start t2, verify added to open + service.dispatcherTransactionStarted(t2); + assertEquals(ImmutableMap.of(t1Guid, t1, t2Guid, t2), service.getOpenTransactions()); + assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); + + // Add t1 and t2 to set of previously reported + service.addReportedTransaction(t1Guid); + service.addReportedTransaction(t2Guid); + + // Cancel t1, verify removed from open and previously reported + service.dispatcherTransactionCancelled(t1); + assertEquals(ImmutableMap.of(t2Guid, t2), service.getOpenTransactions()); + assertEquals(Collections.singleton(t2Guid), service.getPreviouslyReportedTransactions()); + + // Finish t2, verify removed from open and previously reported + service.dispatcherTransactionFinished(t2Data, mock(TransactionStats.class)); + assertEquals(Collections.emptyMap(), service.getOpenTransactions()); + assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); + } + + @Test + public void beforeHarvest() { + service.beforeHarvest("unsued", mock(StatsEngine.class)); + + verify(service, times(1)).run(); + } + + @Test + public void run_NoSlowTransactions() { + // Start t1 and t2, which are both open for < 1000ms when run is called + String t1Guid = UUID.randomUUID().toString(); + Transaction t1 = mockTransaction(t1Guid, 1); + String t2Guid = UUID.randomUUID().toString(); + Transaction t2 = mockTransaction(t2Guid, 1); + service.dispatcherTransactionStarted(t1); + service.dispatcherTransactionStarted(t2); + + service.run(); + + verify(insightsService, never()).recordCustomEvent(any(), any()); + assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); + } + + @Test + public void run_FindsSlowestTransaction() { + // Start t1 and t2, which are both open for > 1000ms when run is called. + // t1 has been open longer and should be reported + String t1Guid = UUID.randomUUID().toString(); + Transaction t1 = mockTransaction(t1Guid, 2000); + String t2Guid = UUID.randomUUID().toString(); + Transaction t2 = mockTransaction(t2Guid, 1500); + service.dispatcherTransactionStarted(t1); + service.dispatcherTransactionStarted(t2); + + Map expectedAttributes = new HashMap<>(); + expectedAttributes.put("guid", t1Guid); + doReturn(expectedAttributes).when(service).extractMetadata(same(t1), anyLong()); + + service.run(); + + ArgumentCaptor eventCaptor = ArgumentCaptor.forClass(CustomInsightsEvent.class); + verify(insightsService).storeEvent(eq("App name"), eventCaptor.capture()); + CustomInsightsEvent event = eventCaptor.getValue(); + assertEquals("SlowTransaction", event.getType()); + assertTrue(event.getTimestamp() > 0); + assertEquals(expectedAttributes, event.getUserAttributesCopy()); + assertTrue(event.getPriority() >= 0); + } + + @Test + public void extractMetadata() { + String t1Guid = UUID.randomUUID().toString(); + Transaction t1 = mockTransaction(t1Guid, 2000); + when(t1.getUserAttributes()).thenReturn(ImmutableMap.of("k1", "v1")); + when(t1.getErrorAttributes()).thenReturn(ImmutableMap.of("k2", "v2")); + when(t1.getAgentAttributes()).thenReturn(ImmutableMap.of("k3", "v3")); + when(t1.getIntrinsicAttributes()).thenReturn(ImmutableMap.of("k4", "v4")); + when(t1.getPriorityTransactionName()).thenReturn(PriorityTransactionName.create("t1 name", "t1 category", TransactionNamePriority.CUSTOM_HIGH)); + + long threadId = 1L; + when(t1.getInitiatingThreadId()).thenReturn(threadId); + ThreadInfo threadInfo = mock(ThreadInfo.class); + when(threadMXBean.getThreadInfo(threadId, 5)).thenReturn(threadInfo); + when(threadInfo.getThreadName()).thenReturn("thread name"); + when(threadInfo.getThreadState()).thenReturn(Thread.State.BLOCKED); + StackTraceElement[] stackTrace = new StackTraceElement[]{ + new StackTraceElement("declaring class 1", "method name 1", "file name 1", 1), + new StackTraceElement("declaring class 2", "method name 2", "file name 2", 2) + }; + when(threadInfo.getStackTrace()).thenReturn(stackTrace); + + Map attributes = service.extractMetadata(t1, 1000); + assertEquals("v1", attributes.get("k1")); + assertEquals("v2", attributes.get("k2")); + assertEquals("v3", attributes.get("k3")); + assertEquals("v4", attributes.get("k4")); + assertEquals(t1Guid, attributes.get("guid")); + assertEquals("t1 name", attributes.get("name")); + assertEquals("t1 category", attributes.get("transactionType")); + assertTrue((long) attributes.get("timestamp") > 0); + assertTrue((long) attributes.get("elapsed_ms") > 0); + assertEquals(1L, attributes.get("thread.id")); + assertEquals("thread name", attributes.get("thread.name")); + assertEquals("BLOCKED", attributes.get("thread.state")); + String expectedStackTrace = "declaring class 1.method name 1(file name 1:1)\n" + + "\tat declaring class 2.method name 2(file name 2:2)\n"; + assertEquals(expectedStackTrace, attributes.get("code.stacktrace")); + } + + private static Transaction mockTransaction(String guid, long startedAtOffsetMillis) { + Transaction transaction = mock(Transaction.class); + when(transaction.getGuid()).thenReturn(guid); + when(transaction.getWallClockStartTimeMs()).thenReturn(System.currentTimeMillis() - startedAtOffsetMillis); + return transaction; + } + +} From 0d3afa8fdc5f7586a541bd9d753307d48a05af28 Mon Sep 17 00:00:00 2001 From: Jack Berg Date: Wed, 4 Oct 2023 14:15:34 -0500 Subject: [PATCH 6/7] Simplify code to avoid sending same transaction multiple times --- .../SlowTransactionService.java | 24 +++---------------- .../SlowTransactionServiceTest.java | 15 +++--------- 2 files changed, 6 insertions(+), 33 deletions(-) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java index a36f617f8a..fdc32c1c2a 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java @@ -21,17 +21,14 @@ import java.lang.management.ThreadMXBean; import java.util.Collections; import java.util.HashMap; -import java.util.HashSet; import java.util.List; import java.util.Map; -import java.util.Set; import java.util.concurrent.ConcurrentHashMap; import java.util.logging.Level; public class SlowTransactionService extends AbstractService implements ExtendedTransactionListener, HarvestListener { private final ConcurrentHashMap openTransactions = new ConcurrentHashMap<>(); - private final Set previouslyReportedTransactions = new HashSet<>(); private final ThreadMXBean threadMXBean; private final boolean isEnabled; @@ -95,7 +92,6 @@ public void dispatcherTransactionCancelled(Transaction transaction) { getLogger().finest("Transaction cancelled with guid " + transaction.getGuid()); } openTransactions.remove(transaction.getGuid()); - previouslyReportedTransactions.remove(transaction.getGuid()); } @Override @@ -104,7 +100,6 @@ public void dispatcherTransactionFinished(TransactionData transactionData, Trans getLogger().finest("Transaction finished with guid " + transactionData.getGuid()); } openTransactions.remove(transactionData.getGuid()); - previouslyReportedTransactions.remove(transactionData.getGuid()); } // Visible for testing @@ -112,11 +107,6 @@ Map getOpenTransactions() { return Collections.unmodifiableMap(openTransactions); } - // Visible for testing - Set getPreviouslyReportedTransactions() { - return Collections.unmodifiableSet(previouslyReportedTransactions); - } - @Override public void beforeHarvest(String appName, StatsEngine statsEngine) { run(); @@ -136,11 +126,6 @@ void run() { // Identify the slowest open transaction we haven't yet reported for (Transaction transaction : openTransactions.values()) { - // Ignore previously reported transactions - if (previouslyReportedTransactions.contains(transaction.getGuid())) { - continue; - } - long openMs = System.currentTimeMillis() - transaction.getWallClockStartTimeMs(); if (openMs > slowestOpenMillis) { slowestOpen = transaction; @@ -171,12 +156,9 @@ void run() { DistributedTraceServiceImpl.nextTruncatedFloat())); //insightsService.recordCustomEvent("SlowTransaction", attributes); } - addReportedTransaction(guid); - } - - // Visible for testing - void addReportedTransaction(String guid) { - previouslyReportedTransactions.add(guid); + // Remove from openTransactions to ensure we don't report the same Transaction + // multiple times + openTransactions.remove(guid); } // Visible for testing diff --git a/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java b/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java index bdd4fcb4fd..2849f6d4e0 100644 --- a/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java @@ -3,7 +3,6 @@ import com.google.common.collect.ImmutableMap; import com.newrelic.agent.HarvestService; import com.newrelic.agent.IRPMService; -import com.newrelic.agent.RPMService; import com.newrelic.agent.RPMServiceManager; import com.newrelic.agent.Transaction; import com.newrelic.agent.TransactionData; @@ -148,26 +147,18 @@ public void dispatcherTransactionStartedCancelledFinished() { // Start t1, verify added to open service.dispatcherTransactionStarted(t1); assertEquals(ImmutableMap.of(t1Guid, t1), service.getOpenTransactions()); - assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); // Start t2, verify added to open service.dispatcherTransactionStarted(t2); assertEquals(ImmutableMap.of(t1Guid, t1, t2Guid, t2), service.getOpenTransactions()); - assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); - // Add t1 and t2 to set of previously reported - service.addReportedTransaction(t1Guid); - service.addReportedTransaction(t2Guid); - - // Cancel t1, verify removed from open and previously reported + // Cancel t1, verify removed from open service.dispatcherTransactionCancelled(t1); assertEquals(ImmutableMap.of(t2Guid, t2), service.getOpenTransactions()); - assertEquals(Collections.singleton(t2Guid), service.getPreviouslyReportedTransactions()); - // Finish t2, verify removed from open and previously reported + // Finish t2, verify removed from open service.dispatcherTransactionFinished(t2Data, mock(TransactionStats.class)); assertEquals(Collections.emptyMap(), service.getOpenTransactions()); - assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); } @Test @@ -190,7 +181,7 @@ public void run_NoSlowTransactions() { service.run(); verify(insightsService, never()).recordCustomEvent(any(), any()); - assertEquals(Collections.emptySet(), service.getPreviouslyReportedTransactions()); + assertEquals(ImmutableMap.of(t1Guid, t1, t2Guid, t2), service.getOpenTransactions()); } @Test From 0412d2a2d16141db04a6405e5e72a20155f4498d Mon Sep 17 00:00:00 2001 From: Jerry Duffy Date: Fri, 6 Oct 2023 15:17:12 -0400 Subject: [PATCH 7/7] s12y metrics; update reference yml file --- .../src/main/java/com/newrelic/agent/MetricNames.java | 4 ++++ .../service/slowtransactions/SlowTransactionService.java | 6 ++++++ newrelic-agent/src/main/resources/newrelic.yml | 6 ++++++ 3 files changed, 16 insertions(+) diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java b/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java index 9a5314c588..ef1568dbc6 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java @@ -492,6 +492,10 @@ public class MetricNames { public static final String SUPPORTABILITY_ERROR_GROUPING_CALLBACK_ENABLED = "Supportability/ErrorGrouping/Callback/enabled"; public static final String SUPPORTABILITY_ERROR_GROUPING_CALLBACK_EXECUTION_TIME = "Supportability/ErrorGrouping/Callback/ExecutionTime"; + // Slow transaction detection + public static final String SUPPORTABILITY_SLOW_TXN_DETECTION_ENABLED = "Supportability/SlowTransactionDetection/enabled"; + public static final String SUPPORTABILITY_SLOW_TXN_DETECTION_DISABLED = "Supportability/SlowTransactionDetection/disabled"; + /** * Utility method for adding supportability metrics to APIs * diff --git a/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java index fdc32c1c2a..2fa676b702 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java @@ -2,6 +2,7 @@ import com.newrelic.agent.ExtendedTransactionListener; import com.newrelic.agent.HarvestListener; +import com.newrelic.agent.MetricNames; import com.newrelic.agent.Transaction; import com.newrelic.agent.TransactionData; import com.newrelic.agent.config.AgentConfig; @@ -14,6 +15,7 @@ import com.newrelic.agent.stats.TransactionStats; import com.newrelic.agent.tracing.DistributedTraceServiceImpl; import com.newrelic.agent.util.StackTraces; +import com.newrelic.api.agent.NewRelic; import javax.annotation.Nullable; import java.lang.management.ManagementFactory; @@ -50,6 +52,10 @@ public SlowTransactionService(AgentConfig agentConfig) { this.thresholdMillis = slowTransactionsConfig.getThresholdMillis(); this.maxStackTraceLines = agentConfig.getMaxStackTraceLines(); this.threadMXBean = threadMXBean; + + NewRelic.getAgent().getMetricAggregator().incrementCounter( + agentConfig.getSlowTransactionsConfig().isEnabled() ? + MetricNames.SUPPORTABILITY_SLOW_TXN_DETECTION_ENABLED : MetricNames.SUPPORTABILITY_SLOW_TXN_DETECTION_DISABLED); } @Override diff --git a/newrelic-agent/src/main/resources/newrelic.yml b/newrelic-agent/src/main/resources/newrelic.yml index 1c09af1f31..5b7289145f 100644 --- a/newrelic-agent/src/main/resources/newrelic.yml +++ b/newrelic-agent/src/main/resources/newrelic.yml @@ -413,6 +413,12 @@ common: &default_settings deserialization: enabled: true + # Slow transaction detection will report an event to New Relic ("SlowTransaction") whenever a Transaction's time exceeds the threshold value + # (in ms). A transaction will only be reported once. + slow_transactions: + enabled: false + threshold: 1000 + # Application Environments # ------------------------------------------ # Environment specific settings are in this section.