Refine implementation, add configuration, add unit tests

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();
+
 }

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<String, Object> props) {
         transactionEventsConfig = initTransactionEvents();
         commandParserConfig = initCommandParserConfig();
         normalizationRuleConfig = new NormalizationRuleConfig(props);
+        slowTransactionsConfig = initSlowTransactionsConfig();
 
         Map<String, Object> flattenedProps = new HashMap<>();
         flatten("", props, flattenedProps);
@@ -856,6 +859,11 @@ private CommandParserConfig initCommandParserConfig() {
         return new CommandParserConfigImpl(nestedProps(CommandParserConfigImpl.ROOT));
     }
 
+    private SlowTransactionsConfig initSlowTransactionsConfig() {
+        Map<String, Object> 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<String, Object> map) {
         Object result = map;
         for (String component : property) {

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();
+
+}

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<String, Object> 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;
+    }
+
+}

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();

newrelic-agent/src/main/java/com/newrelic/agent/slowtransactions/SlowTransactionService.java → 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<String, Transaction> openTransactions = new ConcurrentHashMap<>();
     private final Set<String> 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<String, Transaction> getOpenTransactions() {
+        return Collections.unmodifiableMap(openTransactions);
     }
 
-    @Override
-    public boolean isEnabled() {
-        return true;
+    // Visible for testing
+    Set<String> 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<String, Object> 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<String, Object> extractMetadata(Transaction transaction, long openMillis) {
         Map<String, Object> 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<StackTraceElement> 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<StackTraceElement> 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();
     }