event logging for various interesting things in ext_facts

Summary:
I want to start collecting telemetry on all the weird corner cases and failure modes
that can happen with Facts. This is a start. Rare events bypass PerfSampleRate when
it's nonzero but still skip logging when it is zero.

Refactored more of the hhvm_sandbox_events logging code to a central location
runtime/base/sandbox-events.{cpp,h} since we need to call it from outside FactsLogger.

Reviewed By: nt591

Differential Revision: D52580966

fbshipit-source-id: 941187d990a0eb4071045d31378fe64f93e2fb8f

Author: edwinsmith

hphp/runtime/base/autoload-handler.cpp

@@ -28,6 +28,7 @@
 #include "hphp/runtime/base/container-functions.h"
 #include "hphp/runtime/base/runtime-option.h"
 #include "hphp/runtime/base/repo-autoload-map.h"
+#include "hphp/runtime/base/sandbox-events.h"
 #include "hphp/runtime/base/unit-cache.h"
 #include "hphp/runtime/vm/repo-global-data.h"
 #include "hphp/runtime/vm/unit.h"
@@ -89,6 +90,9 @@ FactsStore* getFactsForRequest() {
     return map;
   } catch (const std::exception& e) {
     auto repoRoot = repoOptions->dir();
+    rareSboxEvent("autoload-handler",
+        folly::sformat("getFactsForRequest: {}", e.what()),
+        repoRoot.native());
     Logger::FError(
         "Failed to update native autoloader, not natively autoloading {}. {}\n",
         repoRoot.native(),

hphp/runtime/base/sandbox-events.cpp

@@ -0,0 +1,43 @@
+/*
+   +----------------------------------------------------------------------+
+   | HipHop for PHP                                                       |
+   +----------------------------------------------------------------------+
+   | Copyright (c) 2010-present Facebook, Inc. (http://www.facebook.com)  |
+   +----------------------------------------------------------------------+
+   | This source file is subject to version 3.01 of the PHP license,      |
+   | that is bundled with this package in the file LICENSE, and is        |
+   | available through the world-wide-web at the following url:           |
+   | http://www.php.net/license/3_01.txt                                  |
+   | If you did not receive a copy of the PHP license and are unable to   |
+   | obtain it through the world-wide-web, please send a note to          |
+   | [email protected] so we can mail you a copy immediately.               |
+   +----------------------------------------------------------------------+
+*/
+#include "hphp/runtime/base/sandbox-events.h"
+#include "hphp/runtime/base/runtime-option.h"
+
+namespace HPHP {
+
+void logSboxEvent(uint32_t sample_rate, std::string_view source,
+    std::string_view event, std::string_view key, uint64_t duration_us) {
+  if (!getenv("INSIDE_RE_WORKER")) {
+    StructuredLogEntry ent;
+    ent.force_init = true;
+    ent.setProcessUuid("hhvm_uuid");
+    ent.setInt("sample_rate", sample_rate);
+    ent.setStr("source", source);
+    ent.setStr("event", event);
+    ent.setStr("key", key);
+    ent.setInt("duration_us", duration_us);
+    StructuredLog::log("hhvm_sandbox_events", ent);
+  }
+}
+
+void rareSboxEvent(std::string_view source, std::string_view event,
+                   std::string_view key) {
+  if (RuntimeOption::AutoloadPerfSampleRate != 0) {
+    logSboxEvent(1, source, event, key, 0);
+  }
+}
+
+}

hphp/runtime/base/sandbox-events.h

@@ -0,0 +1,49 @@
+/*
+   +----------------------------------------------------------------------+
+   | HipHop for PHP                                                       |
+   +----------------------------------------------------------------------+
+   | Copyright (c) 2010-present Facebook, Inc. (http://www.facebook.com)  |
+   +----------------------------------------------------------------------+
+   | This source file is subject to version 3.01 of the PHP license,      |
+   | that is bundled with this package in the file LICENSE, and is        |
+   | available through the world-wide-web at the following url:           |
+   | http://www.php.net/license/3_01.txt                                  |
+   | If you did not receive a copy of the PHP license and are unable to   |
+   | obtain it through the world-wide-web, please send a note to          |
+   | [email protected] so we can mail you a copy immediately.               |
+   +----------------------------------------------------------------------+
+*/
+
+#pragma once
+#include <chrono>
+#include <string_view>
+#include "hphp/util/struct-log.h"
+
+namespace HPHP {
+
+void logSboxEvent(uint32_t sampleRate, std::string_view source,
+                     std::string_view event, std::string_view key,
+                     uint64_t duration_us);
+
+void rareSboxEvent(std::string_view source, std::string_view event,
+                   std::string_view key);
+
+template <typename F>
+auto timeSboxEvent(
+    uint32_t sampleRate, std::string_view source,
+    std::string_view event, std::string_view key, F&& func) {
+  using namespace std::chrono_literals;
+  auto t0 = std::chrono::steady_clock::now();
+  SCOPE_EXIT {
+    if (StructuredLog::coinflip(sampleRate)) {
+      auto tf = std::chrono::steady_clock::now();
+      auto elapsed =
+          std::chrono::duration<double, std::chrono::microseconds::period>{
+              tf - t0};
+      logSboxEvent(sampleRate, source, event, key, elapsed.count());
+    }
+  };
+  return func();
+}
+
+}

hphp/runtime/ext/facts/ext_facts.cpp

@@ -40,7 +40,7 @@
 #include "hphp/runtime/base/autoload-map.h"
 #include "hphp/runtime/base/builtin-functions.h"
 #include "hphp/runtime/base/config.h"
-#include "hphp/runtime/base/init-fini-node.h"
+#include "hphp/runtime/base/sandbox-events.h"
 #include "hphp/runtime/base/static-string-table.h"
 #include "hphp/runtime/base/string-data.h"
 #include "hphp/runtime/base/tv-type.h"
@@ -391,6 +391,7 @@ FactsStore* SqliteAutoloadMapFactory::getForOptions(
       return {std::move(mk)};
     } catch (const RepoOptionsParseExc& e) {
       XLOG(ERR) << e.what();
+      rareSboxEvent("ext_facts", "RepoOptionsParseExc", e.what());
       return std::nullopt;
     }
   }();
@@ -421,6 +422,8 @@ FactsStore* SqliteAutoloadMapFactory::getForOptions(
   };
 
   if (mapKey->m_dbKey.m_mode == SQLite::OpenMode::ReadOnly) {
+    rareSboxEvent(
+        "ext_facts", "getForOptions opening trusted store", mapKey->toString());
     XLOGF(
         DBG0,
         "Loading {} from trusted Autoload DB at {}",
@@ -445,6 +448,8 @@ FactsStore* SqliteAutoloadMapFactory::getForOptions(
   // Prefetch a FactsDB if we don't have one, while guarded by m_mutex
   prefetchDb(mapKey->m_root, mapKey->m_dbKey);
 
+  rareSboxEvent(
+      "ext_facts", "getForOptions opening mutable store", mapKey->toString());
   return m_stores
       .insert(
           {*mapKey,
@@ -480,8 +485,11 @@ void SqliteAutoloadMapFactory::garbageCollectUnusedAutoloadMaps(
       XLOG(INFO) << "Evicting SqliteAutoloadMap: " << mapKey.toString();
       auto it = m_stores.find(mapKey);
       if (it != m_stores.end()) {
+        rareSboxEvent("ext_facts", __func__, mapKey.toString());
         maps.push_back(std::move(it->second));
         m_stores.erase(it);
+      } else {
+        rareSboxEvent("ext_facts", "evict unknown mapkey", mapKey.toString());
       }
       m_lastUsed.erase(mapKey);
     }
@@ -579,6 +587,7 @@ Variant HHVM_FUNCTION(facts_db_path, const String& rootStr) {
   }();
   if (!root) {
     XLOG(ERR) << "Error resolving " << rootStr.slice();
+    rareSboxEvent("ext_facts", "facts_db_path bad root", rootStr.slice());
     return Variant{Variant::NullInit{}};
   }
   assertx(root->is_absolute());
@@ -591,6 +600,10 @@ Variant HHVM_FUNCTION(facts_db_path, const String& rootStr) {
     return Variant{
         Facts::SqliteAutoloadMapKey::get(repoOptions).m_dbKey.m_path.native()};
   } catch (const Facts::RepoOptionsParseExc& e) {
+    rareSboxEvent(
+        "ext_facts",
+        folly::sformat("facts_db_path {}", rootStr.slice()),
+        e.what());
     throw_invalid_operation_exception(makeStaticString(e.what()));
   }
 }

hphp/runtime/ext/facts/facts-store.cpp

@@ -33,6 +33,7 @@
 #include "hphp/runtime/base/array-init.h"
 #include "hphp/runtime/base/array-iterator.h"
 #include "hphp/runtime/base/request-injection-data.h"
+#include "hphp/runtime/base/sandbox-events.h"
 #include "hphp/runtime/base/type-array.h"
 #include "hphp/runtime/base/type-string.h"
 #include "hphp/runtime/base/type-variant.h"
@@ -713,9 +714,15 @@ struct FactsStoreImpl final
               delta.m_files.size());
           auto sharedThis = weakThis.lock();
           if (!sharedThis) {
+            rareSboxEvent("facts-store", "subscribe weakThis==null", "");
             return;
           }
-          sharedThis->update();
+          timeSboxEvent(
+              RO::AutoloadPerfSampleRate,
+              "facts-store",
+              "subscribe update",
+              "",
+              [&] { sharedThis->update(); });
         });
   }
 
@@ -743,6 +750,8 @@ struct FactsStoreImpl final
             INFO,
             "Suppression file found at {}, not updating native Facts.",
             suppressionFilePath.native());
