From ebd454da32c78443f1dc1bdc69ed41ae8d639741 Mon Sep 17 00:00:00 2001 From: Chisu Yu Date: Thu, 6 Sep 2012 04:15:57 +0000 Subject: [PATCH] =?UTF-8?q?[=EC=9C=A0=EC=B9=98=EC=88=98]=20[NOBTS]=20add?= =?UTF-8?q?=20draft=20trace=20stack?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit git-svn-id: http://svn.bds.nhncorp.com/pe/hippo-tomcat-profiler/trunk@586 84d0f5b1-2673-498c-a247-62c4ff18d310 --- .../com/profiler/context/DeadlineSpanMap.java | 5 + src/main/java/com/profiler/context/Trace.java | 130 +++++++++++++++--- .../com/profiler/context/TraceHandler.java | 5 + .../java/com/profiler/context/TraceID.java | 12 +- .../com/profiler/context/TraceIDStack.java | 48 +++++++ .../connector/HTTPClientModifier.java | 6 + .../ExecuteMethodInterceptor.java | 11 +- .../java/com/profiler/context/TraceTest.java | 17 ++- 8 files changed, 207 insertions(+), 27 deletions(-) create mode 100644 src/main/java/com/profiler/context/TraceHandler.java create mode 100644 src/main/java/com/profiler/context/TraceIDStack.java diff --git a/src/main/java/com/profiler/context/DeadlineSpanMap.java b/src/main/java/com/profiler/context/DeadlineSpanMap.java index 5f82c0d74..d2174854f 100644 --- a/src/main/java/com/profiler/context/DeadlineSpanMap.java +++ b/src/main/java/com/profiler/context/DeadlineSpanMap.java @@ -50,4 +50,9 @@ public class DeadlineSpanMap { Trace.logSpan(this.span); } } + + @Override + public String toString() { + return map.toString(); + } } diff --git a/src/main/java/com/profiler/context/Trace.java b/src/main/java/com/profiler/context/Trace.java index 2a57d4d45..67bf152da 100644 --- a/src/main/java/com/profiler/context/Trace.java +++ b/src/main/java/com/profiler/context/Trace.java @@ -17,7 +17,12 @@ public final class Trace { private static final DeadlineSpanMap spanMap = new DeadlineSpanMap(); - private static final ThreadLocal traceIdLocal = new NamedThreadLocal("TraceId"); + // private static final ThreadLocal traceIdLocal = new + // NamedThreadLocal("TraceId"); + + private static final ThreadLocal traceIdLocal = new NamedThreadLocal("TraceId"); + + // private static final TraceIDStack traceIdStack = new TraceIDStack(); private static volatile boolean tracingEnabled = true; @@ -25,17 +30,78 @@ public final class Trace { } + public static void handle(TraceHandler handler) { + TraceIDStack traceIDStack = traceIdLocal.get(); + if (traceIDStack == null) { + traceIDStack = new TraceIDStack(); + traceIdLocal.set(traceIDStack); + } + + try { + TraceID nextId = getNextTraceId(); + traceIDStack.incr(); + + if (traceIDStack.getTraceId() == null) { + System.out.println(getCurrentTraceId()); + traceIDStack.setTraceId(nextId); + } + + handler.handle(); + } catch (Exception e) { + e.printStackTrace(); + } finally { + traceIDStack.decr(); + } + } + + public static void traceBlockBegin() { + TraceIDStack traceIDStack = traceIdLocal.get(); + if (traceIDStack == null) { + traceIDStack = new TraceIDStack(); + traceIdLocal.set(traceIDStack); + } + + try { + TraceID nextId = getNextTraceId(); + traceIDStack.incr(); + + if (traceIDStack.getTraceId() == null) { + traceIDStack.setTraceId(nextId); + } + } catch (Exception e) { + e.printStackTrace(); + } + } + + public static void traceBlockEnd() { + TraceIDStack traceIDStack = traceIdLocal.get(); + traceIDStack.decr(); + } + /** * Get current TraceID or if's not exists create new one and return it. * * @return */ public static TraceID getTraceIdOrCreateNew() { - TraceID id = traceIdLocal.get(); + // TraceID id = traceIdLocal.get(); + TraceIDStack stack = traceIdLocal.get(); + TraceID id = null; + if (stack != null) { + id = stack.getTraceId(); + } if (id == null) { + System.out.println("create new traceid"); + id = TraceID.newTraceId(); - traceIdLocal.set(id); + // traceIdLocal.set(id); + + if (stack == null) { + traceIdLocal.set(new TraceIDStack()); + } + + traceIdLocal.get().setTraceId(id); return id; } @@ -43,9 +109,21 @@ public final class Trace { } public static boolean removeTraceId() { - TraceID traceId = traceIdLocal.get(); + // TraceID traceId = traceIdLocal.get(); + TraceIDStack stack = traceIdLocal.get(); + TraceID traceId = null; + if (stack != null) + traceId = stack.getTraceId(); + if (traceId != null) { - traceIdLocal.remove(); + // traceIdLocal.remove(); + + if (stack == null) { + traceIdLocal.set(new TraceIDStack()); + } + + traceIdLocal.get().clear(); + spanMap.remove(traceId); return true; } @@ -58,7 +136,14 @@ public final class Trace { * @return */ public static TraceID getCurrentTraceId() { - return traceIdLocal.get(); + // return traceIdLocal.get(); + TraceIDStack stack = traceIdLocal.get(); + + if (stack == null) { + return null; + } + + return stack.getTraceId(); } public static void enable() { @@ -71,15 +156,18 @@ public final class Trace { public static TraceID getNextTraceId() { TraceID current = getTraceIdOrCreateNew(); - long currentSpanId = current.getSpanId(); - return new TraceID(current.getId(), currentSpanId, SpanID.nextSpanID(currentSpanId), current.isSampled(), current.getFlags()); + return current.getNextTraceId(); + // long currentSpanId = current.getSpanId(); + // return new TraceID(current.getId(), currentSpanId, + // SpanID.nextSpanID(currentSpanId), current.isSampled(), + // current.getFlags()); } public static void setTraceId(TraceID traceId) { if (getCurrentTraceId() != null) { logger.log(Level.WARNING, "TraceID is already exists. But overwritten."); - - //TODO: remove this, just for debugging. + + // TODO: remove this, just for debugging. System.out.println("###############################################################################################################"); System.out.println("# [DEBUG MSG] TraceID is overwritten."); System.out.println("# Before : " + getCurrentTraceId()); @@ -91,7 +179,14 @@ public final class Trace { e.printStackTrace(); } } - Trace.traceIdLocal.set(traceId); + + TraceIDStack stack = traceIdLocal.get(); + + if (stack == null) + traceIdLocal.set(new TraceIDStack()); + + Trace.traceIdLocal.get().setTraceId(traceId); + // Trace.traceIdLocal.set(traceId); } private static void mutate(TraceID traceId, SpanUpdater spanUpdater) { @@ -106,14 +201,15 @@ public final class Trace { static void logSpan(Span span) { try { // TODO: send span to the server. - System.out.println("\n\n[WRITE SPAN] hashCode=" + span.hashCode() + ",\n\t " + span + ",\n\t SpanMap.size=" + spanMap.size() + ",\n\t CurrentThreadID=" + Thread.currentThread().getId() + ",\n\t CurrentThreadName=" + Thread.currentThread().getName() +"\n\n"); + System.out.println("\n\n[WRITE SPAN] hashCode=" + span.hashCode() + ",\n\t " + span + ",\n\t SpanMap.size=" + spanMap.size() + ",\n\t CurrentThreadID=" + Thread.currentThread().getId() + ",\n\t CurrentThreadName=" + Thread.currentThread().getName() + "\n\n"); // TODO: remove this, just for debugging - if (spanMap.size() > 0) { - System.out.println("##################################################################"); - System.out.println("# [DEBUG MSG] WARNING SpanMap size > 0 check spanMap. #"); - System.out.println("##################################################################"); - } + // if (spanMap.size() > 0) { + // System.out.println("##################################################################"); + // System.out.println("# [DEBUG MSG] WARNING SpanMap size > 0 check spanMap. #"); + // System.out.println("##################################################################"); + // System.out.println("current spamMap=" + spanMap); + // } DataSender.getInstance().addDataToSend(span.toThrift()); diff --git a/src/main/java/com/profiler/context/TraceHandler.java b/src/main/java/com/profiler/context/TraceHandler.java new file mode 100644 index 000000000..728a9deb1 --- /dev/null +++ b/src/main/java/com/profiler/context/TraceHandler.java @@ -0,0 +1,5 @@ +package com.profiler.context; + +public interface TraceHandler { + public void handle(); +} \ No newline at end of file diff --git a/src/main/java/com/profiler/context/TraceID.java b/src/main/java/com/profiler/context/TraceID.java index 2ba33ffdc..6caf7f78d 100644 --- a/src/main/java/com/profiler/context/TraceID.java +++ b/src/main/java/com/profiler/context/TraceID.java @@ -14,6 +14,10 @@ public class TraceID { return new TraceID(uuid, SpanID.NULL, SpanID.newSpanID(), false, 0); } + public TraceID getNextTraceId() { + return new TraceID(id, spanId, SpanID.nextSpanID(spanId), sampled, flags); + } + public TraceID(UUID id, long parentSpanId, long spanId, boolean sampled, int flags) { this.id = id; this.parentSpanId = parentSpanId; @@ -29,16 +33,18 @@ public class TraceID { public TraceKey getTraceKey() { long most = id.getMostSignificantBits(); long least = id.getLeastSignificantBits(); - return new TraceKey(most, least); + return new TraceKey(most, least, spanId); } public static class TraceKey { private long most; private long least; + private long span; - public TraceKey(long most, long least) { + public TraceKey(long most, long least, long span) { this.most = most; this.least = least; + this.span = span; } @Override @@ -54,6 +60,8 @@ public class TraceID { return false; if (most != that.most) return false; + if (span != that.span) + return false; return true; } diff --git a/src/main/java/com/profiler/context/TraceIDStack.java b/src/main/java/com/profiler/context/TraceIDStack.java new file mode 100644 index 000000000..dfd0588c0 --- /dev/null +++ b/src/main/java/com/profiler/context/TraceIDStack.java @@ -0,0 +1,48 @@ +package com.profiler.context; + +/** + * + * @author netspider + * + */ +public class TraceIDStack { + + private TraceID[] traceIDs = new TraceID[1]; + + private volatile int index = 0; + + public TraceID getTraceId() { + return traceIDs[index]; + } + + public TraceID getParentTraceId() { + if (index > 0) { + return traceIDs[index - 1]; + } + System.out.println("PID is NULL"); + return null; + } + + public void setTraceId(TraceID traceId) { + traceIDs[index] = traceId; + } + + public void incr() { + index++; + if (index > traceIDs.length - 1) { + System.out.println("INCR"); + TraceID[] old = traceIDs; + traceIDs = new TraceID[index + 1]; + System.arraycopy(old, 0, traceIDs, 0, old.length); + } + } + + public void decr() { + if (index > 0) + index--; + } + + public void clear() { + traceIDs[index] = null; + } +} diff --git a/src/main/java/com/profiler/modifier/connector/HTTPClientModifier.java b/src/main/java/com/profiler/modifier/connector/HTTPClientModifier.java index 7749081bc..dbb0ec80c 100644 --- a/src/main/java/com/profiler/modifier/connector/HTTPClientModifier.java +++ b/src/main/java/com/profiler/modifier/connector/HTTPClientModifier.java @@ -47,6 +47,12 @@ public class HTTPClientModifier extends AbstractModifier { logger.info("Modifing. " + javassistClassName); } + try { + classLoader.loadClass("com.profiler.context.TraceHandler"); + } catch (Exception e) { + e.printStackTrace(); + } + Interceptor interceptor = newInterceptor(classLoader, protectedDomain, "com.profiler.modifier.connector.interceptors.ExecuteMethodInterceptor"); if (interceptor == null) { return null; 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 0e9d1f067..e406c430f 100644 --- a/src/main/java/com/profiler/modifier/connector/interceptors/ExecuteMethodInterceptor.java +++ b/src/main/java/com/profiler/modifier/connector/interceptors/ExecuteMethodInterceptor.java @@ -29,8 +29,10 @@ public class ExecuteMethodInterceptor implements StaticAroundInterceptor { public void before(Object target, String className, String methodName, String parameterDescription, Object[] args) { System.out.println("\n\n\n\nINVOKE HTTP START ----------------------------------------------------------------------------------------------------------------------------------------------------"); - HttpHost host = (HttpHost) args[0]; - HttpRequest request = (HttpRequest) args[1]; + final HttpHost host = (HttpHost) args[0]; + final HttpRequest request = (HttpRequest) args[1]; + + Trace.traceBlockBegin(); TraceID nextId = Trace.getNextTraceId(); @@ -46,12 +48,17 @@ public class ExecuteMethodInterceptor implements StaticAroundInterceptor { Trace.recordAttibute("http.url", request.toString()); Trace.record(Annotation.ClientSend); + Trace.traceBlockEnd(); + StopWatch.start("ExecuteMethodInterceptor"); } @Override public void after(Object target, String className, String methodName, String parameterDescription, Object[] args, Object result) { + Trace.traceBlockBegin(); Trace.record(Annotation.ClientRecv, StopWatch.stopAndGetElapsed("ExecuteMethodInterceptor")); + Trace.traceBlockEnd(); + System.out.println("\n\n\n\nINVOKE HTTP END ----------------------------------------------------------------------------------------------------------------------------------------------------"); } } \ No newline at end of file diff --git a/src/test/java/com/profiler/context/TraceTest.java b/src/test/java/com/profiler/context/TraceTest.java index 0399de714..ccc80d873 100644 --- a/src/test/java/com/profiler/context/TraceTest.java +++ b/src/test/java/com/profiler/context/TraceTest.java @@ -6,14 +6,13 @@ public class TraceTest { @Test public void trace() { - TraceID nextId = Trace.getNextTraceId(); - nextId.setSampled(Trace.getTraceIdOrCreateNew().isSampled()); - - Trace.setTraceId(nextId); + Trace.traceBlockBegin(); + Trace.setTraceId(TraceID.newTraceId()); // http server receive Trace.recordRpcName("service_name", "http://"); Trace.recordEndPoint("localhost", 8080); + Trace.recordAttibute("KEY", "VALUE"); Trace.record(Annotation.ServerRecv); // get data form db @@ -21,15 +20,21 @@ public class TraceTest { // response to client Trace.record(Annotation.ServerSend); + + Trace.traceBlockEnd(); } private void getDataFromDB() { + Trace.traceBlockBegin(); + // db server request - Trace.recordRpcName("mysql", "mysql"); - Trace.recordMessage("query"); + Trace.recordRpcName("mysql", "rpc"); + Trace.recordAttibute("mysql.query", "SELECT * FROM TABLE"); Trace.record(Annotation.ClientSend); // get a db response Trace.record(Annotation.ClientRecv); + + Trace.traceBlockEnd(); } }