diff --git a/src/main/java/com/profiler/StopWatch.java b/src/main/java/com/profiler/StopWatch.java index fb1d6625e..d5fc6d45e 100644 --- a/src/main/java/com/profiler/StopWatch.java +++ b/src/main/java/com/profiler/StopWatch.java @@ -9,25 +9,37 @@ public class StopWatch { private static ThreadLocal> local = new NamedThreadLocal>("StopWatch"); - public static void start(String name) { + public static void start(int id) { + start(String.valueOf(id)); + } + + public static long stopAndGetElapsed(int id) { + return stopAndGetElapsed(String.valueOf(id)); + } + + public static void start(String id) { Map map = local.get(); if (map == null) { map = new HashMap(1); - map.put(name, System.nanoTime()); + map.put(id, System.nanoTime()); local.set(map); } else { - map.put(name, System.nanoTime()); + map.put(id, System.nanoTime()); } } - public static long stopAndGetElapsed(String name) { + public static long stopAndGetElapsed(String id) { Map map = local.get(); if (map == null) { - //throw new IllegalStateException("Stopwatch is not started."); - // TODO application 에러로 전달되는경우가 있어서 일단 0으로 - return 0; + // throw new IllegalStateException("Stopwatch is not started."); + // TODO application 에러로 전달되는경우가 있어서 일단 0으로 + return -1; } else { - return System.nanoTime() - map.get(name); + if (map.containsKey(id)) { + return System.nanoTime() - map.get(id); + } else { + return -1; + } } } } diff --git a/src/main/java/com/profiler/context/HippoAnnotation.java b/src/main/java/com/profiler/context/HippoAnnotation.java index 9b2b17ac0..a8027b439 100644 --- a/src/main/java/com/profiler/context/HippoAnnotation.java +++ b/src/main/java/com/profiler/context/HippoAnnotation.java @@ -7,6 +7,12 @@ public class HippoAnnotation { protected final Long duration; protected final String threadname; // TODO: remove, just for debug. + /** + * + * @param time + * @param value + * @param duration duration in nano second. + */ public HippoAnnotation(long time, String value, Long duration) { this.time = time; this.value = value; diff --git a/src/main/java/com/profiler/context/Span.java b/src/main/java/com/profiler/context/Span.java index 045eaacaf..01ff8995e 100644 --- a/src/main/java/com/profiler/context/Span.java +++ b/src/main/java/com/profiler/context/Span.java @@ -24,16 +24,20 @@ public class Span { private final List annotations = new ArrayList(5); private final Set annotationValues = new HashSet(5); + /** + * Cancel timer logic. + * TODO: refactor this. + */ private TimerTask timerTask; - + public void setTimerTask(TimerTask task) { this.timerTask = task; } - + public boolean cancelTimer() { return timerTask.cancel(); } - + public Span(TraceID traceId, String name, EndPoint endPoint) { this.traceID = traceId; this.name = name; @@ -108,8 +112,8 @@ public class Span { com.profiler.context.gen.Span span = new com.profiler.context.gen.Span(); span.setTimestamp(createTime); - span.setMostTraceID(traceID.getTraceId().getMostSignificantBits()); - span.setLeastTraceID(traceID.getTraceId().getLeastSignificantBits()); + span.setMostTraceID(traceID.getId().getMostSignificantBits()); + span.setLeastTraceID(traceID.getId().getLeastSignificantBits()); span.setName(name); span.setSpanID(traceID.getSpanId()); span.setParentSpanId(traceID.getParentSpanId()); diff --git a/src/main/java/com/profiler/context/Trace.java b/src/main/java/com/profiler/context/Trace.java index 6ad3908e8..c9f6459dc 100644 --- a/src/main/java/com/profiler/context/Trace.java +++ b/src/main/java/com/profiler/context/Trace.java @@ -17,7 +17,7 @@ public final class Trace { private static final DeadlineSpanMap spanMap = new DeadlineSpanMap(); - private static final ThreadLocal traceId = new NamedThreadLocal("TraceId"); + private static final ThreadLocal traceIdLocal = new NamedThreadLocal("TraceId"); private static volatile boolean tracingEnabled = true; @@ -30,12 +30,12 @@ public final class Trace { * * @return */ - public static TraceID getTraceId() { - TraceID id = traceId.get(); + public static TraceID getTraceIdOrCreateNew() { + TraceID id = traceIdLocal.get(); if (id == null) { id = TraceID.newTraceId(); - traceId.set(id); + traceIdLocal.set(id); return id; } @@ -43,9 +43,10 @@ public final class Trace { } public static boolean removeTraceId() { - TraceID traceID = traceId.get(); + TraceID traceID = traceIdLocal.get(); if (traceID != null) { - traceId.remove(); + traceIdLocal.remove(); + spanMap.remove(traceID); return true; } return false; @@ -57,7 +58,7 @@ public final class Trace { * @return */ public static TraceID getCurrentTraceId() { - return traceId.get(); + return traceIdLocal.get(); } public static void enable() { @@ -68,13 +69,16 @@ public final class Trace { tracingEnabled = false; } - public static TraceID getNextId() { - TraceID current = getTraceId(); - return new TraceID(current.getTraceId(), current.getSpanId(), SpanID.newSpanID(), current.isSampled(), current.getFlags()); + public static TraceID getNextTraceId() { + TraceID current = getTraceIdOrCreateNew(); + return new TraceID(current.getId(), current.getSpanId(), SpanID.newSpanID(), current.isSampled(), current.getFlags()); } public static void setTraceId(TraceID traceId) { - Trace.traceId.set(traceId); + if (getCurrentTraceId() != null) { + logger.log(Level.WARNING, "TraceID is already exists. But overwritten."); + } + Trace.traceIdLocal.set(traceId); } private static void mutate(TraceID traceId, SpanUpdater spanUpdater) { @@ -88,9 +92,16 @@ public final class Trace { static void logSpan(Span span) { try { - // TODO: send span to server - System.out.println("\n\nWrite span hash=" + span.hashCode() + ", value=" + span + ", spanMap.size=" + spanMap.size() + ", threadid=" + Thread.currentThread().getId() + "\n\n"); + // TODO: send span to the server. + System.out.println("\n\n[WRITE SPAN] hashCode=" + span.hashCode() + ", Value=" + span + ", SpanMap.size=" + spanMap.size() + ", CurrentThreadID=" + Thread.currentThread().getId() + "\n\n"); + // TODO: remove this, just for debugging + if(spanMap.size() > 0) { + System.out.println("###############################################################"); + System.out.println("# WARNING SpanMap size > 0 check spanMap. #"); + System.out.println("###############################################################"); + } + DataSender.getInstance().addDataToSend(span.toThrift()); span.cancelTimer(); @@ -116,13 +127,13 @@ public final class Trace { public static void recordAttribute(final String key, final String value) { recordAttibute(key, (Object) value); } - + public static void recordAttibute(final String key, final Object value) { if (!tracingEnabled) return; try { - mutate(getTraceId(), new SpanUpdater() { + mutate(getTraceIdOrCreateNew(), new SpanUpdater() { @Override public Span updateSpan(Span span) { span.addAnnotation(new HippoBinaryAnnotation(System.currentTimeMillis(), key, value)); @@ -144,8 +155,9 @@ public final class Trace { public static void recordRpcName(final String service, final String rpc) { if (!tracingEnabled) return; + try { - mutate(getTraceId(), new SpanUpdater() { + mutate(getTraceIdOrCreateNew(), new SpanUpdater() { @Override public Span updateSpan(Span span) { span.setServiceName(service); @@ -163,7 +175,7 @@ public final class Trace { return; try { - mutate(getTraceId(), new SpanUpdater() { + mutate(getTraceIdOrCreateNew(), new SpanUpdater() { @Override public Span updateSpan(Span span) { // set endpoint to both span and annotations @@ -181,7 +193,7 @@ public final class Trace { return; try { - mutate(getTraceId(), new SpanUpdater() { + mutate(getTraceIdOrCreateNew(), new SpanUpdater() { @Override public Span updateSpan(Span span) { span.addAnnotation(new HippoAnnotation(System.currentTimeMillis(), value, duration)); diff --git a/src/main/java/com/profiler/context/TraceID.java b/src/main/java/com/profiler/context/TraceID.java index 33699169c..a9bb469fb 100644 --- a/src/main/java/com/profiler/context/TraceID.java +++ b/src/main/java/com/profiler/context/TraceID.java @@ -3,7 +3,7 @@ package com.profiler.context; import java.util.UUID; public class TraceID { - private UUID traceId; + private UUID id; private long parentSpanId; private long spanId; private boolean sampled; @@ -14,21 +14,21 @@ public class TraceID { return new TraceID(uuid, SpanID.NULL, SpanID.newSpanID(), false, 0); } - public TraceID(UUID traceId, long parentSpanId, long spanId, boolean sampled, int flags) { - this.traceId = traceId; + public TraceID(UUID id, long parentSpanId, long spanId, boolean sampled, int flags) { + this.id = id; this.parentSpanId = parentSpanId; this.spanId = spanId; this.sampled = sampled; this.flags = flags; } - public UUID getTraceId() { - return traceId; + public UUID getId() { + return id; } public TraceKey getTraceKey() { - long most = traceId.getMostSignificantBits(); - long least = traceId.getLeastSignificantBits(); + long most = id.getMostSignificantBits(); + long least = id.getLeastSignificantBits(); return new TraceKey(most, least); } @@ -83,7 +83,7 @@ public class TraceID { } public void setTraceId(UUID traceId) { - this.traceId = traceId; + this.id = traceId; } public void setParentSpanId(long parentSpanId) { @@ -107,7 +107,7 @@ public class TraceID { StringBuilder sb = new StringBuilder(); sb.append("TraceID={"); - sb.append("traceId=").append(traceId); + sb.append("id=").append(id); sb.append(", parentSpanId=").append(parentSpanId); sb.append(", spanId=").append(spanId); sb.append(", sampled=").append(sampled); diff --git a/src/main/java/com/profiler/modifier/arcus/ArcusClientModifier.java b/src/main/java/com/profiler/modifier/arcus/ArcusClientModifier.java index a26943307..27f8ba122 100644 --- a/src/main/java/com/profiler/modifier/arcus/ArcusClientModifier.java +++ b/src/main/java/com/profiler/modifier/arcus/ArcusClientModifier.java @@ -4,6 +4,7 @@ import java.security.ProtectionDomain; import java.util.logging.Level; import java.util.logging.Logger; +import com.profiler.StopWatch; import com.profiler.interceptor.bci.ByteCodeInstrumentor; import com.profiler.interceptor.bci.InstrumentClass; import com.profiler.modifier.AbstractModifier; @@ -40,7 +41,7 @@ public class ArcusClientModifier extends AbstractModifier { */ aClass.addTraceVariable("__traceId", "__setTraceId", "__getTraceId", "com.profiler.context.TraceID"); aClass.addTraceVariable("__nextTraceId", "__setNextTraceId", "__getNextTraceId", "com.profiler.context.TraceID"); - aClass.insertCodeAfterConstructor(null, "{ __setTraceId(com.profiler.context.Trace.getCurrentTraceId()); __setNextTraceId(com.profiler.context.Trace.getNextId()); }"); + aClass.insertCodeAfterConstructor(null, "{ __setTraceId(com.profiler.context.Trace.getCurrentTraceId()); __setNextTraceId(com.profiler.context.Trace.getNextTraceId()); }"); aClass.insertCodeBeforeMethod("transitionState", new String[] { "net.spy.memcached.ops.OperationState" }, getTransitionStateAfterCode()); @@ -79,6 +80,10 @@ public class ArcusClientModifier extends AbstractModifier { // code.append("System.out.println(\"\");"); code.append("if (newState == net.spy.memcached.ops.OperationState.READING) {"); + + // TODO: remove, debugging + code.append("System.out.println(\"\\n\\n\\nINVOKE ARCUS BEFORE ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++\");"); + code.append(" java.net.SocketAddress socketAddress = handlingNode.getSocketAddress();"); code.append(" if (socketAddress instanceof java.net.InetSocketAddress) {"); code.append(" java.net.InetSocketAddress addr = (java.net.InetSocketAddress) handlingNode.getSocketAddress();"); @@ -87,10 +92,15 @@ public class ArcusClientModifier extends AbstractModifier { code.append(" com.profiler.context.Trace.recordRpcName(\"arcus\", \"\");"); code.append(" com.profiler.context.Trace.recordAttribute(\"arcus.command\", ((cmd == null) ? \"UNKNOWN\" : new String(cmd.array())));"); code.append(" System.out.println(\"CS\");"); + code.append(" com.profiler.StopWatch.start(this.hashCode());"); code.append(" com.profiler.context.Trace.record(com.profiler.context.Annotation.ClientSend);"); code.append("} else if (newState == net.spy.memcached.ops.OperationState.COMPLETE) {"); code.append(" System.out.println(\"CR\");"); - code.append(" com.profiler.context.Trace.record(com.profiler.context.Annotation.ClientRecv);"); + code.append(" com.profiler.context.Trace.record(com.profiler.context.Annotation.ClientRecv, com.profiler.StopWatch.stopAndGetElapsed(this.hashCode()));"); + + // TODO: remove, debugging + code.append("System.out.println(\"\\n\\n\\nINVOKE ARCUS AFTER ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++\");"); + code.append("}"); code.append("}"); diff --git a/src/main/java/com/profiler/modifier/connector/interceptors/ExecuteMethodInterceptor.java b/src/main/java/com/profiler/modifier/connector/interceptors/ExecuteMethodInterceptor.java index ea8a82e60..c7174e46e 100644 --- a/src/main/java/com/profiler/modifier/connector/interceptors/ExecuteMethodInterceptor.java +++ b/src/main/java/com/profiler/modifier/connector/interceptors/ExecuteMethodInterceptor.java @@ -27,15 +27,15 @@ public class ExecuteMethodInterceptor implements StaticAroundInterceptor { @Override public void before(Object target, String className, String methodName, Object[] args) { - System.out.println("\n\n\n\nHTTP BEFORE"); + System.out.println("\n\n\n\nINVOKE HTTP START ----------------------------------------------------------------------------------------------------------------------------------------------------"); HttpHost host = (HttpHost) args[0]; HttpRequest request = (HttpRequest) args[1]; - TraceID nextId = Trace.getNextId(); + TraceID nextId = Trace.getNextTraceId(); // UUID format을 그대로. - request.addHeader(Header.HTTP_TRACE_ID.toString(), nextId.getTraceId().toString()); + request.addHeader(Header.HTTP_TRACE_ID.toString(), nextId.getId().toString()); request.addHeader(Header.HTTP_SPAN_ID.toString(), Long.toString(nextId.getSpanId())); request.addHeader(Header.HTTP_PARENT_SPAN_ID.toString(), Long.toString(nextId.getParentSpanId())); request.addHeader(Header.HTTP_SAMPLED.toString(), String.valueOf(nextId.isSampled())); @@ -51,7 +51,7 @@ public class ExecuteMethodInterceptor implements StaticAroundInterceptor { @Override public void after(Object target, String className, String methodName, Object[] args, Object result) { - System.out.println("\n\n\n\nHTTP AFTER"); Trace.record(Annotation.ClientRecv, StopWatch.stopAndGetElapsed("ExecuteMethodInterceptor")); + System.out.println("\n\n\n\nINVOKE HTTP END ----------------------------------------------------------------------------------------------------------------------------------------------------"); } } \ No newline at end of file diff --git a/src/main/java/com/profiler/modifier/tomcat/interceptors/InvokeMethodInterceptor.java b/src/main/java/com/profiler/modifier/tomcat/interceptors/InvokeMethodInterceptor.java index 51aa8b35d..f99ff3df0 100644 --- a/src/main/java/com/profiler/modifier/tomcat/interceptors/InvokeMethodInterceptor.java +++ b/src/main/java/com/profiler/modifier/tomcat/interceptors/InvokeMethodInterceptor.java @@ -5,6 +5,7 @@ import java.util.UUID; import javax.servlet.http.HttpServletRequest; +import com.profiler.StopWatch; import com.profiler.context.Annotation; import com.profiler.context.Header; import com.profiler.context.SpanID; @@ -12,45 +13,33 @@ import com.profiler.context.Trace; import com.profiler.context.TraceID; import com.profiler.interceptor.StaticAroundInterceptor; import com.profiler.trace.RequestTracer; -import com.profiler.util.NamedThreadLocal; import com.profiler.util.NumberUtils; public class InvokeMethodInterceptor implements StaticAroundInterceptor { - private ThreadLocal start = new NamedThreadLocal("InvokeMethodInterceptor-starttime"); - @Override public void before(Object target, String className, String methodName, Object[] args) { try { HttpServletRequest request = (HttpServletRequest) args[0]; String requestURL = request.getRequestURI(); String clientIP = request.getRemoteAddr(); - String parameters = getParameter(request); + String parameters = getRequestParameter(request); - UUID traceID = getTraceId(request); - if (traceID != null) { - long parentSpanID = NumberUtils.parseLong(request.getHeader(Header.HTTP_PARENT_SPAN_ID.toString()), SpanID.NULL); - long spanID = NumberUtils.parseLong(request.getHeader(Header.HTTP_SPAN_ID.toString()), SpanID.NULL); - boolean sampled = Boolean.parseBoolean(request.getHeader(Header.HTTP_SAMPLED.toString())); - int flags = NumberUtils.parseInteger(request.getHeader(Header.HTTP_FLAGS.toString()), 0); - - TraceID id = new TraceID(traceID, parentSpanID, spanID, sampled, flags); - - // TODO : refactor this, just for debug - System.out.println("\n\n\ngot a traceid. traceid=" + id + "\n\n\n"); - - Trace.setTraceId(id); + TraceID traceId = populateTraceIdFromRequest(request); + if (traceId != null) { + Trace.setTraceId(traceId); } else { Trace.setTraceId(TraceID.newTraceId()); } Trace.recordRpcName("tomcat", requestURL); Trace.recordEndPoint(request.getLocalAddr(), request.getLocalPort()); - Trace.recordMessage("Parameter=" + parameters); + Trace.recordAttibute("http.params", parameters); Trace.record(Annotation.ServerRecv); RequestTracer.startTransaction(requestURL, clientIP, System.currentTimeMillis(), parameters); - start.set(System.currentTimeMillis()); + + StopWatch.start("InvokeMethodInterceptor-starttime"); } catch (Exception e) { e.printStackTrace(); } @@ -59,24 +48,38 @@ public class InvokeMethodInterceptor implements StaticAroundInterceptor { @Override public void after(Object target, String className, String methodName, Object[] args, Object result) { // TODO result 가 Exception 타입일경우 호출 실패임. - Trace.record(Annotation.ServerSend, System.currentTimeMillis() - start.get()); - start.remove(); + Trace.record(Annotation.ServerSend, StopWatch.stopAndGetElapsed("InvokeMethodInterceptor-starttime")); RequestTracer.endTransaction(); } - private UUID getTraceId(HttpServletRequest request) { - String header = request.getHeader(Header.HTTP_TRACE_ID.toString()); - if (header == null) { - return null; - } - try { - return UUID.fromString(header); - } catch (IllegalArgumentException e) { + /** + * Pupulate source trace from HTTP Header. + * + * @param request + * @return + */ + private TraceID populateTraceIdFromRequest(HttpServletRequest request) { + String strUUID = request.getHeader(Header.HTTP_TRACE_ID.toString()); + + if (strUUID != null) { + UUID uuid = UUID.fromString(strUUID); + long parentSpanID = NumberUtils.parseLong(request.getHeader(Header.HTTP_PARENT_SPAN_ID.toString()), SpanID.NULL); + long spanID = NumberUtils.parseLong(request.getHeader(Header.HTTP_SPAN_ID.toString()), SpanID.NULL); + boolean sampled = Boolean.parseBoolean(request.getHeader(Header.HTTP_SAMPLED.toString())); + int flags = NumberUtils.parseInteger(request.getHeader(Header.HTTP_FLAGS.toString()), 0); + + TraceID id = new TraceID(uuid, parentSpanID, spanID, sampled, flags); + + // TODO : remove this, just for debug + System.out.println("\nGOT A TRACEID. TRACEID=" + id + "\n\n"); + + return id; + } else { return null; } } - private String getParameter(HttpServletRequest request) { + private String getRequestParameter(HttpServletRequest request) { Enumeration attrs = request.getParameterNames(); StringBuilder params = new StringBuilder(); diff --git a/src/test/java/com/profiler/context/SpanTest.java b/src/test/java/com/profiler/context/SpanTest.java index f0356646c..41be272a3 100644 --- a/src/test/java/com/profiler/context/SpanTest.java +++ b/src/test/java/com/profiler/context/SpanTest.java @@ -49,7 +49,7 @@ public class SpanTest { e.printStackTrace(); } - Trace.setTraceId(Trace.getNextId()); + Trace.setTraceId(Trace.getNextTraceId()); Trace.recordMessage("msg:client send"); Trace.record(Annotation.ClientSend); diff --git a/src/test/java/com/profiler/context/TraceTest.java b/src/test/java/com/profiler/context/TraceTest.java index 55d2df705..0399de714 100644 --- a/src/test/java/com/profiler/context/TraceTest.java +++ b/src/test/java/com/profiler/context/TraceTest.java @@ -6,8 +6,8 @@ public class TraceTest { @Test public void trace() { - TraceID nextId = Trace.getNextId(); - nextId.setSampled(Trace.getTraceId().isSampled()); + TraceID nextId = Trace.getNextTraceId(); + nextId.setSampled(Trace.getTraceIdOrCreateNew().isSampled()); Trace.setTraceId(nextId); diff --git a/src/test/java/com/profiler/modifier/db/mysql/MySQLConnectionImplModifierTest.java b/src/test/java/com/profiler/modifier/db/mysql/MySQLConnectionImplModifierTest.java index c3dc162e1..08d31d8a0 100644 --- a/src/test/java/com/profiler/modifier/db/mysql/MySQLConnectionImplModifierTest.java +++ b/src/test/java/com/profiler/modifier/db/mysql/MySQLConnectionImplModifierTest.java @@ -48,7 +48,7 @@ public class MySQLConnectionImplModifierTest { properties.setProperty("password", "testlucy"); Connection connect = driver.connect("jdbc:mysql://10.98.133.22:3306/hippo", properties); - Trace.getTraceId(); + Trace.getTraceIdOrCreateNew(); logger.info("Connection class name:" + connect.getClass().getName()); logger.info("Connection class cl:" + connect.getClass().getClassLoader());