+        rareSboxEvent(
+            "facts-store", "update supressed", suppressionFilePath.native());
         return {};
       }
     }
@@ -774,6 +783,7 @@ struct FactsStoreImpl final
                       "Exception while querying watcher: {}",
                       delta.exception().what());
                   XLOG(ERR) << msg;
+                  rareSboxEvent("facts-store", "update watcher exception", msg);
                   throw UpdateExc{msg};
                 }
                 return updateWithDelta(std::move(delta.value()));
@@ -788,8 +798,7 @@ struct FactsStoreImpl final
           auto lastWatchmanQueryStart = m_lastWatchmanQueryStart.load();
           if (UNLIKELY(lastWatchmanQueryStart < updateStart)) {
             auto currentTime = std::chrono::steady_clock::now();
-            XLOGF(
-                ERR,
+            auto msg = folly::sformat(
                 "Stale update. Last Watchman query was {}ms ago, but update was only {}ms ago.",
                 std::chrono::duration_cast<
                     std::chrono::duration<double, std::milli>>(
@@ -799,15 +808,25 @@ struct FactsStoreImpl final
                     std::chrono::duration<double, std::milli>>(
                     currentTime - updateStart)
                     .count());
+            XLOG(ERR, msg);
+            rareSboxEvent("facts-store", msg, "");
           }
           assertx(updateStart < lastWatchmanQueryStart);
+          auto queryMicros = std::chrono::duration_cast<std::chrono::duration<
+              double,
+              std::chrono::microseconds::period>>(
+                                 lastWatchmanQueryStart - updateStart)
+                                 .count();
+          logSboxEvent(
+              RO::AutoloadPerfSampleRate,
+              "facts-store",
+              "watchman query",
+              m_root.native(),
+              queryMicros);
           XLOGF(
-              INFO,
+              DBG0,
               "update waited {}ms for a Watchman query to return.",
-              std::chrono::duration_cast<
-                  std::chrono::duration<double, std::milli>>(
-                  lastWatchmanQueryStart - updateStart)
-                  .count());
+              queryMicros / 1000);
           return res;
         })
         .semi();

