From c51d9a8b878bd0de4acc955cfb7dc16d1b9b21c5 Mon Sep 17 00:00:00 2001
From: Paul Bissonnette <paulbiss@fb.com>
Date: Wed, 21 Apr 2021 14:01:32 -0700
Subject: [PATCH] Add logging for file tearing during requests

Summary: When decls in compilation is introduced we may have to handle situations where bytecode is requested for a file that was changed on disk after decls were already consumed as a dependency of an already loaded file. We either need to detect this situation and terminate the request or handle it gracefully by recovering the bytecode based on the prior version of the file. Terminating the request will be far simpler, therefore we're hoping to measure how often this happens in practice.

Reviewed By: ricklavoie

Differential Revision: D27805653

fbshipit-source-id: 48edeeedb19cce16b21ad324f7b1e69842204113
---
 hphp/runtime/base/execution-context.cpp | 10 +++++++
 hphp/runtime/base/execution-context.h   |  2 ++
 hphp/runtime/base/runtime-option.h      |  1 +
 hphp/runtime/vm/unit.cpp                | 47 +++++++++++++++++++++++++++++++++
 hphp/runtime/vm/unit.h                  |  6 +++++
 5 files changed, 66 insertions(+)

diff --git a/hphp/runtime/base/execution-context.cpp b/hphp/runtime/base/execution-context.cpp
index b4b90bf5f74..7faf4751556 100644
--- a/hphp/runtime/base/execution-context.cpp
+++ b/hphp/runtime/base/execution-context.cpp
@@ -1450,6 +1450,11 @@ void ExecutionContext::requestInit() {
   // extension function in the VM; this is bad if systemlib itself hasn't been
   // merged.
   autoTypecheckRequestInit();
+
+  if (!RO::RepoAuthoritative && RO::EvalSampleRequestTearing) {
+    m_shouldSampleUnitTearing =
+      StructuredLog::coinflip(RO::EvalSampleRequestTearing);
+  }
 }
 
 void ExecutionContext::requestExit() {
@@ -1481,6 +1486,11 @@ void ExecutionContext::requestExit() {
 
   if (Logger::UseRequestLog) Logger::SetThreadHook(nullptr);
   if (m_requestTrace) record_trace(std::move(*m_requestTrace));
+
+  if (!RO::RepoAuthoritative && m_shouldSampleUnitTearing) {
+    Unit::logTearing();
+    m_shouldSampleUnitTearing = false;
+  }
 }
 
 /**
diff --git a/hphp/runtime/base/execution-context.h b/hphp/runtime/base/execution-context.h
index 4f5a239d3f3..06bbf61dce8 100644
--- a/hphp/runtime/base/execution-context.h
+++ b/hphp/runtime/base/execution-context.h
@@ -632,6 +632,8 @@ public:
   req::vector<ImplicitContext*> m_implicitContexts;
 
   VMParserFrame* m_parserFrame{nullptr};
+
+  bool m_shouldSampleUnitTearing{false};
 };
 
 ///////////////////////////////////////////////////////////////////////////////
diff --git a/hphp/runtime/base/runtime-option.h b/hphp/runtime/base/runtime-option.h
index 29b402ea03a..faa6bf82bae 100644
--- a/hphp/runtime/base/runtime-option.h
+++ b/hphp/runtime/base/runtime-option.h
@@ -1391,6 +1391,7 @@ struct RuntimeOption {
   F(int32_t, NoticeOnCoerceForMath, 0)                                  \
   F(string, TaoMigrationOverride, std::string(""))                      \
   F(string, SRRouteMigrationOverride, std::string(""))                  \
+  F(int32_t, SampleRequestTearing, 0)                                   \
   /* */
 
 private:
diff --git a/hphp/runtime/vm/unit.cpp b/hphp/runtime/vm/unit.cpp
index 072613ee517..1634035e2d7 100644
--- a/hphp/runtime/vm/unit.cpp
+++ b/hphp/runtime/vm/unit.cpp
@@ -1015,11 +1015,58 @@ static size_t compactMergeInfo(Unit::MergeInfo* in, Unit::MergeInfo* out,
   return delta;
 }
 
+namespace {
+RDS_LOCAL(hphp_fast_set<const Unit*>, rl_mergedUnits);
+}
+
+void Unit::logTearing() {
+  assertx(!RO::RepoAuthoritative);
+  assertx(RO::EvalSampleRequestTearing);
+  assertx(g_context);
+
+  auto const repoOptions = g_context->getRepoOptionsForRequest();
+  auto repoRoot = folly::fs::path(repoOptions->path()).parent_path();
+
+  for (auto const u : *rl_mergedUnits) {
+    assertx(!u->isSystemLib());
+    auto const loaded = lookupUnit(const_cast<StringData*>(u->origFilepath()),
+                                   "", nullptr, Native::s_noNativeFuncs, true);
+
+    if (loaded != u && (!loaded || loaded->sha1() != u->sha1())) {
+      StructuredLogEntry ent;
+
+      auto const tpath = [&] () -> std::string {
+        auto const orig = folly::fs::path(u->origFilepath()->data());
+        if (repoRoot.size() > orig.size()) return orig.native();
+        if (!std::equal(repoRoot.begin(), repoRoot.end(), orig.begin())) {
+          return orig.native();
+        }
+        return orig.lexically_relative(repoRoot).native();
+      }();
+      ent.setStr("filepath", tpath);
+      ent.setStr("same_bc",
+                 loaded && loaded->bcSha1() == u->bcSha1() ? "true" : "false");
+      ent.setStr("removed", loaded ? "false" : "true");
+
+      StructuredLog::log("hhvm_sandbox_file_tearing", ent);
+    }
+  }
+
+  rl_mergedUnits->clear();
+}
+
 template <bool debugger>
 void Unit::mergeImpl(MergeInfo* mi) {
   assertx(m_mergeState.load(std::memory_order_relaxed) & MergeState::Merged);
   autoTypecheck(this);
 
+  if (!RO::RepoAuthoritative &&
+      !isSystemLib() &&
+      !origFilepath()->empty() &&
+      g_context && g_context->m_shouldSampleUnitTearing) {
+    rl_mergedUnits->emplace(this);
+  }
+
   FTRACE(1, "Merging unit {} ({} elements to define)\n",
          this->m_origFilepath->data(), mi->m_mergeablesSize);
 
diff --git a/hphp/runtime/vm/unit.h b/hphp/runtime/vm/unit.h
index 4eeee316542..51eb5673973 100644
--- a/hphp/runtime/vm/unit.h
+++ b/hphp/runtime/vm/unit.h
@@ -662,6 +662,12 @@ public:
   void setInterpretOnly();
 
   /*
+   * Log any units which were changed on disk after having been loaded by the
+   * current request.
+   */
+  static void logTearing();
+
+  /*
    * Get parse/runtime failure information if this unit is created as
    * a result of one.
    */
-- 
2.11.4.GIT