posix profiling

include/osquery/killswitch.h

@@ -7,11 +7,14 @@
  * (found in the COPYING file in the root directory of this source tree). You
  * may select, at your option, one of the above-listed licenses.
  */
+
 #pragma once
+
 #include <string>
 
 #include <boost/core/noncopyable.hpp>
 
+#include <osquery/core.h>
 #include <osquery/expected.h>
 #include <osquery/status.h>
 
@@ -31,6 +34,10 @@ class Killswitch : private boost::noncopyable {
  public:
   virtual ~Killswitch();
 
+  // Author: @guliashvili
+  // Creation Time: 5/09/2018
+  bool isPosixProfilingEnabled();
+
   // Author: @guliashvili
   // Creation Time: 4/09/2018
   bool isTotalQueryCounterMonitorEnabled();
@@ -41,7 +48,7 @@ class Killswitch : private boost::noncopyable {
 
   // Author: @guliashvili
   // Creation Time: 3/09/2018
-  bool isExecutingQueryMonitorEnabled();
+  bool isWindowsProfilingEnabled();
 
   // Author: @guliashvili
   // Creation Time: 24/08/2018

osquery/CMakeLists.txt

@@ -102,6 +102,7 @@ include(sql/CMakeLists.txt)
 include(remote/CMakeLists.txt)
 include(utils/CMakeLists.txt)
 include(numeric_monitoring/CMakeLists.txt)
+include(profiler/CMakeLists.txt)
 
 if(NOT SKIP_CARVER)
   include(carver/CMakeLists.txt)

osquery/dispatcher/scheduler.cpp

@@ -8,9 +8,11 @@
  *  You may select, at your option, one of the above-listed licenses.
  */
 
+#include <algorithm>
 #include <ctime>
 
 #include <boost/format.hpp>
+#include <boost/io/detail/quoted_manip.hpp>
 
 #include <osquery/config.h>
 #include <osquery/core.h>
@@ -19,6 +21,7 @@
 #include <osquery/killswitch.h>
 #include <osquery/logger.h>
 #include <osquery/numeric_monitoring.h>
+#include <osquery/profiler/profiler.h>
 #include <osquery/query.h>
 #include <osquery/system.h>
 
@@ -92,8 +95,7 @@ SQLInternal monitor(const std::string& name, const ScheduledQuery& query) {
   return sql;
 }
 
-inline Status launchQuery(const std::string& name,
-                          const ScheduledQuery& query) {
+Status launchQuery(const std::string& name, const ScheduledQuery& query) {
   // Execute the scheduled query and create a named query object.
   LOG(INFO) << "Executing scheduled query " << name << ": " << query.query;
   runDecorators(DECORATE_ALWAYS);
@@ -173,22 +175,6 @@ inline Status launchQuery(const std::string& name,
   return status;
 }
 
-inline void launchQueryWithProfiling(const std::string& name,
-                                     const ScheduledQuery& query) {
-  auto start_time_point = std::chrono::steady_clock::now();
-  auto status = launchQuery(name, query);
-  auto query_duration = std::chrono::duration_cast<std::chrono::milliseconds>(
-      std::chrono::steady_clock::now() - start_time_point);
-  if (Killswitch::get().isExecutingQueryMonitorEnabled()) {
-    auto monitoring_path = boost::format("scheduler.executing_query.%s.%s") %
-                           name % (status.ok() ? "success" : "failure");
-
-    monitoring::record(monitoring_path.str(),
-                       query_duration.count(),
-                       monitoring::PreAggregationType::Min);
-  }
-}
-
 void SchedulerRunner::start() {
   // Start the counter at the second.
   auto i = osquery::getUnixTime();
@@ -199,7 +185,12 @@ void SchedulerRunner::start() {
           if (query.splayed_interval > 0 && i % query.splayed_interval == 0) {
             TablePlugin::kCacheInterval = query.splayed_interval;
             TablePlugin::kCacheStep = i;
-            launchQueryWithProfiling(name, query);
+            {
+              CodeProfiler codeProfiler(
+                  (boost::format("scheduler.executing_query.%s") % name).str());
+              const auto status = launchQuery(name, query);
+              codeProfiler.appendName(status.ok() ? ".success" : ".failure");
+            };
           }
         }));
     // Configuration decorators run on 60 second intervals only.

osquery/killswitch/killswitch.cpp

@@ -32,6 +32,10 @@ FLAG(string,
 Killswitch::Killswitch() {}
 Killswitch::~Killswitch() = default;
 
+bool Killswitch::isPosixProfilingEnabled() {
+  return isNewCodeEnabled("posixProfilingSwitch");
+}
+
 bool Killswitch::isTotalQueryCounterMonitorEnabled() {
   return isNewCodeEnabled("totalQueryCounterMonitorSwitch");
 }
@@ -40,8 +44,8 @@ bool Killswitch::isAppStartMonitorEnabled() {
   return isNewCodeEnabled("appStartMonitorSwitch");
 }
 
-bool Killswitch::isExecutingQueryMonitorEnabled() {
-  return isNewCodeEnabled("executingQueryMonitorSwitch");
+bool Killswitch::isWindowsProfilingEnabled() {
+  return isNewCodeEnabled("windowsProfilingSwitch");
 }
 
 bool Killswitch::isConfigBackupEnabled() {

osquery/profiler/CMakeLists.txt

@@ -0,0 +1,25 @@
+#  Copyright (c) 2014-present, Facebook, Inc.
+#  All rights reserved.
+#
+#  This source code is licensed under both the Apache 2.0 license (found in the
+#  LICENSE file in the root directory of this source tree) and the GPLv2 (found
+#  in the COPYING file in the root directory of this source tree).
+#  You may select, at your option, one of the above-listed licenses.
+
+target_sources(libosquery
+  PRIVATE
+    "${CMAKE_CURRENT_LIST_DIR}/profiler.h"
+)
+if(POSIX)
+  target_sources(libosquery
+    PRIVATE
+      "${CMAKE_CURRENT_LIST_DIR}/posix/profiler.cpp"
+  )
+endif()
+
+if(WINDOWS)
+  target_sources(libosquery
+    PRIVATE
+      "${CMAKE_CURRENT_LIST_DIR}/windows/profiler.cpp"
+  )
+endif()

osquery/profiler/posix/profiler.cpp

@@ -0,0 +1,168 @@
+/**
+ *  Copyright (c) 2014-present, Facebook, Inc.
+ *  All rights reserved.
+ *
+ *  This source code is licensed under both the Apache 2.0 license (found in the
+ *  LICENSE file in the root directory of this source tree) and the GPLv2 (found
+ *  in the COPYING file in the root directory of this source tree).
+ *  You may select, at your option, one of the above-listed licenses.
+ */
+
+#ifdef __linux__
+// Needed for linux specific RUSAGE_THREAD, before including anything else
+#ifndef _GNU_SOURCE
+#define _GNU_SOURCE
+#endif
+#endif
+
+#include <cerrno>
+#include <cstdint>
+#include <cstring>
+
+#include <sys/resource.h>
+#include <sys/time.h>
+
+#include <boost/format.hpp>
+#include <boost/io/detail/quoted_manip.hpp>
+
+#include <osquery/killswitch.h>
+#include <osquery/logger.h>
+#include <osquery/numeric_monitoring.h>
+#include <osquery/profiler/profiler.h>
+
+namespace osquery {
+namespace {
+
+int getRusageWho() {
+  return
+#ifdef __linux__
+      RUSAGE_THREAD; // Linux supports more granular profiling
+#else
+      RUSAGE_SELF;
+#endif
+}
+
+enum class RusageError { FatalError = 1 };
+
+static Expected<struct rusage, RusageError> callRusage() {
+  struct rusage stats;
+  const int who = getRusageWho();
+  auto rusage_status = getrusage(who, &stats);
+  if (rusage_status != -1) {
+    return stats;
+  } else {
+    return createError(RusageError::FatalError, "")
+           << "Linux query profiling failed. error code: " << rusage_status
+           << " message: " << boost::io::quoted(strerror(errno));
+  }
+}
+
+void recordRusageStatDifference(int64_t start_stat,
+                                int64_t end_stat,
+                                const std::string& stat_name) {
+  if (end_stat == 0) {
+    TLOG << "rusage field " << boost::io::quoted(stat_name)
+         << " is not supported";
+  } else if (start_stat <= end_stat) {
+    monitoring::record(
+        stat_name, end_stat - start_stat, monitoring::PreAggregationType::P99);
+  } else {
+    LOG(WARNING) << "Possible overflow detected in rusage field: "
+                 << boost::io::quoted(stat_name);
+  }
+}
+
+void recordRusageStatDifference(const struct timeval& start_stat,
+                                const struct timeval& end_stat,
+                                const std::string& stat_name) {
+  recordRusageStatDifference(
+      std::chrono::duration_cast<std::chrono::milliseconds>(
+          std::chrono::seconds(start_stat.tv_sec) +
+          std::chrono::microseconds(start_stat.tv_usec))
+          .count(),
+      std::chrono::duration_cast<std::chrono::milliseconds>(
+          std::chrono::seconds(end_stat.tv_sec) +
+          std::chrono::microseconds(end_stat.tv_usec))
+          .count(),
+      stat_name + ".millis");
+}
+
+void recordRusageStatDifference(const struct rusage& start_stats,
+                                const struct rusage& end_stats,
+                                const std::string& monitoring_path_prefix) {
+  recordRusageStatDifference(
+      0, end_stats.ru_maxrss, monitoring_path_prefix + ".rss.max.kb");
+
+  recordRusageStatDifference(start_stats.ru_maxrss,
+                             end_stats.ru_maxrss,
+                             monitoring_path_prefix + ".rss.increase.kb");
+
+  recordRusageStatDifference(start_stats.ru_inblock,
+                             end_stats.ru_inblock,
+                             monitoring_path_prefix + ".input.load");
+
+  recordRusageStatDifference(start_stats.ru_oublock,
+                             end_stats.ru_oublock,
+                             monitoring_path_prefix + ".output.load");
+
+  recordRusageStatDifference(start_stats.ru_utime,
+                             end_stats.ru_utime,
+                             monitoring_path_prefix + ".time.user");
+
+  recordRusageStatDifference(start_stats.ru_stime,
+                             end_stats.ru_stime,
+                             monitoring_path_prefix + ".time.system");
+}
+
+} // namespace
+
+class CodeProfiler::CodeProfilerData {
+ public:
+  CodeProfilerData()
+      : rusage_data_(callRusage()),
+        wall_time_(std::chrono::steady_clock::now()) {}
+
+  const std::chrono::time_point<std::chrono::steady_clock>& getWallTime() {
+    return wall_time_;
+  }
+  Expected<struct rusage, RusageError> takeRusageData() {
+    return std::move(rusage_data_);
+  }
+
+ private:
+  Expected<struct rusage, RusageError> rusage_data_;
+  std::chrono::time_point<std::chrono::steady_clock> wall_time_;
+};
+
+CodeProfiler::CodeProfiler(std::string name)
+    : name_(name), code_profiler_data_(new CodeProfilerData()) {}
+
+CodeProfiler::~CodeProfiler() {
+  if (Killswitch::get().isPosixProfilingEnabled()) {
+    CodeProfilerData code_profiler_data_end;
+
+    auto rusage_start = code_profiler_data_->takeRusageData();
+    if (!rusage_start) {
+      LOG(ERROR) << "rusage_start error: "
+                 << rusage_start.getError().getFullMessageRecursive();
+    } else {
+      auto rusage_end = code_profiler_data_end.takeRusageData();
+      if (!rusage_end) {
+        LOG(ERROR) << "rusage_end error: "
+                   << rusage_end.getError().getFullMessageRecursive();
+      } else {
+        recordRusageStatDifference(*rusage_start, *rusage_end, name_);
+      }
+    }
+
+    const auto query_duration =
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            code_profiler_data_end.getWallTime() -
+            code_profiler_data_->getWallTime());
+    monitoring::record(name_ + ".time.wall.millis",
+                       query_duration.count(),
+                       monitoring::PreAggregationType::Min);
+  }
+}
+
+} // namespace osquery

osquery/profiler/profiler.h

@@ -0,0 +1,35 @@
+/**
+ *  Copyright (c) 2014-present, Facebook, Inc.
+ *  All rights reserved.
+ *
+ *  This source code is licensed under both the Apache 2.0 license (found in the
+ *  LICENSE file in the root directory of this source tree) and the GPLv2 (found
+ *  in the COPYING file in the root directory of this source tree).
+ *  You may select, at your option, one of the above-listed licenses.
+ */
+
+#pragma once
+
+#include <memory>
+#include <string>
+
+namespace osquery {
+
+class CodeProfiler final {
+ public:
+  CodeProfiler(std::string name);
+
+  ~CodeProfiler();
+
+  void appendName(const std::string& appendName) {
+    name_ += appendName;
+  }
+
+ private:
+  class CodeProfilerData;
+
+  std::string name_;
+  std::unique_ptr<CodeProfilerData> code_profiler_data_;
+};
+
+} // namespace osquery