hphp/runtime/ext/facts/log-perf.cpp

@@ -15,8 +15,9 @@
 */
 #include "hphp/runtime/ext/facts/log-perf.h"
 #include <folly/logging/xlog.h>
+#include "hphp/runtime/base/autoload-map.h"
+#include "hphp/runtime/base/sandbox-events.h"
 #include "hphp/runtime/base/type-variant.h"
-#include "hphp/util/struct-log.h"
 
 namespace HPHP::Facts {
 
@@ -47,26 +48,8 @@ auto FactsLogger::logPerf(
     std::string_view method,
     std::string_view key,
     F&& func) const {
-  using namespace std::chrono_literals;
-  auto t0 = std::chrono::steady_clock::now();
-  SCOPE_EXIT {
-    if (StructuredLog::coinflip(m_sampleRate)) {
-      auto tf = std::chrono::steady_clock::now();
-      auto elapsed =
-          std::chrono::duration<double, std::chrono::microseconds::period>{
-              tf - t0};
-      StructuredLogEntry ent;
-      ent.force_init = true;
-      ent.setProcessUuid("hhvm_uuid");
-      ent.setInt("sample_rate", m_sampleRate);
-      ent.setStr("source", m_impl);
-      ent.setStr("event", method);
-      ent.setStr("key", key);
-      ent.setInt("duration_us", elapsed.count());
-      StructuredLog::log("hhvm_sandbox_events", ent);
-    }
-  };
-  return func();
+  return timeSboxEvent(
+      m_sampleRate, m_impl, method, key, std::forward<F>(func));
 }
 
 void FactsLogger::ensureUpdated() {