From 74e270776d8f9e203c5669fb2dc610e3b01ad9d5 Mon Sep 17 00:00:00 2001 From: Sander Hautvast Date: Sun, 15 Jul 2018 12:56:40 +0200 Subject: [PATCH] Finally implemented callstack completely and correctly --- agent.iml | 3 + pom.xml | 6 ++ src/main/java/perfix/MethodNode.java | 55 +++++++++++++ src/main/java/perfix/Registry.java | 61 +++++++++++--- .../java/perfix/instrument/Instrumentor.java | 25 ++++++ .../perfix/instrument/JdbcInstrumentor.java | 79 +++++++------------ .../java/perfix/instrument/StatementText.java | 55 ++++++++----- src/main/java/perfix/instrument/Util.java | 18 +++++ src/main/java/perfix/server/HTTPServer.java | 2 - .../server/json/SynthSerializerFactory.java | 11 +-- src/test/java/StatementTextTest.java | 4 +- src/testapp/java/testperfix/cmdline/App.java | 15 +++- 12 files changed, 235 insertions(+), 99 deletions(-) create mode 100644 src/main/java/perfix/MethodNode.java create mode 100644 src/main/java/perfix/instrument/Util.java diff --git a/agent.iml b/agent.iml index e3d8113..28f345b 100644 --- a/agent.iml +++ b/agent.iml @@ -31,6 +31,9 @@ + + + diff --git a/pom.xml b/pom.xml index 6b4b98b..f66846f 100644 --- a/pom.xml +++ b/pom.xml @@ -32,6 +32,12 @@ 4.12 test + + + org.apache.commons + commons-dbcp2 + 2.4.0 + com.h2database h2 diff --git a/src/main/java/perfix/MethodNode.java b/src/main/java/perfix/MethodNode.java new file mode 100644 index 0000000..ff70e57 --- /dev/null +++ b/src/main/java/perfix/MethodNode.java @@ -0,0 +1,55 @@ +package perfix; + +import java.util.ArrayList; +import java.util.List; +import java.util.Objects; + +public class MethodNode { + public final String name; + public final List children; + public MethodNode parent; + public Report report; + + public MethodNode(String name) { + this.name = name; + this.children = new ArrayList<>(); + } + + public void addChild(MethodNode child){ + children.add(child); + } + + public String getName() { + return name; + } + + public Report getReport() { + return report; + } + + public List getChildren() { + return children; + } + + @Override + public String toString() { + return "MethodNode{" + + "name='" + name + '\'' + + '}'; + } + + @Override + public boolean equals(Object o) { + if (this == o) return true; + if (o == null || getClass() != o.getClass()) return false; + MethodNode that = (MethodNode) o; + return Objects.equals(name, that.name); + } + + @Override + public int hashCode() { + return Objects.hash(name); + } + + +} diff --git a/src/main/java/perfix/Registry.java b/src/main/java/perfix/Registry.java index a209178..6856809 100644 --- a/src/main/java/perfix/Registry.java +++ b/src/main/java/perfix/Registry.java @@ -1,5 +1,7 @@ package perfix; +import perfix.instrument.Util; + import java.util.*; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentSkipListMap; @@ -8,25 +10,55 @@ import java.util.concurrent.atomic.LongAdder; public class Registry { private static final Map> methods = new ConcurrentHashMap<>(); - private static final Map> callstack = new ConcurrentHashMap<>(); - private static final ThreadLocal currentMethod = new ThreadLocal<>(); + private static final List callstack = new ArrayList<>(); + private static final ThreadLocal currentMethod = new ThreadLocal<>(); + + @SuppressWarnings("unused") //used in generated code + public static MethodInvocation startJdbc(String name) { + if (!Util.isFirstExecutionStarted()) { + Util.startExecution(); + return start(name); + } else { + return null; + } + } @SuppressWarnings("unused") public static MethodInvocation start(String name) { MethodInvocation methodInvocation = new MethodInvocation(name); - String parent = currentMethod.get(); + MethodNode newNode = new MethodNode(methodInvocation.getName()); + + MethodNode parent = currentMethod.get(); if (parent != null) { - callstack.computeIfAbsent(parent, k -> new HashSet<>()).add(methodInvocation.getName()); + parent.addChild(newNode); + newNode.parent = parent; + } else { + callstack.add(newNode); } - currentMethod.set(methodInvocation.getName()); + + currentMethod.set(newNode); return methodInvocation; } + @SuppressWarnings("unused") + public static void stopJdbc(MethodInvocation queryInvocation) { + if (Util.isFirstExecutionStarted() && queryInvocation != null) { + stop(queryInvocation); + Util.endExecution(); + } + } + @SuppressWarnings("unused") public static void stop(MethodInvocation methodInvocation) { - methodInvocation.t1 = System.nanoTime(); - methods.computeIfAbsent(methodInvocation.getName(), key -> new ArrayList<>()).add(methodInvocation); + if (methodInvocation != null) { + methodInvocation.t1 = System.nanoTime(); + methods.computeIfAbsent(methodInvocation.getName(), key -> new ArrayList<>()).add(methodInvocation); + } + MethodNode methodNode = currentMethod.get(); + if (methodNode != null) { + currentMethod.set(methodNode.parent); + } } public static SortedMap sortedMethodsByDuration() { @@ -41,12 +73,19 @@ public class Registry { return sortedByTotal; } - //work in progress - public static Map> getCallStack() { - callstack.forEach((name, children) -> { + public static List getCallStack() { + addReport(callstack); + return callstack; + } + private static void addReport(List callstack) { + callstack.forEach(methodNode -> { + LongAdder totalDuration = new LongAdder(); + List methodInvocations = methods.get(methodNode.name); + methodInvocations.forEach(methodInvocation -> totalDuration.add(methodInvocation.getDuration())); + methodNode.report = new Report(methodNode.name, methodInvocations.size(), totalDuration.longValue()); + addReport(methodNode.children); }); - return null; } } diff --git a/src/main/java/perfix/instrument/Instrumentor.java b/src/main/java/perfix/instrument/Instrumentor.java index ca9bc7d..0b03be7 100644 --- a/src/main/java/perfix/instrument/Instrumentor.java +++ b/src/main/java/perfix/instrument/Instrumentor.java @@ -60,6 +60,31 @@ public abstract class Instrumentor { } } + /* record times at beginning and end of sql call + * sql calls are special in the sense that certain jdbc connection pool implementations + * create a nested chain of jdbc statement implementations, resulting in too many reported + * (measured) calls if not handled in a way to prevent this */ + void instrumentJdbcCall(CtMethod methodToinstrument, String metricName) { + try { + methodToinstrument.addLocalVariable("_perfixmethod", perfixMethodInvocationClass); + methodToinstrument.insertBefore("_perfixmethod = perfix.Registry.startJdbc(" + metricName + ");"); + methodToinstrument.insertAfter("perfix.Registry.stopJdbc(_perfixmethod);"); + } catch (CannotCompileException e) { + throw new RuntimeException(e); + } + } + + /* record times at beginning and end of method body*/ + void instrumentJdbcCall(CtMethod methodToinstrument) { + try { + methodToinstrument.addLocalVariable("_perfixmethod", perfixMethodInvocationClass); + methodToinstrument.insertBefore("_perfixmethod = perfix.Registry.startJdbc(perfix.instrument.StatementText.toString(_perfixSqlStatement));"); + methodToinstrument.insertAfter("perfix.Registry.stopJdbc(_perfixmethod);"); + } catch (CannotCompileException e) { + throw new RuntimeException(e); + } + } + byte[] bytecode(CtClass classToInstrument) throws IOException, CannotCompileException { classToInstrument.detach(); return classToInstrument.toBytecode(); diff --git a/src/main/java/perfix/instrument/JdbcInstrumentor.java b/src/main/java/perfix/instrument/JdbcInstrumentor.java index ccbae05..77d385a 100644 --- a/src/main/java/perfix/instrument/JdbcInstrumentor.java +++ b/src/main/java/perfix/instrument/JdbcInstrumentor.java @@ -12,19 +12,6 @@ import static java.util.Arrays.stream; public class JdbcInstrumentor extends Instrumentor { - private static final String JAVASQL_EXECUTE_METHOD = "execute"; - private static final String JAVASQL_EXECUTEQUERY_METHOD = "executeQuery"; - private static final String JAVASQL_EXECUTEUPDATE_METHOD = "executeUpdate"; - private static final String JAVASQL_PACKAGE = "java/sql"; - private static final String JAVASQL_STATEMENT_INTERFACE = "java.sql.Statement"; - private static final String JAVASQL_PREPAREDSTATEMENT_INTERFACE = "java.sql.PreparedStatement"; - private static final String JAVASQL_CONNECTION_INTERFACE = "java.sql.Connection"; - private static final String JAVASQL_PREPAREDSTATEMENT_RESOURCENAME = "java/sql/PreparedStatement"; - private static final String JAVASQL_PREPARED_STATEMENT_CLASSNAME = "java.sql.PreparedStatement"; - private static final String JAVASQL_PREPARESTATEMENT_METHODNAME = "prepareStatement"; - - private static final String PERFIX_SQLSTATEMENT_FIELD = "_perfixSqlStatement"; - private static final String PERFIX_SETSQL_METHOD = "setSqlForPerfix"; private static CtClass statementTextClass = null; JdbcInstrumentor(List includes, ClassPool classPool) { @@ -39,11 +26,11 @@ public class JdbcInstrumentor extends Instrumentor { /* Need to enhance interface to be able to set a statement (string) for perfix. */ byte[] instrumentJdbcPreparedStatement(CtClass preparedStatementInterface, byte[] uninstrumentedByteCode) { try { - preparedStatementInterface.getDeclaredMethod(PERFIX_SETSQL_METHOD); + preparedStatementInterface.getDeclaredMethod("setSqlForPerfix"); } catch (NotFoundException e1) { e1.printStackTrace(); try { - CtMethod setSqlForPerfix = new CtMethod(CtClass.voidType, PERFIX_SETSQL_METHOD, new CtClass[]{stringClass}, preparedStatementInterface); + CtMethod setSqlForPerfix = new CtMethod(CtClass.voidType, "setSqlForPerfix", new CtClass[]{stringClass}, preparedStatementInterface); preparedStatementInterface.addMethod(setSqlForPerfix); } catch (CannotCompileException e2) { @@ -66,21 +53,21 @@ public class JdbcInstrumentor extends Instrumentor { * and injected into the PreparedStatement instance under a fixed name, whatever the implementation type */ byte[] instrumentJdbcConnection(CtClass classToInstrument, byte[] uninstrumentedByteCode) { try { - stream(classToInstrument.getDeclaredMethods(JAVASQL_PREPARESTATEMENT_METHODNAME)).forEach(method -> { + stream(classToInstrument.getDeclaredMethods("prepareStatement")).forEach(method -> { try { // The sql statement String that is the first argument for this method is injected into PreparedStatementImpl // using a name known (only) to perfix, so that it can fetch it later in that class (instance) // this way no JDBC implementor specific code is needed - CtClass preparedStatementInterface = classpool.get(JAVASQL_PREPARED_STATEMENT_CLASSNAME); + CtClass preparedStatementInterface = classpool.get("java.sql.PreparedStatement"); try { - preparedStatementInterface.getDeclaredMethod(PERFIX_SETSQL_METHOD); + preparedStatementInterface.getDeclaredMethod("setSqlForPerfix"); } catch (NotFoundException e1) { - CtMethod setSqlForPerfix = new CtMethod(CtClass.voidType, PERFIX_SETSQL_METHOD, new CtClass[]{stringClass}, preparedStatementInterface); + CtMethod setSqlForPerfix = new CtMethod(CtClass.voidType, "setSqlForPerfix", new CtClass[]{stringClass}, preparedStatementInterface); preparedStatementInterface.addMethod(setSqlForPerfix); } - method.insertAfter(JAVASSIST_RETURNVALUE + "." + PERFIX_SETSQL_METHOD + "(" + JAVASSIST_FIRST_ARGUMENT_NAME + ");"); //$_ is result instance, $1 is first argument + method.insertAfter("$_.setSqlForPerfix($1);"); //$_ is result instance, $1 is first argument } catch (CannotCompileException | NotFoundException e) { // suppress e.printStackTrace(); @@ -100,26 +87,14 @@ public class JdbcInstrumentor extends Instrumentor { try { addPerfixFields(preparedStatementClass); addPerfixStatementSetter(preparedStatementClass); - - // instrument execute to record query duration - stream(preparedStatementClass.getDeclaredMethods(JAVASQL_EXECUTE_METHOD)).forEach(method -> - instrumentMethod(method, PERFIX_SQLSTATEMENT_FIELD + ".toString()") - ); - - // instrument executeQuery to record query duration - stream(preparedStatementClass.getDeclaredMethods(JAVASQL_EXECUTEQUERY_METHOD)).forEach(method -> - instrumentMethod(method, PERFIX_SQLSTATEMENT_FIELD + ".toString()") - ); - - // instrument executeUpdate to record query duration - stream(preparedStatementClass.getDeclaredMethods(JAVASQL_EXECUTEUPDATE_METHOD)).forEach(method -> - instrumentMethod(method, PERFIX_SQLSTATEMENT_FIELD + ".toString()") - ); + stream(preparedStatementClass.getDeclaredMethods("execute")).forEach(this::instrumentJdbcCall); + stream(preparedStatementClass.getDeclaredMethods("executeQuery")).forEach(this::instrumentJdbcCall); + stream(preparedStatementClass.getDeclaredMethods("executeUpdate")).forEach(this::instrumentJdbcCall); getDeclaredMethods(preparedStatementClass, "setString", "setObject", "setDate", "setTime", "setTimestamp") .forEach(method -> { try { - method.insertBefore(PERFIX_SQLSTATEMENT_FIELD + ".set($1, \"\'\"+$2+\"\'\");"); + method.insertBefore("perfix.instrument.StatementText.set(_perfixSqlStatement,$1, \"\'\"+$2+\"\'\");"); } catch (CannotCompileException e) { throw new RuntimeException(e); } @@ -129,7 +104,7 @@ public class JdbcInstrumentor extends Instrumentor { "setInt", "setFloat", "setDouble", "setBoolean", "setLong", "setShort") .forEach(method -> { try { - method.insertBefore(PERFIX_SQLSTATEMENT_FIELD + ".set($1, $2);"); + method.insertBefore("perfix.instrument.StatementText.set(_perfixSqlStatement,$1,$2);"); } catch (CannotCompileException e) { throw new RuntimeException(e); } @@ -138,7 +113,7 @@ public class JdbcInstrumentor extends Instrumentor { getDeclaredMethods(preparedStatementClass, "setNull") .forEach(method -> { try { - method.insertBefore(PERFIX_SQLSTATEMENT_FIELD + ".set($1, \"[NULL]\");"); + method.insertBefore("perfix.instrument.StatementText.set(_perfixSqlStatement,$1,\"[NULL]\");"); } catch (CannotCompileException e) { throw new RuntimeException(e); } @@ -171,12 +146,12 @@ public class JdbcInstrumentor extends Instrumentor { byte[] instrumentJdbcStatement(CtClass classToInstrument, byte[] uninstrumentedByteCode) { try { //instrument executeQuery to record query duration - stream(classToInstrument.getDeclaredMethods(JAVASQL_EXECUTEQUERY_METHOD)).forEach(method -> - instrumentMethod(method, JAVASSIST_FIRST_ARGUMENT_NAME) + stream(classToInstrument.getDeclaredMethods("executeQuery")).forEach(method -> + instrumentJdbcCall(method, "$1") ); //instrument executeUpdate to record query duration - stream(classToInstrument.getDeclaredMethods(JAVASQL_EXECUTEUPDATE_METHOD)).forEach(method -> - instrumentMethod(method, JAVASSIST_FIRST_ARGUMENT_NAME) + stream(classToInstrument.getDeclaredMethods("executeUpdate")).forEach(method -> + instrumentJdbcCall(method, "$1") ); return bytecode(classToInstrument); } catch (Exception e) { @@ -188,43 +163,43 @@ public class JdbcInstrumentor extends Instrumentor { private void addPerfixFields(CtClass preparedStatementClass) throws CannotCompileException, NotFoundException { // add a String field that will contain the statement - CtField perfixSqlField = new CtField(statementTextClass, PERFIX_SQLSTATEMENT_FIELD, preparedStatementClass); + CtField perfixSqlField = new CtField(statementTextClass, "_perfixSqlStatement", preparedStatementClass); perfixSqlField.setModifiers(Modifier.PRIVATE); preparedStatementClass.addField(perfixSqlField); } private void addPerfixStatementSetter(CtClass preparedStatementImplClass) throws CannotCompileException { // add setter for the new field - CtMethod setSqlForPerfix = new CtMethod(CtClass.voidType, PERFIX_SETSQL_METHOD, new CtClass[]{stringClass}, preparedStatementImplClass); + CtMethod setSqlForPerfix = new CtMethod(CtClass.voidType, "setSqlForPerfix", new CtClass[]{stringClass}, preparedStatementImplClass); setSqlForPerfix.setModifiers(Modifier.PUBLIC); - setSqlForPerfix.setBody(PERFIX_SQLSTATEMENT_FIELD + "= new perfix.instrument.StatementText(" + JAVASSIST_FIRST_ARGUMENT_NAME + ");"); + setSqlForPerfix.setBody("_perfixSqlStatement=new perfix.instrument.StatementText($1);"); preparedStatementImplClass.addMethod(setSqlForPerfix); } boolean isJdbcStatementImpl(String resource, CtClass ctClass) throws NotFoundException { - if (!resource.startsWith(JAVASQL_PACKAGE)) { + if (!resource.startsWith("java/sql")) { return stream(ctClass.getInterfaces()) - .anyMatch(i -> i.getName().equals(JAVASQL_STATEMENT_INTERFACE) && !i.getName().equals(JAVASQL_PREPARED_STATEMENT_CLASSNAME)); + .anyMatch(i -> i.getName().equals("java.sql.Statement") && !i.getName().equals("java.sql.PreparedStatement")); } return false; } boolean isJdbcPreparedStatement(String resource) { - return resource.equals(JAVASQL_PREPAREDSTATEMENT_RESOURCENAME); + return resource.equals("java/sql/PreparedStatement"); } boolean isJdbcPreparedStatementImpl(String resource, CtClass ctClass) throws NotFoundException { - if (!resource.startsWith(JAVASQL_PACKAGE)) { + if (!resource.startsWith("java/sql")) { return stream(ctClass.getInterfaces()) - .anyMatch(i -> i.getName().equals(JAVASQL_PREPAREDSTATEMENT_INTERFACE)); + .anyMatch(i -> i.getName().equals("java.sql.PreparedStatement")); } return false; } boolean isJdbcConnectionImpl(String resource, CtClass ctClass) throws NotFoundException { - if (!resource.startsWith(JAVASQL_PACKAGE)) { + if (!resource.startsWith("java/sql")) { return stream(ctClass.getInterfaces()) - .anyMatch(i -> i.getName().equals(JAVASQL_CONNECTION_INTERFACE)); + .anyMatch(i -> i.getName().equals("java.sql.Connection")); } return false; } diff --git a/src/main/java/perfix/instrument/StatementText.java b/src/main/java/perfix/instrument/StatementText.java index 7b269eb..fe298b4 100644 --- a/src/main/java/perfix/instrument/StatementText.java +++ b/src/main/java/perfix/instrument/StatementText.java @@ -12,47 +12,62 @@ public class StatementText { this.sql = new StringBuilder(sql); } - public void set(int index, Object value) { - if (index < 1 || index > vars.length + 1) { - throw new IndexOutOfBoundsException("" + index); + + public static void set(StatementText statementText, int index, Object value) { + if (statementText != null) { + if (index < 1 || index > statementText.vars.length + 1) { + throw new IndexOutOfBoundsException("" + index); + } + statementText.vars[index - 1] = value; + } else { + if (statementText!=null){ + System.out.println(statementText); + } else { + System.out.println("null"); + } } - vars[index - 1] = value; } - public void set(int index, int value){ - set(index, Integer.toString(value)); + @SuppressWarnings("unused") //used in generated code + public static String toString(StatementText statementText) { + return statementText != null ? statementText.toString() : "[none]"; } - public void set(int index, long value){ - set(index, Long.toString(value)); + public static void set(StatementText statementText, int index, int value) { + set(statementText, index, Integer.toString(value)); } - public void set(int index, double value){ - set(index, Double.toString(value)); + public static void set(StatementText statementText, int index, long value) { + set(statementText, index, Long.toString(value)); } - public void set(int index, boolean value){ - set(index, Boolean.toString(value)); + public static void set(StatementText statementText, int index, double value) { + set(statementText, index, Double.toString(value)); } - public void set(int index, float value){ - set(index, Float.toString(value)); + public static void set(StatementText statementText, int index, boolean value) { + set(statementText, index, Boolean.toString(value)); } - public void set(int index, short value){ - set(index, Short.toString(value)); + public static void set(StatementText statementText, int index, float value) { + set(statementText, index, Float.toString(value)); + } + + public static void set(StatementText statementText, int index, short value) { + set(statementText, index, Short.toString(value)); } @Override public String toString() { + StringBuilder output=new StringBuilder(sql); int found = 0; for (int i = 0; i < sql.length(); i++) { - if (sql.charAt(i) == BOUNDVAR_MARK) { - sql.deleteCharAt(i); - sql.insert(i, vars[found++]); + if (output.charAt(i) == BOUNDVAR_MARK) { + output.deleteCharAt(i); + output.insert(i, vars[found++]); } } - return sql.toString(); + return output.toString(); } private int countVars(String sql) { diff --git a/src/main/java/perfix/instrument/Util.java b/src/main/java/perfix/instrument/Util.java new file mode 100644 index 0000000..ab9e078 --- /dev/null +++ b/src/main/java/perfix/instrument/Util.java @@ -0,0 +1,18 @@ +package perfix.instrument; + +public class Util { + private final static ThreadLocal STATEMENT_INSTRUMENTED_TL = new ThreadLocal<>(); + + public static void startExecution() { + STATEMENT_INSTRUMENTED_TL.set(true); + } + + public static void endExecution() { + STATEMENT_INSTRUMENTED_TL.set(false); + } + + public static boolean isFirstExecutionStarted() { + Boolean isStarted = STATEMENT_INSTRUMENTED_TL.get(); + return isStarted != null ? isStarted : false; + } +} diff --git a/src/main/java/perfix/server/HTTPServer.java b/src/main/java/perfix/server/HTTPServer.java index 2892138..fb29ebc 100644 --- a/src/main/java/perfix/server/HTTPServer.java +++ b/src/main/java/perfix/server/HTTPServer.java @@ -40,8 +40,6 @@ public class HTTPServer extends NanoHTTPD { private Response perfixMetrics() { try { return addCors(newFixedLengthResponse(Response.Status.OK, "application/json", Serializer.toJSONString(new ArrayList<>(Registry.sortedMethodsByDuration().values())))); - - } catch (Exception e) { e.printStackTrace(); return newFixedLengthResponse(e.toString()); diff --git a/src/main/java/perfix/server/json/SynthSerializerFactory.java b/src/main/java/perfix/server/json/SynthSerializerFactory.java index d55462b..3a8c4ad 100644 --- a/src/main/java/perfix/server/json/SynthSerializerFactory.java +++ b/src/main/java/perfix/server/json/SynthSerializerFactory.java @@ -131,15 +131,10 @@ public class SynthSerializerFactory implements SerializerFactory { * The generated code fills a StringBuilder. The values are generated by the subserializers */ private String handleArray(CtClass beanClass) { - String source = "\tStringBuilder result=new StringBuilder(\"[\");\n"; + String source = "\tjava.util.StringJoiner result=new java.util.StringJoiner(\",\",\"[\",\"]\");\n"; source += "\tfor (int i=0; i