diff --git a/README.md b/README.md index 31e84c2..87c5b22 100644 --- a/README.md +++ b/README.md @@ -193,6 +193,22 @@ Tue Jun 23 12:39:25 CEST 2020 2020-06-23T12:39:25.875 TraceAgent (trace_retval): `public int net.test.TestClass2nd.methodWithArgs(java.lang.String,int) returns with 12 ``` +### Example for common argument (both global and action argument): `isThreadnameLogged` +The `isThreadnameLogged` can be used to request the current thread name to be contained as prefix in the actions logs. +This is especially useful in multithreaded applications. +This is false by default but via setting it globally this default can be changed: + +``` +$ java -javaagent:target/trace-agent-1.0-SNAPSHOT.jar="isDateLogged:true,isThreadnameLogged:true" -jar ../testartifact/target/testartifact-1.0-SNAPSHOT.jar +Hello World! +2020-06-23T12:34:27.746 [main] TraceAgent (timing): `public void net.test.TestClass.test()` took 101212548 nano +... +``` +The `isThreadnameLogged` can be enabled on action level too if needed: + +``` +elapsed_time_in_nano net.test.TestClass test isThreadnameLogged:true +``` ### Trace agent global only parameters There are parameters which configures the trace agent globally. @@ -527,6 +543,7 @@ Heapdump file names follows the following patttern: * `isDateLogged` (scope: both `global` and `action`) The `isDateLogged` can be used to request the current date time to be contained as prefix in the actions logs. * `dateTimeFormat` (scope: `global`) Can be used to specify formatting for datetimes. The default is [ISO_LOCAL_DATE_TIME](https://docs.oracle.com/javase/8/docs/api/java/time/format/DateTimeFormatter.html#ISO_LOCAL_DATE_TIME). For the details and valid patterns please check: [DateTimeFormatter](https://docs.oracle.com/javase/8/docs/api/java/time/format/DateTimeFormatter.html). +* `isThreadnameLogged` (scope: both `global` and `action`) The `isThreadnameLogged` can be used to request the current thread name to be contained as prefix in the actions logs. * `log_threshold_ms` (scope: multiple actions) This threshold represents the elapsed number of milliseconds after there will be a printout. The default is `0`, which means it should printout on every call. For example, if we only like to log an action when it takes more than 1 second to complete: `elapsed_time_in_ms net.test.TestClass test log_threshold_ms:1000` * `log_threshold_nano` (scope: only for `elapsed_time_in_nano`) Similar to `log_threshold_ms` but in nanoseconds. * `limit_count` (scope: only for `stack_trace`) Trace only the first `limit_count` number of calls. This limit is turned off by default by set it to -1. @@ -544,17 +561,17 @@ All actions have the following set of arguments Here is the full list of actions and supported `params` -| Action | Supported arguments | -| --------------------------- | --------------------------------------------- | -| elapsed_time_in_nano | isDateLogged, log_threshold_nano | -| elapsed_time_in_ms | isDateLogged, log_threshold_ms | -| stack_trace | isDateLogged, log_threshold_ms, limit_count | -| trace_args | isDateLogged, log_threshold_ms | -| trace_retval | isDateLogged, log_threshold_ms | -| trace_args_with_method_call | isDateLogged, param_index, method_to_call | -| counter | isDateLogged, count_frequency | -| avg_timing | isDateLogged, window_length | -| trace_login_config | isDateLogged, entry_name | +| Action | Supported arguments | +| --------------------------- |-------------------------------------------------------| +| elapsed_time_in_nano | isDateLogged, isThreadnameLogged, log_threshold_nano | +| elapsed_time_in_ms | isDateLogged, isThreadnameLogged, log_threshold_ms | +| stack_trace | isDateLogged, isThreadnameLogged, log_threshold_ms, limit_count | +| trace_args | isDateLogged, isThreadnameLogged, log_threshold_ms | +| trace_retval | isDateLogged, isThreadnameLogged, log_threshold_ms | +| trace_args_with_method_call | isDateLogged, isThreadnameLogged, param_index, method_to_call | +| counter | isDateLogged, isThreadnameLogged, count_frequency | +| avg_timing | isDateLogged, isThreadnameLogged, window_length | +| trace_login_config | isDateLogged, isThreadnameLogged, entry_name | # Some complex examples how to specify a javaagent diff --git a/trace-agent-it/test_exec/src/test/java/TestTraceAgent.java b/trace-agent-it/test_exec/src/test/java/TestTraceAgent.java index aa7034b..269e368 100644 --- a/trace-agent-it/test_exec/src/test/java/TestTraceAgent.java +++ b/trace-agent-it/test_exec/src/test/java/TestTraceAgent.java @@ -27,7 +27,18 @@ public class TestTraceAgent { + "\" " + "-jar ../sampleApp/target/sampleApp-1.0-SNAPSHOT.jar"); + private static CommandLine cmdWithThreadNameArgs = + CommandLine.parse( + "java -XX:NativeMemoryTracking=detail -javaagent:../../trace-agent/target/trace-agent-1.0-SNAPSHOT.jar=\"isThreadnameLogged:true,actionsFile:./" + + ACTION_FILE_NAME + + "\" " + + "-jar ../sampleApp/target/sampleApp-1.0-SNAPSHOT.jar"); + private String runTraceAgent(String... actions) throws IOException { + return runTraceAgent(false, actions); + } + + private String runTraceAgent(boolean isThreadNameLogged, String... actions) throws IOException { String res = ""; try (ByteArrayOutputStream outputStream = new ByteArrayOutputStream()) { DefaultExecutor executor = new DefaultExecutor(); @@ -38,7 +49,11 @@ private String runTraceAgent(String... actions) throws IOException { actionWriter.append(a + "\n"); } actionWriter.close(); - executor.execute(cmd); + if (isThreadNameLogged) { + executor.execute(cmdWithThreadNameArgs); + } else { + executor.execute(cmd); + } } finally { actionFile.delete(); } @@ -164,4 +179,24 @@ public void testDiagnosticCommandNativeMemory() throws IOException { streamSupplier.get().anyMatch(s -> s.equals("TraceAgent (diagnostic_command / vmNativeMemory): at the beginning of `public void net.test.TestClass2nd.anotherMethod()`:"))); assertTrue(streamSupplier.get().anyMatch(s -> s.equals("Native Memory Tracking:"))); } + + @Test + public void testTraceArgsWithThreadNameAsJVMArg() throws IOException { + String output = runTraceAgent(true, "trace_args net.test.TestClass2nd methodWithArgs"); + Supplier> streamSupplier = toStreamSupplier(output); + assertTrue( + streamSupplier + .get() + .anyMatch(s -> s.contains("[main] TraceAgent (trace_args pre): `public int net.test.TestClass2nd.methodWithArgs(java.lang.String,int) called with [secret, 42]"))); + } + + @Test + public void testTraceArgsWithThreadNameAsActionArg() throws IOException { + String output = runTraceAgent("trace_args net.test.TestClass2nd methodWithArgs isThreadnameLogged:true"); + Supplier> streamSupplier = toStreamSupplier(output); + assertTrue( + streamSupplier + .get() + .anyMatch(s -> s.contains("[main] TraceAgent (trace_args pre): `public int net.test.TestClass2nd.methodWithArgs(java.lang.String,int) called with [secret, 42]"))); + } } diff --git a/trace-agent/src/main/java/net/test/CommonActionArgs.java b/trace-agent/src/main/java/net/test/CommonActionArgs.java index 85b4c11..b8b1b72 100644 --- a/trace-agent/src/main/java/net/test/CommonActionArgs.java +++ b/trace-agent/src/main/java/net/test/CommonActionArgs.java @@ -7,8 +7,12 @@ public class CommonActionArgs { public static final String IS_DATE_LOGGED = "isDateLogged"; + public static final String IS_THREADNAME_LOGGED = "isThreadnameLogged"; + private final DateTimeFormatter dateTimeFormatter; + private final boolean threadnameLogged; + public CommonActionArgs(Map parsedActionArgs, DefaultArguments defaults) { final String isDateLoggedStr = parsedActionArgs.get(IS_DATE_LOGGED); if (isDateLoggedStr == null) { @@ -24,15 +28,23 @@ public CommonActionArgs(Map parsedActionArgs, DefaultArguments d dateTimeFormatter = null; } } + final String isThreadNameLoggedStr = parsedActionArgs.get(IS_THREADNAME_LOGGED); + if (isThreadNameLoggedStr == null) { + threadnameLogged = defaults.isThreadNameLogged(); + } else { + threadnameLogged = Boolean.valueOf(isThreadNameLoggedStr); + } } public String addPrefix(String str) { - final String prefixed; - if (dateTimeFormatter == null) { - prefixed = str; - } else { - prefixed = dateTimeFormatter.format(LocalDateTime.now()) + " " + str; + StringBuilder prefixed = new StringBuilder(); + if (dateTimeFormatter != null) { + prefixed.append(dateTimeFormatter.format(LocalDateTime.now())).append(" "); + } + if (threadnameLogged) { + prefixed.append("[").append(Thread.currentThread().getName()).append("] "); } - return prefixed; + prefixed.append(str); + return prefixed.toString(); } } diff --git a/trace-agent/src/main/java/net/test/DefaultArguments.java b/trace-agent/src/main/java/net/test/DefaultArguments.java index 513eb17..6837419 100644 --- a/trace-agent/src/main/java/net/test/DefaultArguments.java +++ b/trace-agent/src/main/java/net/test/DefaultArguments.java @@ -1,14 +1,12 @@ package net.test; import java.time.format.DateTimeFormatter; -import java.util.ArrayList; -import java.util.List; -import java.util.HashMap; -import java.util.Map; public interface DefaultArguments { DateTimeFormatter getDateTimeFormatter(); boolean isDateLogged(); + + boolean isThreadNameLogged(); } diff --git a/trace-agent/src/main/java/net/test/TraceAgentArgs.java b/trace-agent/src/main/java/net/test/TraceAgentArgs.java index 8cc8c8e..25f22fc 100644 --- a/trace-agent/src/main/java/net/test/TraceAgentArgs.java +++ b/trace-agent/src/main/java/net/test/TraceAgentArgs.java @@ -20,11 +20,15 @@ public class TraceAgentArgs implements DefaultArguments { private final Boolean isDateLoggedFlag; + private final Boolean isThreadNameLoggedFlag; + private final PrintStream targetStream; public TraceAgentArgs(String arguments) { Map parsedArgs = - ArgUtils.parseOptionalArgs(Arrays.asList(EXTERNAL_ACTION_FILE_PATH, ENABLE_AGENT_LOG, DATE_TIME_FORMAT, CommonActionArgs.IS_DATE_LOGGED, TARGET_STREAM), arguments); + ArgUtils.parseOptionalArgs( + Arrays.asList(EXTERNAL_ACTION_FILE_PATH, ENABLE_AGENT_LOG, DATE_TIME_FORMAT, CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, TARGET_STREAM), + arguments); this.externalActionFilePath = parsedArgs.get(EXTERNAL_ACTION_FILE_PATH); if (parsedArgs.getOrDefault(TARGET_STREAM, "stdout").equals("stderr")) { this.targetStream = System.err; @@ -42,6 +46,7 @@ public TraceAgentArgs(String arguments) { // parse the common arguments this.isDateLoggedFlag = Boolean.valueOf(parsedArgs.get(CommonActionArgs.IS_DATE_LOGGED)); + this.isThreadNameLoggedFlag = Boolean.valueOf(parsedArgs.get(CommonActionArgs.IS_THREADNAME_LOGGED)); } public String getExternalActionFilePath() { @@ -60,6 +65,10 @@ public boolean isDateLogged() { return this.isDateLoggedFlag; } + public boolean isThreadNameLogged() { + return this.isThreadNameLoggedFlag; + } + public PrintStream getTargetStream() { return targetStream; } diff --git a/trace-agent/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java b/trace-agent/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java index e657267..597188d 100644 --- a/trace-agent/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java +++ b/trace-agent/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java @@ -22,7 +22,7 @@ public class AvgTimingInterceptorMs { private static String WINDOW_LENGTH = "window_length"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, WINDOW_LENGTH); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, WINDOW_LENGTH); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/CounterInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/CounterInterceptor.java index 4223a8a..266d85f 100644 --- a/trace-agent/src/main/java/net/test/interceptor/CounterInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/CounterInterceptor.java @@ -24,7 +24,7 @@ public class CounterInterceptor { private static String COUNT_FREQUENCY = "count_frequency"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, COUNT_FREQUENCY); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, COUNT_FREQUENCY); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/DiagnosticCommandInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/DiagnosticCommandInterceptor.java index fb1ce39..494b4a1 100644 --- a/trace-agent/src/main/java/net/test/interceptor/DiagnosticCommandInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/DiagnosticCommandInterceptor.java @@ -44,7 +44,7 @@ private static ObjectName createDiagObj() { private static String LIMIT_OUTPUT_LINES = "limit_output_lines"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, COMMAND, LIMIT_OUTPUT_LINES, WHERE, WITH_GC); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, COMMAND, LIMIT_OUTPUT_LINES, WHERE, WITH_GC); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/HeapDumpCommandInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/HeapDumpCommandInterceptor.java index eb98ec1..a22e83d 100644 --- a/trace-agent/src/main/java/net/test/interceptor/HeapDumpCommandInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/HeapDumpCommandInterceptor.java @@ -42,7 +42,7 @@ private static void dumpHeap(String filePath, boolean live) { private static String LIVE_OBJECTS = "live_objects"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, WHERE, LIVE_OBJECTS); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, WHERE, LIVE_OBJECTS); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorMs.java b/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorMs.java index 87c8598..9ba0fff 100644 --- a/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorMs.java +++ b/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorMs.java @@ -22,7 +22,7 @@ public class TimingInterceptorMs { private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_MILLISECONDS); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorNano.java b/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorNano.java index 4f34022..b34e1d6 100644 --- a/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorNano.java +++ b/trace-agent/src/main/java/net/test/interceptor/TimingInterceptorNano.java @@ -23,7 +23,7 @@ public class TimingInterceptorNano { private static String LOG_THRESHOLD_NANO = "log_threshold_nano"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_NANO); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_NANO); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/TraceArgsInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/TraceArgsInterceptor.java index 61548d3..d0a434f 100644 --- a/trace-agent/src/main/java/net/test/interceptor/TraceArgsInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/TraceArgsInterceptor.java @@ -24,7 +24,7 @@ public class TraceArgsInterceptor { private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_MILLISECONDS); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java index 68a5be2..229c035 100644 --- a/trace-agent/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java @@ -23,7 +23,7 @@ public class TraceArgsWithMethodCallInterceptor { private static String METHOD_TO_CALL = "method_to_call"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, PARAM_INDEX, METHOD_TO_CALL); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, PARAM_INDEX, METHOD_TO_CALL); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java index d082ce7..2988d04 100644 --- a/trace-agent/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java @@ -24,7 +24,7 @@ public class TraceLoginConfigInterceptor { private static String ENTRY_NAME = "entry_name"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, ENTRY_NAME); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, ENTRY_NAME); private CommonActionArgs commonActionArgs; diff --git a/trace-agent/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java b/trace-agent/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java index 739e8ea..1569f61 100644 --- a/trace-agent/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java +++ b/trace-agent/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java @@ -20,7 +20,7 @@ public class TraceRetValueInterceptor { private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms"; - private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS); + private static List KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_MILLISECONDS); private CommonActionArgs commonActionArgs;