diff --git a/src/main/java/com/profiler/context/Annotation.java b/src/main/java/com/profiler/context/Annotation.java index 4f0e4a976..4d7afe0de 100644 --- a/src/main/java/com/profiler/context/Annotation.java +++ b/src/main/java/com/profiler/context/Annotation.java @@ -1,15 +1,22 @@ package com.profiler.context; public enum Annotation { - ClientSend("CS"), ClientRecv("CR"), ServerSend("SS"), ServerRecv("SR"); + @Deprecated + ClientSend("CS"), + @Deprecated + ClientRecv("CR"), + @Deprecated + ServerSend("SS"), + @Deprecated + ServerRecv("SR"); - private String code; + private String code; - Annotation(String code) { - this.code = code; - } + Annotation(String code) { + this.code = code; + } - public String getCode() { - return this.code; - } + public String getCode() { + return this.code; + } } diff --git a/src/main/java/com/profiler/context/CallStack.java b/src/main/java/com/profiler/context/CallStack.java index 6625bad5c..83c29f5c5 100644 --- a/src/main/java/com/profiler/context/CallStack.java +++ b/src/main/java/com/profiler/context/CallStack.java @@ -1,18 +1,20 @@ package com.profiler.context; -import java.util.Arrays; +import java.util.logging.Level; +import java.util.logging.Logger; /** * @author netspider */ public class CallStack { + // CallStack을 동시성 환경에서 복사해서 볼수 있는 방법이 필요함. private StackFrame[] stack = new StackFrame[4]; // 추적 depth크기 제한을 위해서 필요. 해당 사이즈를 넘어갈경우 부드럽게 트레이스를 무시하는 로직이 필요함. private final int TRACE_STACK_MAX_SIZE = 64; - private int index = 0; + private int index = -1; // copy시의 락 생각할 경우 좀더 정교하게 잡을수 있을듯. // push, pop, copy만 락을 잡아도 될거 같은 생각이 듬. @@ -46,9 +48,16 @@ public class CallStack { } public synchronized void pop() { - if (index > 0) { + if (index >= 0) { stack[index] = null; index--; + } else { + Logger logger = Logger.getLogger(this.getClass().getName()); + if (logger.isLoggable(Level.WARNING)) { + // 자체 stack dump 필요. + Exception ex = new Exception("Profiler CallStack check. index:" + index); + logger.log(Level.WARNING, "invalid callStack found", ex); + } } } diff --git a/src/main/java/com/profiler/context/Span.java b/src/main/java/com/profiler/context/Span.java index 120e6c7a4..6828c7ecd 100644 --- a/src/main/java/com/profiler/context/Span.java +++ b/src/main/java/com/profiler/context/Span.java @@ -1,10 +1,7 @@ package com.profiler.context; import java.util.ArrayList; -import java.util.HashSet; import java.util.List; -import java.util.Set; -import java.util.TimerTask; import com.profiler.Agent; @@ -16,7 +13,10 @@ import com.profiler.Agent; public class Span { private final TraceID traceID; - private final long createTime; + + private long startTime; + + private long endTime; private String serviceName; private String name; @@ -25,23 +25,18 @@ public class Span { private final List annotations = new ArrayList(5); - private long rpcStartTime; - private long rpcEndTime; - public Span(TraceID traceId, String name, String endPoint) { this.traceID = traceId; this.name = name; this.endPoint = endPoint; - this.createTime = System.currentTimeMillis(); } + public TraceID getTraceID() { + return traceID; + } + + public boolean addAnnotation(HippoAnnotation annotation) { - if (annotation.getKey().equals(Annotation.ClientSend.getCode()) || annotation.getKey().equals(Annotation.ServerRecv.getCode())) { - rpcStartTime = annotation.getTimestamp(); - } - if (annotation.getKey().equals(Annotation.ClientRecv.getCode()) || annotation.getKey().equals(Annotation.ServerSend.getCode())) { - rpcEndTime = annotation.getTimestamp(); - } return annotations.add(annotation); } @@ -82,25 +77,29 @@ public class Span { this.isTerminal = isTerminal; } - public long getRpcStartTime() { - return rpcStartTime; + public void setStartTime(long startTime) { + this.startTime = startTime; } - public long getRpcEndTime() { - return rpcEndTime; + public long getStartTime() { + return startTime; } - public long getCreateTime() { - return createTime; + public void setEndTime(long endTime) { + this.endTime = endTime; } + public long getEndTime() { + return endTime; + } public String toString() { StringBuilder sb = new StringBuilder(); sb.append("{"); sb.append("\n\t TraceID = ").append(traceID); - sb.append(",\n\t CreateTime = ").append(createTime); + sb.append(",\n\t StartTime = ").append(startTime); + sb.append(",\n\t EndTime = ").append(endTime); sb.append(",\n\t Name = ").append(name); sb.append(",\n\t ServiceName = ").append(serviceName); sb.append(",\n\t EndPoint = ").append(endPoint); @@ -120,7 +119,9 @@ public class Span { com.profiler.common.dto.thrift.Span span = new com.profiler.common.dto.thrift.Span(); span.setAgentId(Agent.getInstance().getAgentId()); - span.setTimestamp(createTime); + span.setTimestamp(startTime); + // TODO api를 생성하고 여기를 고치자. + //span.setEndTime(startTime); span.setMostTraceId(traceID.getId().getMostSignificantBits()); span.setLeastTraceId(traceID.getId().getLeastSignificantBits()); span.setName(name); @@ -130,8 +131,7 @@ public class Span { span.setEndPoint(endPoint); span.setTerminal(isTerminal); - // TODO: set duration. - + // 여기서 데이터 인코딩을 하자. List annotationList = new ArrayList(annotations.size()); for (HippoAnnotation a : annotations) { annotationList.add(a.toThrift()); diff --git a/src/main/java/com/profiler/context/StackFrame.java b/src/main/java/com/profiler/context/StackFrame.java index 04462d694..7781ec860 100644 --- a/src/main/java/com/profiler/context/StackFrame.java +++ b/src/main/java/com/profiler/context/StackFrame.java @@ -4,21 +4,17 @@ package com.profiler.context; * */ public class StackFrame { - private TraceID traceID; + private int stackId; - private long time; private Span span; - public StackFrame() { + public StackFrame(Span span) { + this.span = span; } public TraceID getTraceID() { - return traceID; - } - - public void setTraceID(TraceID traceID) { - this.traceID = traceID; + return span.getTraceID(); } public int getStackFrameId() { @@ -30,15 +26,17 @@ public class StackFrame { } public void markBeforeTime() { - this.time = System.currentTimeMillis(); + this.span.setStartTime(System.currentTimeMillis()); + } + + public void markAfterTime() { + this.span.setEndTime(System.currentTimeMillis()); } public long afterTime() { - return System.currentTimeMillis() - this.time; - } - - public long getTime() { - return this.time; + long end = System.currentTimeMillis(); + this.span.setEndTime(end); + return end - this.span.getStartTime(); } diff --git a/src/main/java/com/profiler/context/Trace.java b/src/main/java/com/profiler/context/Trace.java index b44d76506..f3e5f6fef 100644 --- a/src/main/java/com/profiler/context/Trace.java +++ b/src/main/java/com/profiler/context/Trace.java @@ -34,6 +34,7 @@ public final class Trace { // traceObject에서 spanid의 유효성을 히스토리를 관리한다면 같은 thread에서는 span랜덤생성아이디의 충돌을 방지할수 있기는 함. this.root = TraceID.newTraceId(); this.callStack = new CallStack(); + this.callStack.push(); StackFrame stackFrame = createStackFrame(root, ROOT_STACKID); this.callStack.setStackFrame(stackFrame); } @@ -41,6 +42,7 @@ public final class Trace { public Trace(TraceID continueRoot) { this.root = continueRoot; this.callStack = new CallStack(); + this.callStack.push(); StackFrame stackFrame = createStackFrame(continueRoot, ROOT_STACKID); this.callStack.setStackFrame(stackFrame); } @@ -76,12 +78,9 @@ public final class Trace { } private StackFrame createStackFrame(TraceID nextId, int stackId) { - StackFrame stackFrame = new StackFrame(); - stackFrame.setStackFrameId(stackId); - stackFrame.setTraceID(nextId); - Span span = new Span(nextId, null, null); - stackFrame.setSpan(span); + StackFrame stackFrame = new StackFrame(span); + stackFrame.setStackFrameId(stackId); return stackFrame; } @@ -115,12 +114,22 @@ public final class Trace { traceBlockEnd(NOCHECK_STACKID); } +// public void traceBlockFinalEnd() { +// StackFrame currentStackFrame = callStack.getCurrentStackFrame(); +// if (currentStackFrame.getStackFrameId() != ROOT_STACKID) { +// // 자체 stack dump를 하면 오류발견이 쉬울것으로 생각됨. +// logger.warning("Corrupted RootCallStack found. StackId not matched"); +// } +// logSpan(currentStackFrame); +// } + public void traceBlockEnd(int stackId) { StackFrame currentStackFrame = callStack.getCurrentStackFrame(); if (currentStackFrame.getStackFrameId() != stackId) { // 자체 stack dump를 하면 오류발견이 쉬울것으로 생각됨. logger.warning("Corrupted CallStack found. StackId not matched"); } + logSpan(currentStackFrame); callStack.pop(); } @@ -128,16 +137,16 @@ public final class Trace { return callStack.getCurrentStackFrame(); } - public boolean removeCurrentTraceIdFromStack() { - StackFrame currentStackFrame = callStack.getCurrentStackFrame(); - if (currentStackFrame != null) { - TraceID traceId = currentStackFrame.getTraceID(); - callStack.currentStackFrameClear(); -// spanMap.remove(traceId); - return true; - } - return false; - } +// public boolean removeCurrentTraceIdFromStack() { +// StackFrame currentStackFrame = callStack.getCurrentStackFrame(); +// if (currentStackFrame != null) { +// TraceID traceId = currentStackFrame.getTraceID(); +// callStack.currentStackFrameClear(); +//// spanMap.remove(traceId); +// return true; +// } +// return false; +// } /** * Get current TraceID. If it was not set this will return null. @@ -162,16 +171,8 @@ public final class Trace { } - private void logSpan(String key, Span span) { - if (key == null) { - return; - } - if (key.equals(Annotation.ClientRecv.getCode()) || key.equals(Annotation.ServerSend.getCode())) { - logSpan(span); - } - } - - void logSpan(Span span) { + void logSpan(StackFrame stackFrame) { + Span span = stackFrame.getSpan(); try { if (logger.isLoggable(Level.INFO)) { logger.info("[WRITE SPAN]" + span + " CurrentThreadID=" + Thread.currentThread().getId() + ",\n\t CurrentThreadName=" + Thread.currentThread().getName() + "\n\n"); @@ -272,7 +273,7 @@ public final class Trace { try { Span span = getCurrentStackFrame().getSpan(); span.addAnnotation(new HippoAnnotation(System.currentTimeMillis(), key, duration)); - logSpan(key, span); + } catch (Exception e) { logger.log(Level.SEVERE, e.getMessage(), e); } diff --git a/src/main/java/com/profiler/context/TraceContext.java b/src/main/java/com/profiler/context/TraceContext.java index 1e1668c1a..ec0e5e4ec 100644 --- a/src/main/java/com/profiler/context/TraceContext.java +++ b/src/main/java/com/profiler/context/TraceContext.java @@ -35,16 +35,15 @@ public class TraceContext { return threadLocal.get(); } - public Trace attachTraceObject(TraceID traceID) { - Trace trace = this.threadLocal.get(); - if (trace == null) { -// TraceID traceID = TraceID.newTraceId(); - Trace newTrace = new Trace(traceID); - newTrace.setDataSender(this.dataSender); - threadLocal.set(newTrace); - return newTrace; + public void attachTraceObject(Trace trace) { + Trace old = this.threadLocal.get(); + if (old != null) { + // 잘못된 상황의 old를 덤프할것. + throw new IllegalStateException("already Trace Object exist."); } - throw new IllegalStateException("already Trace Object exist"); + // datasender연결 부분 수정 필요. + trace.setDataSender(this.dataSender); + threadLocal.set(trace); } public void detachTraceObject() { diff --git a/src/main/java/com/profiler/modifier/arcus/interceptors/BaseOperationTransitionStateInterceptor.java b/src/main/java/com/profiler/modifier/arcus/interceptors/BaseOperationTransitionStateInterceptor.java index 271039917..37c8a432c 100644 --- a/src/main/java/com/profiler/modifier/arcus/interceptors/BaseOperationTransitionStateInterceptor.java +++ b/src/main/java/com/profiler/modifier/arcus/interceptors/BaseOperationTransitionStateInterceptor.java @@ -2,7 +2,6 @@ package com.profiler.modifier.arcus.interceptors; import com.profiler.context.Annotation; import com.profiler.context.AsyncTrace; -import com.profiler.context.TraceContext; import com.profiler.interceptor.StaticBeforeInterceptor; import com.profiler.util.InterceptorUtils; import com.profiler.util.MetaObject; @@ -65,7 +64,7 @@ public class BaseOperationTransitionStateInterceptor implements StaticBeforeInte TimeObject timeObject = (TimeObject) asyncTrace.getAttachObject(); timeObject.markSendTime(); - long createTime = asyncTrace.getSpan().getCreateTime(); + long createTime = asyncTrace.getSpan().getStartTime(); asyncTrace.record(Annotation.ClientSend, System.currentTimeMillis() - createTime); } else if (newState == OperationState.COMPLETE || newState == OperationState.TIMEDOUT) { if (logger.isLoggable(Level.FINE)) { diff --git a/src/main/java/com/profiler/modifier/db/interceptor/ConnectionCloseInterceptor.java b/src/main/java/com/profiler/modifier/db/interceptor/ConnectionCloseInterceptor.java index 0691668d3..4a1803890 100644 --- a/src/main/java/com/profiler/modifier/db/interceptor/ConnectionCloseInterceptor.java +++ b/src/main/java/com/profiler/modifier/db/interceptor/ConnectionCloseInterceptor.java @@ -12,8 +12,9 @@ import java.util.logging.Logger; public class ConnectionCloseInterceptor implements StaticBeforeInterceptor { private final Logger logger = Logger.getLogger(ConnectionCloseInterceptor.class.getName()); + private static final Object[] EMPTY = new Object[]{null}; - private final MetaObject setUrl = new MetaObject("__setUrl", String.class); + private final MetaObject setUrl = new MetaObject("__setUrl", Object.class); @Override public void before(Object target, String className, String methodName, String parameterDescription, Object[] args) { @@ -26,7 +27,7 @@ public class ConnectionCloseInterceptor implements StaticBeforeInterceptor { } // close의 경우 호출이 실패하더라도 데이터를 삭제해야함. if (target instanceof Connection) { - this.setUrl.invoke(target, new Object[]{null}); + this.setUrl.invoke(target, EMPTY); } } } diff --git a/src/main/java/com/profiler/modifier/db/interceptor/PreparedStatementExecuteQueryInterceptor.java b/src/main/java/com/profiler/modifier/db/interceptor/PreparedStatementExecuteQueryInterceptor.java index eaab4460b..139212316 100644 --- a/src/main/java/com/profiler/modifier/db/interceptor/PreparedStatementExecuteQueryInterceptor.java +++ b/src/main/java/com/profiler/modifier/db/interceptor/PreparedStatementExecuteQueryInterceptor.java @@ -56,7 +56,7 @@ public class PreparedStatementExecuteQueryInterceptor implements StaticAroundInt Map bindValue = getBindValue.invoke(target); String bindString = toBindVariable(bindValue); trace.recordAttribute("BindValue", bindString); - trace.recordAttribute("API", descriptor.getClassName() + "." + descriptor.getMethodName() + descriptor.getSimpleParameterDescriptor()); + trace.recordAttribute("API", descriptor.getClassName() + "." + descriptor.getMethodName() + descriptor.getSimpleParameterDescriptor() + ":" + descriptor.getLineNumber()); clean(target); diff --git a/src/main/java/com/profiler/modifier/tomcat/interceptors/StandardHostValveInvokeInterceptor.java b/src/main/java/com/profiler/modifier/tomcat/interceptors/StandardHostValveInvokeInterceptor.java index 5d79b1207..8581f7bd6 100644 --- a/src/main/java/com/profiler/modifier/tomcat/interceptors/StandardHostValveInvokeInterceptor.java +++ b/src/main/java/com/profiler/modifier/tomcat/interceptors/StandardHostValveInvokeInterceptor.java @@ -40,19 +40,19 @@ public class StandardHostValveInvokeInterceptor implements StaticAroundIntercept TraceID traceId = populateTraceIdFromRequest(request); Trace trace; if (traceId != null) { - TraceID nextTraceId = traceId.getNextTraceId(); + trace = new Trace(traceId); if (logger.isLoggable(Level.INFO)) { - logger.info("TraceID exist. continue trace. " + nextTraceId); + logger.info("TraceID exist. continue trace. " + trace.getCurrentTraceId()); logger.log(Level.FINE, "requestUrl:" + requestURL + " clientIp" + clientIP + " parameter:" + parameters); } - trace = traceContext.attachTraceObject(nextTraceId); + traceContext.attachTraceObject(trace); } else { - TraceID newTraceID = TraceID.newTraceId(); + trace = new Trace(); if (logger.isLoggable(Level.INFO)) { - logger.info("TraceID not exist. start new trace. " + newTraceID); + logger.info("TraceID not exist. start new trace. " + trace.getCurrentTraceId()); logger.log(Level.FINE, "requestUrl:" + requestURL + " clientIp" + clientIP + " parameter:" + parameters); } - trace = traceContext.attachTraceObject(newTraceID); + traceContext.attachTraceObject(trace); } trace.markBeforeTime(); @@ -90,7 +90,7 @@ public class StandardHostValveInvokeInterceptor implements StaticAroundIntercept } // TODO result 가 Exception 타입일경우 호출 실패임. trace.record(Annotation.ServerSend, trace.afterTime()); - + trace.traceBlockEnd(); } /** 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 0ce65eaf5..b1972eab4 100644 --- a/src/test/java/com/profiler/modifier/db/mysql/MySQLConnectionImplModifierTest.java +++ b/src/test/java/com/profiler/modifier/db/mysql/MySQLConnectionImplModifierTest.java @@ -4,6 +4,7 @@ import com.mysql.jdbc.JDBC4PreparedStatement; import com.profiler.context.Trace; import com.profiler.context.TraceContext; import com.profiler.context.TraceID; +import com.profiler.modifier.db.util.DatabaseInfo; import com.profiler.util.MetaObject; import com.profiler.util.TestClassLoader; import org.junit.Assert; @@ -43,7 +44,7 @@ public class MySQLConnectionImplModifierTest { loader.initialize(); } - private MetaObject getUrl = new MetaObject("__getUrl"); + private MetaObject getUrl = new MetaObject("__getUrl"); @Test public void testModify() throws Exception { @@ -58,15 +59,15 @@ public class MySQLConnectionImplModifierTest { properties.setProperty("password", "testlucy"); TraceContext traceContext = new TraceContext(); - TraceID traceID = TraceID.newTraceId(); - traceContext.attachTraceObject(traceID); + Trace trace = new Trace(); + traceContext.attachTraceObject(trace); Connection connection = driver.connect("jdbc:mysql://10.98.133.22:3306/hippo", properties); logger.info("Connection class name:" + connection.getClass().getName()); logger.info("Connection class cl:" + connection.getClass().getClassLoader()); - String url = getUrl.invoke(connection); + DatabaseInfo url = getUrl.invoke(connection); Assert.assertNotNull(url); statement(connection); @@ -78,7 +79,7 @@ public class MySQLConnectionImplModifierTest { preparedStatement3(connection); connection.close(); - String clearUrl = getUrl.invoke(connection); + DatabaseInfo clearUrl = getUrl.invoke(connection); Assert.assertNull(clearUrl); traceContext.detachTraceObject();