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 f37def43fc..54ad100f83 100644 --- a/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java +++ b/newrelic-agent/src/main/java/com/newrelic/agent/MetricNames.java @@ -493,6 +493,9 @@ 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/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 04d06c31a8..d13f40640f 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 e708b1b460..ca83e0322f 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.service.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()); @@ -230,6 +232,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); @@ -276,6 +279,8 @@ protected synchronized void doStart() throws Exception { harvestService.addHarvestListener(extensionService); harvestService.addHarvestListener(jarCollectorHarvestListener); + slowTransactionService = new SlowTransactionService(config); + asyncTxService.start(); threadService.start(); statsService.start(); @@ -308,6 +313,7 @@ protected synchronized void doStart() throws Exception { circuitBreakerService.start(); distributedTraceService.start(); spanEventsService.start(); + slowTransactionService.start(); startServices(); @@ -378,6 +384,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/service/slowtransactions/SlowTransactionService.java b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java new file mode 100644 index 0000000000..2fa676b702 --- /dev/null +++ b/newrelic-agent/src/main/java/com/newrelic/agent/service/slowtransactions/SlowTransactionService.java @@ -0,0 +1,214 @@ +package com.newrelic.agent.service.slowtransactions; + +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; +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.agent.tracing.DistributedTraceServiceImpl; +import com.newrelic.agent.util.StackTraces; +import com.newrelic.api.agent.NewRelic; + +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.List; +import java.util.Map; +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 ThreadMXBean threadMXBean; + + 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; + + NewRelic.getAgent().getMetricAggregator().incrementCounter( + agentConfig.getSlowTransactionsConfig().isEnabled() ? + MetricNames.SUPPORTABILITY_SLOW_TXN_DETECTION_ENABLED : MetricNames.SUPPORTABILITY_SLOW_TXN_DETECTION_DISABLED); + } + + @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 + public void dispatcherTransactionStarted(Transaction transaction) { + if (getLogger().isLoggable(Level.FINEST)) { + getLogger().finest("Transaction started with id " + transaction.getGuid()); + } + openTransactions.put(transaction.getGuid(), transaction); + } + + @Override + public void dispatcherTransactionCancelled(Transaction transaction) { + if (getLogger().isLoggable(Level.FINEST)) { + getLogger().finest("Transaction cancelled with guid " + transaction.getGuid()); + } + openTransactions.remove(transaction.getGuid()); + } + + @Override + public void dispatcherTransactionFinished(TransactionData transactionData, TransactionStats transactionStats) { + if (getLogger().isLoggable(Level.FINEST)) { + getLogger().finest("Transaction finished with guid " + transactionData.getGuid()); + } + openTransactions.remove(transactionData.getGuid()); + } + + // Visible for testing + Map getOpenTransactions() { + return Collections.unmodifiableMap(openTransactions); + } + + @Override + public void beforeHarvest(String appName, StatsEngine statsEngine) { + run(); + } + + @Override + public void afterHarvest(String appName) { + } + + // Visible for testing + void run() { + if (getLogger().isLoggable(Level.FINE)) { + getLogger().fine("Identifying slow threads. Open transactions: " + openTransactions.size()); + } + Transaction slowestOpen = null; + long slowestOpenMillis = thresholdMillis; + + // Identify the slowest open transaction we haven't yet reported + for (Transaction transaction : openTransactions.values()) { + long openMs = System.currentTimeMillis() - transaction.getWallClockStartTimeMs(); + if (openMs > slowestOpenMillis) { + slowestOpen = transaction; + slowestOpenMillis = openMs; + } + } + + if (slowestOpen == null) { + getLogger().fine("No new slow transactions identified."); + return; + } + + // 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); + } + // Remove from openTransactions to ensure we don't report the same Transaction + // multiple times + openTransactions.remove(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(transaction.getUserAttributes()); + attributes.putAll(transaction.getErrorAttributes()); + attributes.putAll(transaction.getAgentAttributes()); + attributes.putAll(transaction.getIntrinsicAttributes()); + + // General + 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 = transaction.getInitiatingThreadId(); + attributes.put("thread.id", initiatingThreadId); + ThreadInfo threadInfo = threadMXBean.getThreadInfo(initiatingThreadId, maxStackTraceLines); + if (threadInfo != null) { + attributes.put("thread.name", threadInfo.getThreadName()); + attributes.put("thread.state", threadInfo.getThreadState().name()); + List scrubbedStackTraceElements = StackTraces.scrubAndTruncate(threadInfo.getStackTrace()); + attributes.put("code.stacktrace", stackTraceString(scrubbedStackTraceElements)); + } + + new IllegalArgumentException().printStackTrace(); + return attributes; + } + + private static String stackTraceString(List stackTrace) { + if (stackTrace.isEmpty()) { + return ""; + } + StringBuilder stringBuilder = new StringBuilder(); + 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/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. 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..2849f6d4e0 --- /dev/null +++ b/newrelic-agent/src/test/java/com/newrelic/agent/service/slowtransactions/SlowTransactionServiceTest.java @@ -0,0 +1,260 @@ +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.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()); + + // Start t2, verify added to open + service.dispatcherTransactionStarted(t2); + assertEquals(ImmutableMap.of(t1Guid, t1, t2Guid, t2), service.getOpenTransactions()); + + // Cancel t1, verify removed from open + service.dispatcherTransactionCancelled(t1); + assertEquals(ImmutableMap.of(t2Guid, t2), service.getOpenTransactions()); + + // Finish t2, verify removed from open + service.dispatcherTransactionFinished(t2Data, mock(TransactionStats.class)); + assertEquals(Collections.emptyMap(), service.getOpenTransactions()); + } + + @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(ImmutableMap.of(t1Guid, t1, t2Guid, t2), service.getOpenTransactions()); + } + + @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; + } + +}