private void logStats(long totalExecutionTimeNs, Deque<String> indentationStack, StringBuilder sb, final boolean asciiArt, AsciiCallTreeSignatureFormatter callTreeAsciiFormatter) { appendTimesPercentTable(totalExecutionTimeNs, sb, asciiArt); appendCallTree(indentationStack, sb, asciiArt, callTreeAsciiFormatter); for (CallStackElement callStats : getChildren()) { if (!isRoot()) { if (isLastChild()) { indentationStack.add(" "); } else { indentationStack.add(asciiArt ? HORIZONTAL : "| "); } } callStats.logStats(totalExecutionTimeNs, indentationStack, sb, asciiArt, callTreeAsciiFormatter); if (!isRoot()) { indentationStack.pollLast(); } } }
/** * Activates the profiling for the current thread by setting the provided * {@link CallStackElement} as the root of the call stack * * @return the root of the call stack */ public static CallStackElement activateProfiling(String signature) { CallStackElement root = CallStackElement.createRoot(signature); methodCallParent.set(root); return root; }
@Override public String getSignature(CallStackElement callTreeElement) { final String shortSignature = callTreeElement.getShortSignature(); if (shortSignature != null) { return shortSignature; } else { return callTreeElement.getSignature(); } }
/** * Removes this node from the parent */ public void remove() { if (parent != null) { parent.getChildren().remove(this); recycle(); } }
public void removeCallsFasterThan(long thresholdNs) { for (Iterator<CallStackElement> iterator = children.iterator(); iterator.hasNext(); ) { CallStackElement child = iterator.next(); if (child.executionTime < thresholdNs && !child.isIOQuery()) { iterator.remove(); child.recycle(); } else { child.removeCallsFasterThan(thresholdNs); } } }
@Test public void testProfiler() { ProfilerTest profilerTest = new ProfilerTest(); CallStackElement total = Profiler.activateProfiling("total"); Assert.assertEquals(21, profilerTest.method1()); Profiler.stop(); Assert.assertEquals(total.toString(), 1, total.getChildren().size()); Assert.assertEquals(total.toString(), 3, total.getChildren().get(0).getChildren().size()); final String method5 = total.getChildren().get(0).getChildren().get(2).getSignature(); Assert.assertTrue(method5, method5.contains("org.stagemonitor.tracing.prof.ProfilerTest.method5")); }
@Test public void testFreemarkerProfilingMethodCall() throws Exception { final CallStackElement callTree = Profiler.activateProfiling("testFreemarkerProfilingMethodCall"); final String renderedTemplate = processTemplate("test.ftl", "${templateModel.getFoo()}", new TemplateModel()); Profiler.stop(); Profiler.deactivateProfiling(); assertThat(renderedTemplate).isEqualTo("foo"); System.out.println(callTree); assertThat(callTree.getChildren()).hasSize(1); final CallStackElement freemarkerNode = callTree.getChildren().get(0); assertThat(freemarkerNode.getSignature()).isEqualTo("test.ftl:1#templateModel.getFoo()"); assertThat(freemarkerNode.getChildren()).hasSize(1); final CallStackElement templateModelNode = freemarkerNode.getChildren().get(0); assertThat(templateModelNode.getSignature()).isEqualTo("String org.stagemonitor.tracing.freemarker.FreemarkerProfilingTransformerTest$TemplateModel.getFoo()"); }
@Test public void testShortSignature() { final String signature = "foobar.ftl:123#foo.getBar('123').baz"; // don't try to shorten ftl signatures assertThat(CallStackElement.createRoot(signature).getShortSignature()).isNull(); }
@Test public void testProfileServlet() throws Exception { Filter filter = new CompositeFilter(); final CallStackElement total = Profiler.activateProfiling("total"); filter.doFilter(new MockHttpServletRequest(), new MockHttpServletResponse(), new MockFilterChain()); Profiler.stop(); final CallStackElement serviceCall = total.getChildren().iterator().next(); assertEquals("CompositeFilter#doFilter", serviceCall.getShortSignature()); }
@Test public void testRemoveCallsFasterThanNotIncluded() { final CallStackElement callStackElement = TestClass.method0(); callStackElement.removeCallsFasterThan(TimeUnit.MILLISECONDS.toNanos(50)); assertEquals( "----------------------------------------------------------------------\n" + "Selftime (ms) Total (ms) Method signature\n" + "----------------------------------------------------------------------\n" + "000000.00 000% ---------- 001000.00 100% |||||||||| method0\n" + "000000.00 000% ---------- 001000.00 100% |||||||||| `-- method1\n" + "000050.00 005% :--------- 000500.00 050% |||||----- |-- method1_1\n" + "000200.00 020% ||-------- 000200.00 020% ||-------- | |-- method1_1_1\n" + "000200.00 020% ||-------- 000250.00 025% ||:------- | `-- method1_1_2\n" + "000050.00 005% :--------- 000050.00 005% :--------- | `-- method1_1_2_1\n" + "000150.00 015% |:-------- 000500.00 050% |||||----- `-- method1_2\n" + "000050.00 005% :--------- 000050.00 005% :--------- |-- select * from user \n" + "000050.00 005% :--------- 000050.00 005% :--------- |-- select * from address \n" + "000250.00 025% ||:------- 000250.00 025% ||:------- `-- method1_2_1\n", callStackElement.toString()); callStackElement.recycle(); }
private void addCallTreeToSpan(SpanContextInformation info, Span span, String operationName) { final CallStackElement callTree = info.getCallTree(); callTree.setSignature(operationName); final double minExecutionTimeMultiplier = tracingPlugin.getMinExecutionTimePercent() / 100; if (minExecutionTimeMultiplier > 0d) { callTree.removeCallsFasterThan((long) (callTree.getExecutionTime() * minExecutionTimeMultiplier)); } if (!tracingPlugin.getExcludedTags().contains(SpanUtils.CALL_TREE_JSON)) { span.setTag(SpanUtils.CALL_TREE_JSON, JsonUtils.toJson(callTree)); } if (!tracingPlugin.getExcludedTags().contains(SpanUtils.CALL_TREE_ASCII)) { span.setTag(SpanUtils.CALL_TREE_ASCII, callTree.toString(true, tracingPlugin.getCallTreeAsciiFormatter())); } } }
private boolean isLastChild() { if (parent == null) { return true; } final List<CallStackElement> parentChildren = parent.getChildren(); return parentChildren.get(parentChildren.size() - 1) == this; }
/** * <pre>{@code * test.ftl:1#templateModel.getFoo() <- added by {@code freemarker.core.MethodCall#_eval(Environment)} * |-- test.ftl:1#templateModel.getFoo <- added by {@code freemarker.core.Dot#_eval(Environment)} * `-- String org.stagemonitor.tracing.freemarker.FreemarkerProfilingTest$TemplateModel.getFoo() * }</pre> * * We want to remove <code>templateModel.getFoo</code> as getFoo only returns the method reference, which is then * invoked by {@code freemarker.core.MethodCall#_eval(Environment)}. * Therefore, <code>getFoo</code> does not invoke the model and thus is not relevant for the call tree */ private static void removeCurrentNodeIfItHasNoChildren(CallStackElement currentFreemarkerCall) { if (currentFreemarkerCall != null && currentFreemarkerCall.getChildren().isEmpty()) { currentFreemarkerCall.remove(); } }
@Test public void testProfiler() { final CallStackElement callStackElement = TestClass.method0(); assertEquals( "----------------------------------------------------------------------\n" + "Selftime (ms) Total (ms) Method signature\n" + "----------------------------------------------------------------------\n" + "000000.00 000% ---------- 001000.00 100% |||||||||| method0\n" + "000000.00 000% ---------- 001000.00 100% |||||||||| `-- method1\n" + "000050.00 005% :--------- 000500.00 050% |||||----- |-- method1_1\n" + "000200.00 020% ||-------- 000200.00 020% ||-------- | |-- method1_1_1\n" + "000200.00 020% ||-------- 000250.00 025% ||:------- | `-- method1_1_2\n" + "000050.00 005% :--------- 000050.00 005% :--------- | `-- method1_1_2_1\n" + "000150.00 015% |:-------- 000500.00 050% |||||----- `-- method1_2\n" + "000050.00 005% :--------- 000050.00 005% :--------- |-- select * from user \n" + "000050.00 005% :--------- 000050.00 005% :--------- |-- select * from address \n" + "000250.00 025% ||:------- 000250.00 025% ||:------- `-- method1_2_1\n", callStackElement.toString()); callStackElement.recycle(); }
@Override public String getSignature(CallStackElement callTreeElement) { return callTreeElement.getSignature(); }
@Override public String toString() { return toString(false, new ShortSignatureFormatter()); }
@Override public void finalize() throws Throwable { super.finalize(); if (callTree != null) { callTree.recycle(); } }
private void appendPercent(StringBuilder sb, long time, long totalExecutionTimeNs, boolean asciiArt) { final double percent = time / (double) totalExecutionTimeNs; sb.append(String.format(Locale.US, "%03.0f", percent * 100)).append("% ").append(printPercentAsBar(percent, 10, asciiArt)).append(' '); }
@Test public void testInnerPrivateMethod() { class Test { private void test() { } } Test test = new Test(); CallStackElement total = Profiler.activateProfiling("total"); test.test(); Profiler.stop(); Assert.assertFalse(total.toString(), total.getChildren().iterator().next().getSignature().contains("access$")); }
@Test public void testFreemarkerProfiling() throws Exception { final CallStackElement callTree = Profiler.activateProfiling("testFreemarkerProfiling"); final String renderedTemplate = processTemplate("test.ftl", "${templateModel.foo}", new TemplateModel()); Profiler.stop(); Profiler.deactivateProfiling(); assertThat(renderedTemplate).isEqualTo("foo"); System.out.println(callTree); assertThat(callTree.getChildren()).hasSize(1); final CallStackElement freemarkerNode = callTree.getChildren().get(0); assertThat(freemarkerNode.getSignature()).isEqualTo("test.ftl:1#templateModel.foo"); assertThat(freemarkerNode.getChildren()).hasSize(1); final CallStackElement templateModelNode = freemarkerNode.getChildren().get(0); assertThat(templateModelNode.getSignature()).isEqualTo("String org.stagemonitor.tracing.freemarker.FreemarkerProfilingTransformerTest$TemplateModel.getFoo()"); }