diff --git a/com.microsoft.java.debug.core/.classpath b/com.microsoft.java.debug.core/.classpath index 9ba41a249..b3a434205 100644 --- a/com.microsoft.java.debug.core/.classpath +++ b/com.microsoft.java.debug.core/.classpath @@ -31,6 +31,19 @@ + + + + + + + + + + + + + diff --git a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/ProtocolServer.java b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/ProtocolServer.java index 9e503e0af..6ddf327a9 100644 --- a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/ProtocolServer.java +++ b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/ProtocolServer.java @@ -19,12 +19,14 @@ import java.util.logging.Level; import java.util.logging.Logger; +import com.google.gson.JsonObject; import com.microsoft.java.debug.core.Configuration; import com.microsoft.java.debug.core.DebugException; import com.microsoft.java.debug.core.UsageDataSession; import com.microsoft.java.debug.core.protocol.AbstractProtocolServer; import com.microsoft.java.debug.core.protocol.Events.DebugEvent; import com.microsoft.java.debug.core.protocol.Events.StoppedEvent; +import com.microsoft.java.debug.core.protocol.Events.TelemetryEvent; import com.microsoft.java.debug.core.protocol.Messages; import com.sun.jdi.VMDisconnectedException; @@ -99,12 +101,18 @@ public CompletableFuture sendRequest(Messages.Request request public void sendEvent(DebugEvent event) { // See the two bugs https://github.com/Microsoft/java-debug/issues/134 and https://github.com/Microsoft/vscode/issues/58327, // it requires the java-debug to send the StoppedEvent after ContinueResponse/StepResponse is received by DA. + JsonObject telemetry = new JsonObject(); + telemetry.addProperty("event_send", event.type); + telemetry.addProperty("status","outgoing"); + telemetry.addProperty("timestamp", System.nanoTime()); if (event instanceof StoppedEvent) { + telemetry.addProperty("send_later", "true"); sendEventLater(event); } else { + telemetry.addProperty("send_later", "false"); super.sendEvent(event); } - + super.sendEvent(new TelemetryEvent("jb", telemetry)); } /** @@ -116,6 +124,11 @@ private void sendEventLater(DebugEvent event) { if (this.isDispatchingRequest) { this.eventQueue.offer(event); } else { + JsonObject telemetry = new JsonObject(); + telemetry.addProperty("event_send", event.type); + telemetry.addProperty("status","send_nafter_sched"); + telemetry.addProperty("timestamp", System.nanoTime()); + super.sendEvent(new TelemetryEvent("jb", telemetry)); super.sendEvent(event); } } @@ -128,10 +141,16 @@ protected void dispatchRequest(Messages.Request request) { synchronized (lock) { this.isDispatchingRequest = true; } - + debugAdapter.dispatchRequest(request).thenCompose((response) -> { CompletableFuture future = new CompletableFuture<>(); if (response != null) { + JsonObject telemetry = new JsonObject(); + telemetry.addProperty("command", request.command); + telemetry.addProperty("status","end"); + telemetry.addProperty("seq", request.seq); + telemetry.addProperty("timestamp", System.nanoTime()); + super.sendEvent(new TelemetryEvent("jb", telemetry)); sendResponse(response); future.complete(null); } else { @@ -169,9 +188,14 @@ protected void dispatchRequest(Messages.Request request) { synchronized (lock) { this.isDispatchingRequest = false; } - while (this.eventQueue.peek() != null) { - super.sendEvent(this.eventQueue.poll()); + DebugEvent dbe = this.eventQueue.poll(); + JsonObject telemetry = new JsonObject(); + telemetry.addProperty("event_send", dbe.type); + telemetry.addProperty("status","at_last"); + telemetry.addProperty("timestamp", System.nanoTime()); + super.sendEvent(new TelemetryEvent("jb", telemetry)); + super.sendEvent(dbe); } } } diff --git a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/EvaluateRequestHandler.java b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/EvaluateRequestHandler.java index d135ee5b2..11e81cb6e 100644 --- a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/EvaluateRequestHandler.java +++ b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/EvaluateRequestHandler.java @@ -22,6 +22,7 @@ import org.apache.commons.lang3.StringUtils; +import com.google.gson.JsonObject; import com.microsoft.java.debug.core.Configuration; import com.microsoft.java.debug.core.DebugException; import com.microsoft.java.debug.core.DebugSettings; @@ -37,6 +38,7 @@ import com.microsoft.java.debug.core.adapter.variables.VariableDetailUtils; import com.microsoft.java.debug.core.adapter.variables.VariableProxy; import com.microsoft.java.debug.core.adapter.variables.VariableUtils; +import com.microsoft.java.debug.core.protocol.Events.TelemetryEvent; import com.microsoft.java.debug.core.protocol.Messages.Response; import com.microsoft.java.debug.core.protocol.Requests.Arguments; import com.microsoft.java.debug.core.protocol.Requests.Command; @@ -83,8 +85,8 @@ public CompletableFuture handle(Command command, Arguments arguments, "Evaluation failed because the thread is not suspended.", ErrorCode.EVALUATE_NOT_SUSPENDED_THREAD)); } - return CompletableFuture.supplyAsync(() -> { + long asyncStartTime = System.nanoTime(); IEvaluationProvider engine = context.getProvider(IEvaluationProvider.class); try { Value value = engine.evaluate(expression, stackFrameReference.getThread(), stackFrameReference.getDepth()).get(); @@ -167,6 +169,12 @@ public CompletableFuture handle(Command command, Arguments arguments, // for primitive value response.body = new Responses.EvaluateResponseBody(variableFormatter.valueToString(value, options), 0, variableFormatter.typeToString(value == null ? null : value.type(), options), 0); + long asyncEndTime = System.nanoTime(); + JsonObject perf = new JsonObject(); + perf.addProperty("command", "evaluate"); + perf.addProperty("duration", (asyncEndTime - asyncStartTime)); + context.getProtocolServer().sendEvent(new TelemetryEvent("dap", perf)); + logger.info("JBDEBUG : Handle Async EvaluateRequestHandler in " + (asyncEndTime - asyncStartTime)/1000000 + " ms"); return response; } catch (InterruptedException | ExecutionException e) { Throwable cause = e; diff --git a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/StepRequestHandler.java b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/StepRequestHandler.java index 71f28355a..76fa73ee7 100644 --- a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/StepRequestHandler.java +++ b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/adapter/handler/StepRequestHandler.java @@ -17,10 +17,13 @@ import java.util.Objects; import java.util.concurrent.CompletableFuture; import java.util.concurrent.CompletionException; +import java.util.logging.Logger; import org.apache.commons.lang3.ArrayUtils; +import com.google.gson.JsonObject; import com.microsoft.java.debug.core.AsyncJdwpUtils; +import com.microsoft.java.debug.core.Configuration; import com.microsoft.java.debug.core.DebugEvent; import com.microsoft.java.debug.core.DebugUtility; import com.microsoft.java.debug.core.IDebugSession; @@ -32,6 +35,7 @@ import com.microsoft.java.debug.core.adapter.IDebugRequestHandler; import com.microsoft.java.debug.core.adapter.ISourceLookUpProvider.MethodInvocation; import com.microsoft.java.debug.core.protocol.Events; +import com.microsoft.java.debug.core.protocol.Events.TelemetryEvent; import com.microsoft.java.debug.core.protocol.Messages.Response; import com.microsoft.java.debug.core.protocol.Requests.Arguments; import com.microsoft.java.debug.core.protocol.Requests.Command; @@ -64,6 +68,8 @@ public class StepRequestHandler implements IDebugRequestHandler { + private static final Logger logger = Logger.getLogger(Configuration.LOGGER_NAME); + @Override public List getTargetCommands() { return Arrays.asList(Command.STEPIN, Command.STEPOUT, Command.NEXT); @@ -72,14 +78,20 @@ public List getTargetCommands() { @Override public CompletableFuture handle(Command command, Arguments arguments, Response response, IDebugAdapterContext context) { + long startTime = System.nanoTime(); if (context.getDebugSession() == null) { return AdapterUtils.createAsyncErrorResponse(response, ErrorCode.EMPTY_DEBUG_SESSION, "Debug Session doesn't exist."); } - + long start1Time, start2Time, start3Time, start4Time, start5Time; + start2Time = System.nanoTime(); + start3Time = System.nanoTime(); + start4Time = System.nanoTime(); + start5Time = System.nanoTime(); StepArguments stepArguments = (StepArguments) arguments; long threadId = stepArguments.threadId; int targetId = (stepArguments instanceof StepInArguments) ? ((StepInArguments) stepArguments).targetId : 0; ThreadReference thread = context.getThreadCache().getThread(threadId); + start1Time = System.nanoTime(); if (thread == null) { thread = DebugUtility.getThread(context.getDebugSession(), threadId); } @@ -87,6 +99,7 @@ public CompletableFuture handle(Command command, Arguments arguments, JdiExceptionReference exception = context.getExceptionManager().removeException(threadId); context.getStepResultManager().removeMethodResult(threadId); try { + start2Time = System.nanoTime(); final ThreadReference targetThread = thread; ThreadState threadState = new ThreadState(); threadState.threadId = threadId; @@ -99,7 +112,7 @@ public CompletableFuture handle(Command command, Arguments arguments, .subscribe(debugEvent -> { handleDebugEvent(debugEvent, context.getDebugSession(), context, threadState); }); - + if (command == Command.STEPIN) { threadState.pendingStepRequest = DebugUtility.createStepIntoRequest(thread, context.getStepFilters().allowClasses, @@ -117,10 +130,13 @@ public CompletableFuture handle(Command command, Arguments arguments, threadState.targetStepIn = targetId > 0 ? (MethodInvocation) context.getRecyclableIdPool().getObjectById(targetId) : null; + + start3Time = System.nanoTime(); if (context.asyncJDWP()) { List> futures = new ArrayList<>(); futures.add(AsyncJdwpUtils.runAsync(() -> { // JDWP Command: TR_FRAMES + logger.severe("JBDEBUG : Handle Step Request - TR_FRAMES"); try { threadState.topFrame = getTopFrame(targetThread); threadState.stepLocation = threadState.topFrame.location(); @@ -139,22 +155,34 @@ public CompletableFuture handle(Command command, Arguments arguments, } catch (IncompatibleThreadStateException e1) { throw new CompletionException(e1); } + logger.severe("JBDEBUG : Handle Step Request - TR_FRAMES - End"); })); futures.add(AsyncJdwpUtils.runAsync( // JDWP Command: OR_IS_COLLECTED - () -> threadState.pendingMethodExitRequest.addThreadFilter(targetThread) + () -> { + logger.severe("JBDEBUG : Handle Step Request - OR_IS_COLLECTED"); + threadState.pendingMethodExitRequest.addThreadFilter(targetThread); + logger.severe("JBDEBUG : Handle Step Request - OR_IS_COLLECTED - End"); + } )); futures.add(AsyncJdwpUtils.runAsync(() -> { try { // JDWP Command: TR_FRAME_COUNT + logger.severe("JBDEBUG : Handle Step Request - TR_FRAME_COUNT"); threadState.stackDepth = targetThread.frameCount(); + logger.severe("JBDEBUG : Handle Step Request - TR_FRAME_COUNT - End"); } catch (IncompatibleThreadStateException e) { throw new CompletionException(e); } })); futures.add( // JDWP Command: ER_SET - AsyncJdwpUtils.runAsync(() -> threadState.pendingStepRequest.enable()) + AsyncJdwpUtils.runAsync(() -> { + logger.severe("JBDEBUG : Handle Step Request - ER_SET"); + threadState.pendingStepRequest.enable(); + logger.severe("JBDEBUG : Handle Step Request - ER_SET - End"); + } + ) ); try { @@ -187,10 +215,11 @@ public CompletableFuture handle(Command command, Arguments arguments, threadState.pendingStepRequest.enable(); threadState.pendingMethodExitRequest.enable(); } - + start4Time = System.nanoTime(); context.getThreadCache().removeEventThread(thread.uniqueID()); DebugUtility.resumeThread(thread); ThreadsRequestHandler.checkThreadRunningAndRecycleIds(thread, context); + start5Time = System.nanoTime(); } catch (IncompatibleThreadStateException ex) { // Roll back the Exception info if stepping fails. context.getExceptionManager().setException(threadId, exception); @@ -217,7 +246,23 @@ public CompletableFuture handle(Command command, Arguments arguments, ex.getCause() != null ? ex.getCause() : ex); } } - + long endTime = System.nanoTime(); + JsonObject perf = new JsonObject(); + // THis is useless + perf.addProperty("command", "setStep"); + perf.addProperty("duration", (endTime - startTime)); + perf.addProperty("timer_start", startTime); + perf.addProperty("timer_end", endTime); + perf.addProperty("version", 1); + context.getProtocolServer().sendEvent(new TelemetryEvent("jb", perf)); + logger.info("JBDEBUG : Handle Step Request, total = " + + (endTime - startTime)/1000000 + " ms ( " + + (start1Time - startTime)/1000000 + " ms + " + + (start2Time - start1Time)/1000000 + " ms + " + + (start3Time - start2Time)/1000000 + " ms + " + + (start4Time - start3Time)/1000000 + " ms + " + + (start5Time - start4Time)/1000000 + " ms + " + + (endTime - start5Time)/1000000 + " ms )"); return CompletableFuture.completedFuture(response); } @@ -225,7 +270,7 @@ private void handleDebugEvent(DebugEvent debugEvent, IDebugSession debugSession, ThreadState threadState) { Event event = debugEvent.event; EventRequestManager eventRequestManager = debugSession.getVM().eventRequestManager(); - + long startTime = System.nanoTime(); // When a breakpoint occurs, abort any pending step requests from the same thread. if (event instanceof BreakpointEvent || event instanceof ExceptionEvent) { // if we have a pending target step in then ignore and continue. @@ -244,6 +289,7 @@ private void handleDebugEvent(DebugEvent debugEvent, IDebugSession debugSession, } } } else if (event instanceof StepEvent) { + ThreadReference thread = ((StepEvent) event).thread(); long threadId = thread.uniqueID(); threadState.deleteStepRequest(eventRequestManager); @@ -325,6 +371,13 @@ private void handleDebugEvent(DebugEvent debugEvent, IDebugSession debugSession, } debugEvent.shouldResume = true; } + long endTime = System.nanoTime(); + JsonObject perf = new JsonObject(); + perf.addProperty("command", "handleStep"); + perf.addProperty("duration", (endTime - startTime)); + perf.addProperty("timer_start", startTime); + perf.addProperty("timer_end", endTime); + context.getProtocolServer().sendEvent(new TelemetryEvent("jb", perf)); } private boolean isStoppedAtSelectedMethod(StackFrame frame, MethodInvocation selectedMethod) { diff --git a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/protocol/AbstractProtocolServer.java b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/protocol/AbstractProtocolServer.java index 61d57bd85..cbfe7a20a 100644 --- a/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/protocol/AbstractProtocolServer.java +++ b/com.microsoft.java.debug.core/src/main/java/com/microsoft/java/debug/core/protocol/AbstractProtocolServer.java @@ -33,9 +33,11 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; +import com.google.gson.JsonObject; import com.microsoft.java.debug.core.adapter.AdapterUtils; import com.microsoft.java.debug.core.adapter.ErrorCode; import com.microsoft.java.debug.core.protocol.Events.DebugEvent; +import com.microsoft.java.debug.core.protocol.Events.TelemetryEvent; import io.reactivex.disposables.Disposable; import io.reactivex.schedulers.Schedulers; @@ -221,6 +223,12 @@ private void processData() { if (message.type.equals("request")) { Messages.Request request = JsonUtils.fromJson(messageData, Messages.Request.class); if (this.isValidDAPRequest) { + JsonObject telemetry = new JsonObject(); + telemetry.addProperty("command", request.command); + telemetry.addProperty("status","start"); + telemetry.addProperty("seq", request.seq); + telemetry.addProperty("timestamp", System.nanoTime()); + sendEvent(new TelemetryEvent("jb", telemetry)); requestSubject.onNext(request); } else { Messages.Response response = new Messages.Response(request.seq, request.command);