void (@NotNull RunnableInfo info, @NotNull ApplicationEx app) { final EventWatcher watcher = EventWatcher.getInstanceOrNull(); final long waitingFinishedNs = System.nanoTime(); try { doRun(info, app); } catch (ProcessCanceledException ignored) { } catch (Throwable t) { if (ApplicationManager.getApplication().isUnitTestMode()) { ExceptionUtil.rethrow(t); } LOG.error(t); } finally { if (watcher != null) { final Runnable runnable = info.runnable; final long executionFinishedNs = System.nanoTime(); final long waitedInQueueNs = waitingFinishedNs - info.queuedTimeNs; final long executionDurationNs = executionFinishedNs - waitingFinishedNs; //RC: ExceptionAnalyzer reports negative values here, but it is not clear there do they come from. // The reasons I could think of now are: // 1) oddities of .nanoTime() behavior under different CPU power-saving modes // 2) changing .nanoTime() origin due to thead being relocated to another CPU // 3) long overflow in (end-start) expression. // those are straightforward reasons, but 1-2 was mostly solved (it seems to me) in a modern // hardware/software, and 3 is hard to expect in our use-cases. Hence, negative values could be // due to some other code bug I don't see right now. Safeguarding here prevents errors down the // stack, but it also shifts value statistics final long waitedTimeInQueueNs_safe = waitedInQueueNs >= 0 ? waitedInQueueNs : 0; final long executionDurationNs_safe = executionDurationNs >= 0 ? executionDurationNs : 0; watcher.runnableTaskFinished(runnable, waitedTimeInQueueNs_safe, info.queueSize, executionDurationNs_safe, info.wasInSkippedItems); if (waitedInQueueNs < 0 || executionDurationNs<0) { //maybe logs give us some hints about why the values are negative: THROTTLED_LOG.info("waitedInQueueNs(" + waitedInQueueNs + ") | executionDurationNs(" + executionDurationNs + ") is negative -> unexpected state"); } } } }