Tests for foundational language server metrics (sorbet#2706)

* Add tests for counters. * Assertions for last_diagnostic_latency. * If the first typecheck for edit 2 gets canceled by edit 3, the typecheck for edit 2+3 should use 2's timer. * Basic histogram test * Explicit null check. * Canonicalize counters.
deborasetton · Feb 25, 2020 · 5add669 · 5add669
1 parent 3290b12
commit 5add669
Show file tree

Hide file tree

Showing 17 changed files with 369 additions and 16 deletions.
diff --git a/common/Counters.h b/common/Counters.h
@@ -40,6 +40,11 @@ class Proto;
 namespace web_tracer_framework {
 class Tracing;
 }
+
+namespace test::lsp {
+class CounterStateDatabase;
+}
+
 struct CounterState {
     CounterState();
     ~CounterState();
@@ -57,6 +62,7 @@ struct CounterState {
     friend class core::Proto;
     friend class StatsD;
     friend class sorbet::web_tracer_framework::Tracing;
+    friend class sorbet::test::lsp::CounterStateDatabase;
 
     CounterState(std::unique_ptr<CounterImpl> counters);
     std::unique_ptr<CounterImpl> counters;

diff --git a/common/Timer.cc b/common/Timer.cc
@@ -47,7 +47,11 @@ void Timer::cancel() {
     this->canceled = true;
 }
 
-Timer Timer::clone(ConstExprStr name) {
+Timer Timer::clone() const {
+    return clone(name);
+}
+
+Timer Timer::clone(ConstExprStr name) const {
     Timer forked(log, name, prev, {}, start, {});
     forked.args = args;
     forked.tags = tags;

diff --git a/common/Timer.h b/common/Timer.h
@@ -35,8 +35,11 @@ class Timer {
     // Add a tag to the statsd metrics for this timer. Will not appear in traces.
     void setTag(ConstExprStr name, ConstExprStr value);
 
-    // Creates a new timer with the same start time and args but a different name.
-    Timer clone(ConstExprStr name);
+    // Creates a new timer with the same start time, tags, args, and name.
+    Timer clone() const;
+
+    // Creates a new timer with the same start time, tags, and args but a different name.
+    Timer clone(ConstExprStr name) const;
 
     // TODO We could add more overloads for this if we need them (to create other kinds of Timers)
     // We could also make this more generic to allow more sleep duration types.

diff --git a/main/lsp/LSPIndexer.cc b/main/lsp/LSPIndexer.cc
@@ -96,6 +96,12 @@ UnorderedMap<int, core::FileHash> mergeEvictions(const UnorderedMap<int, core::F
 LSPIndexer::LSPIndexer(shared_ptr<const LSPConfiguration> config, unique_ptr<core::GlobalState> initialGS)
     : config(config), initialGS(move(initialGS)), emptyWorkers(WorkerPool::create(0, *config->logger)) {}
 
+LSPIndexer::~LSPIndexer() {
+    if (pendingTypecheckLatencyTimer != nullptr) {
+        pendingTypecheckLatencyTimer->cancel();
+    }
+}
+
 vector<core::FileHash> LSPIndexer::computeFileHashes(const vector<shared_ptr<core::File>> &files,
                                                      WorkerPool &workers) const {
     Timer timeit(config->logger, "computeFileHashes");
@@ -212,7 +218,10 @@ void LSPIndexer::initialize(LSPFileUpdates &updates, WorkerPool &workers) {
     initialGS->errorQueue = move(savedErrorQueue);
 }
 
-LSPFileUpdates LSPIndexer::commitEdit(SorbetWorkspaceEditParams &edit, std::vector<core::FileHash> newHashesOrEmpty) {
+LSPFileUpdates LSPIndexer::commitEdit(unique_ptr<Timer> &latencyTimer, SorbetWorkspaceEditParams &edit,
+                                      std::vector<core::FileHash> newHashesOrEmpty) {
+    Timer timeit(config->logger, "LSPIndexer::commitEdit");
+    timeit.setTag("computedFileHashes", newHashesOrEmpty.empty() ? ConstExprStr("true") : ConstExprStr("false"));
     LSPFileUpdates update;
     update.epoch = edit.epoch;
     update.editCount = edit.mergeCount + 1;
@@ -310,6 +319,12 @@ LSPFileUpdates LSPIndexer::commitEdit(SorbetWorkspaceEditParams &edit, std::vect
     if (!update.canTakeFastPath) {
         update.updatedGS = initialGS->deepCopy();
         pendingTypecheckUpdates = update.copy();
+        if (pendingTypecheckLatencyTimer != nullptr) {
+            pendingTypecheckLatencyTimer->cancel();
+        }
+        if (latencyTimer != nullptr) {
+            pendingTypecheckLatencyTimer = make_unique<Timer>(latencyTimer->clone());
+        }
         pendingTypecheckEvictedStateHashes = std::move(evictedHashes);
     } else {
         // Edit takes the fast path. Merge with this edit so we can reverse it if the slow path gets canceled.
@@ -318,6 +333,13 @@ LSPFileUpdates LSPIndexer::commitEdit(SorbetWorkspaceEditParams &edit, std::vect
         auto mergedEvictions = mergeEvictions(pendingTypecheckEvictedStateHashes, evictedHashes);
         pendingTypecheckUpdates = move(merged);
         pendingTypecheckEvictedStateHashes = std::move(mergedEvictions);
+        if (update.canceledSlowPath && pendingTypecheckLatencyTimer != nullptr) {
+            // Replace edit's latencyTimer with that of the running slow path.
+            if (latencyTimer != nullptr) {
+                latencyTimer->cancel();
+            }
+            latencyTimer = make_unique<Timer>(pendingTypecheckLatencyTimer->clone());
+        }
     }
     // Don't copy over these (test-only) properties, as they only apply to the original request.
     pendingTypecheckUpdates.cancellationExpected = false;

diff --git a/main/lsp/LSPIndexer.h b/main/lsp/LSPIndexer.h
@@ -30,6 +30,9 @@ class LSPIndexer final {
     std::vector<core::FileHash> globalStateHashes;
     /** Contains a copy of the last edit committed on the slow path. Used in slow path cancelation logic. */
     LSPFileUpdates pendingTypecheckUpdates;
+    /** Contains a clone of the latency timer for the pending typecheck operation. Is used to ensure that we correctly
+     * track the latency of canceled & rescheduled typechecking operations. */
+    std::unique_ptr<Timer> pendingTypecheckLatencyTimer;
     /** Contains globalStateHashes evicted with `pendingTypecheckUpdates`. Used in slow path cancelation logic. */
     UnorderedMap<int, core::FileHash> pendingTypecheckEvictedStateHashes;
     std::unique_ptr<KeyValueStore> kvstore; // always null for now.
@@ -41,6 +44,7 @@ class LSPIndexer final {
 
 public:
     LSPIndexer(std::shared_ptr<const LSPConfiguration> config, std::unique_ptr<core::GlobalState> initialGS);
+    ~LSPIndexer();
 
     /** Determines if the given edit can take the fast path relative to the most recently committed edit. */
     bool canTakeFastPath(const SorbetWorkspaceEditParams &params, const std::vector<core::FileHash> &fileHashes) const;
@@ -60,7 +64,8 @@ class LSPIndexer final {
      *
      * If `newHashesOrEmpty` contains file hashes, this function avoids re-computing those hashes.
      */
-    LSPFileUpdates commitEdit(SorbetWorkspaceEditParams &edit, std::vector<core::FileHash> newHashesOrEmpty);
+    LSPFileUpdates commitEdit(std::unique_ptr<Timer> &latencyTimer, SorbetWorkspaceEditParams &edit,
+                              std::vector<core::FileHash> newHashesOrEmpty);
 };
 
 } // namespace sorbet::realmain::lsp

diff --git a/main/lsp/LSPPreprocessor.cc b/main/lsp/LSPPreprocessor.cc
@@ -194,6 +194,8 @@ unique_ptr<LSPTask> LSPPreprocessor::getTaskForMessage(LSPMessage &msg) {
                 return make_unique<ShutdownTask>(*config, id);
             case LSPMethod::SorbetError:
                 return make_unique<SorbetErrorTask>(*config, move(get<unique_ptr<SorbetErrorParams>>(rawParams)), id);
+            case LSPMethod::GETCOUNTERS:
+                return make_unique<GetCountersTask>(*config, id);
             default:
                 return make_unique<SorbetErrorTask>(
                     *config,
@@ -264,7 +266,7 @@ void LSPPreprocessor::preprocessAndEnqueue(unique_ptr<LSPMessage> msg) {
     task->latencyTimer = move(msg->latencyTimer);
 
     {
-        Timer timeit(config->logger, "LSPTask::Preprocess");
+        Timer timeit(config->logger, "LSPTask::preprocess");
         timeit.setTag("method", task->methodString());
         task->preprocess(*this);
     }

diff --git a/main/lsp/LSPTask.cc b/main/lsp/LSPTask.cc
@@ -26,6 +26,8 @@ ConstExprStr LSPTask::methodString() const {
             return "PAUSE";
         case LSPMethod::RESUME:
             return "RESUME";
+        case LSPMethod::GETCOUNTERS:
+            return "GETCOUNTERS";
         case LSPMethod::Shutdown:
             return "shutdown";
         case LSPMethod::SorbetError:

diff --git a/main/lsp/LSPTypecheckerCoordinator.cc b/main/lsp/LSPTypecheckerCoordinator.cc
@@ -141,7 +141,7 @@ shared_ptr<core::lsp::Task>
 LSPTypecheckerCoordinator::trySchedulePreemption(std::unique_ptr<LSPQueuePreemptionTask> preemptTask) {
     auto wrappedTask = make_shared<TypecheckerTask>(*config, move(preemptTask),
                                                     make_unique<LSPTypecheckerDelegate>(*emptyWorkers, typechecker),
-                                                    hasDedicatedThread);
+                                                    /* collectCounters */ false);
     // Plant this timer before scheduling task to preempt, as task could run before we plant the timer!
     wrappedTask->timeLatencyUntilRun(make_unique<Timer>(*config->logger, "latency.preempt_slow_path"));
     if (hasDedicatedThread && preemptionTaskManager->trySchedulePreemptionTask(wrappedTask)) {

diff --git a/main/lsp/notifications/sorbet_workspace_edit.cc b/main/lsp/notifications/sorbet_workspace_edit.cc
@@ -45,7 +45,7 @@ void SorbetWorkspaceEditTask::mergeNewer(SorbetWorkspaceEditTask &task) {
 }
 
 void SorbetWorkspaceEditTask::index(LSPIndexer &indexer) {
-    updates = make_unique<LSPFileUpdates>(indexer.commitEdit(*params, cachedFileHashesOrEmpty));
+    updates = make_unique<LSPFileUpdates>(indexer.commitEdit(latencyTimer, *params, cachedFileHashesOrEmpty));
 }
 
 void SorbetWorkspaceEditTask::run(LSPTypecheckerDelegate &typechecker) {
@@ -85,12 +85,15 @@ void SorbetWorkspaceEditTask::runSpecial(LSPTypechecker &typechecker, WorkerPool
     typechecker.state().epochManager->startCommitEpoch(updates->epoch);
     startedNotification.Notify();
     // Only report stats if the edit was committed.
-    if (!typechecker.typecheck(move(*updates), workers)) {
+    if (typechecker.typecheck(move(*updates), workers)) {
         if (latencyTimer != nullptr) {
             // TODO: Move into pushDiagnostics once we have fast feedback.
             latencyTimer->clone("last_diagnostic_latency");
         }
         prodCategoryCounterAdd("lsp.messages.processed", "sorbet.mergedEdits", updates->editCount - 1);
+    } else if (latencyTimer != nullptr) {
+        // Don't report a latency value for canceled slow paths.
+        latencyTimer->cancel();
     }
 }
 

diff --git a/main/lsp/protocol.cc b/main/lsp/protocol.cc
@@ -88,7 +88,7 @@ unique_ptr<Joinable> LSPPreprocessor::runPreprocessor(MessageQueueState &message
             {
                 absl::MutexLock lck(taskQueueMutex.get());
                 // Merge the counters from all of the worker threads with those stored in
-                // processingQueue.
+                // taskQueue.
                 taskQueue->counters = mergeCounters(move(taskQueue->counters));
                 if (taskQueue->terminate) {
                     // We must have processed an exit notification, or one of the downstream threads exited.
@@ -269,6 +269,11 @@ optional<unique_ptr<core::GlobalState>> LSPLoop::runLSP(shared_ptr<LSPInput> inp
 
                 task = move(taskQueue->pendingTasks.front());
                 taskQueue->pendingTasks.pop_front();
+
+                // Test only: Collect counters from other threads into this thread for reporting.
+                if (task->method == LSPMethod::GETCOUNTERS && !taskQueue->counters.hasNullCounters()) {
+                    counterConsume(move(taskQueue->counters));
+                }
             }
 
             logger->debug("[Processing] Running task {} normally", convertLSPMethodToString(task->method));

diff --git a/main/lsp/requests/get_counters.cc b/main/lsp/requests/get_counters.cc
@@ -0,0 +1,30 @@
+#include "main/lsp/requests/get_counters.h"
+#include "main/lsp/LSPOutput.h"
+#include "main/lsp/lsp.h"
+
+using namespace std;
+
+namespace sorbet::realmain::lsp {
+GetCountersTask::GetCountersTask(const LSPConfiguration &config, MessageId id)
+    : LSPTask(config, LSPMethod::GETCOUNTERS), id(move(id)) {}
+
+LSPTask::Phase GetCountersTask::finalPhase() const {
+    return LSPTask::Phase::INDEX;
+}
+
+bool GetCountersTask::canPreempt(const LSPIndexer &) const {
+    return false;
+}
+
+// Has to run on indexing thread, which is what coordinates all threads and collects all of the metrics.
+void GetCountersTask::index(LSPIndexer &indexer) {
+    auto response = make_unique<ResponseMessage>("2.0", id, LSPMethod::GETCOUNTERS);
+    unique_ptr<SorbetCounters> counters = make_unique<SorbetCounters>();
+    counters->counters = getAndClearThreadCounters();
+    response->result = move(counters);
+    config.output->write(move(response));
+}
+
+void GetCountersTask::run(LSPTypecheckerDelegate &typechecker) {}
+
+} // namespace sorbet::realmain::lsp
diff --git a/main/lsp/requests/get_counters.h b/main/lsp/requests/get_counters.h
@@ -0,0 +1,23 @@
+#ifndef RUBY_TYPER_LSP_REQUESTS_GET_COUNTERS_H
+#define RUBY_TYPER_LSP_REQUESTS_GET_COUNTERS_H
+
+#include "main/lsp/LSPTask.h"
+
+namespace sorbet::realmain::lsp {
+class GetCountersTask final : public LSPTask {
+    MessageId id;
+
+public:
+    GetCountersTask(const LSPConfiguration &config, MessageId id);
+
+    bool canPreempt(const LSPIndexer &) const override;
+
+    LSPTask::Phase finalPhase() const override;
+
+    void index(LSPIndexer &indexer) override;
+
+    void run(LSPTypecheckerDelegate &typechecker) override;
+};
+} // namespace sorbet::realmain::lsp
+
+#endif
diff --git a/main/lsp/requests/requests.h b/main/lsp/requests/requests.h
@@ -6,6 +6,7 @@
 #include "main/lsp/requests/definition.h"
 #include "main/lsp/requests/document_highlight.h"
 #include "main/lsp/requests/document_symbol.h"
+#include "main/lsp/requests/get_counters.h"
 #include "main/lsp/requests/hover.h"
 #include "main/lsp/requests/initialize.h"
 #include "main/lsp/requests/references.h"

diff --git a/main/lsp/tools/make_lsp_types.cc b/main/lsp/tools/make_lsp_types.cc
@@ -1300,11 +1300,14 @@ void makeLSPTypes(vector<shared_ptr<JSONClassType>> &enumTypes, vector<shared_pt
                                              },
                                              classTypes);
 
+    auto SorbetCounters = makeObject("SorbetCounters", {}, classTypes, {"CounterState counters;"});
+
     /* Core LSPMessage objects */
     // N.B.: Only contains LSP methods that Sorbet actually cares about.
     // All others are ignored.
     auto LSPMethod = makeStrEnum("LSPMethod",
                                  {
+                                     "__GETCOUNTERS__",
                                      "__PAUSE__",
                                      "__RESUME__",
                                      "$/cancelRequest",
@@ -1340,6 +1343,7 @@ void makeLSPTypes(vector<shared_ptr<JSONClassType>> &enumTypes, vector<shared_pt
     auto methodField = makeField("method", LSPMethod);
     auto RequestMessageParamsType =
         makeDiscriminatedUnion(methodField, {
+                                                {"__GETCOUNTERS__", makeOptional(JSONNull)},
                                                 {"initialize", InitializeParams},
                                                 {"shutdown", makeOptional(JSONNull)},
                                                 {"textDocument/documentHighlight", TextDocumentPositionParams},
@@ -1365,6 +1369,7 @@ void makeLSPTypes(vector<shared_ptr<JSONClassType>> &enumTypes, vector<shared_pt
     auto ResponseMessageResultType = makeDiscriminatedUnion(
         requestMethodField,
         {
+            {"__GETCOUNTERS__", SorbetCounters},
             {"initialize", InitializeResult},
             {"shutdown", JSONNull},
             // DocumentHighlight[] | null