profiler redesign @akindiakov

osquery · Sep 14, 2018 · dcbd744 · dcbd744
1 parent 4cf9765
commit dcbd744
Show file tree

Hide file tree

Showing 4 changed files with 109 additions and 69 deletions.
diff --git a/osquery/dispatcher/scheduler.cpp b/osquery/dispatcher/scheduler.cpp
@@ -185,8 +185,12 @@ void SchedulerRunner::start() {
           if (query.splayed_interval > 0 && i % query.splayed_interval == 0) {
             TablePlugin::kCacheInterval = query.splayed_interval;
             TablePlugin::kCacheStep = i;
-            launchWithProfiling(
-                name, std::bind(launchQuery, std::ref(name), std::ref(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.

diff --git a/osquery/profiler/posix/profiler.cpp b/osquery/profiler/posix/profiler.cpp
@@ -42,6 +42,39 @@ int getRusageWho() {
 #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));
+  }
+}
+
+class 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_;
+};
+
 void recordRusageStatDifference(int64_t start_stat,
                                 int64_t end_stat,
                                 const std::string& stat_name) {
@@ -99,68 +132,42 @@ void recordRusageStatDifference(const struct rusage& start_stats,
                              monitoring_path_prefix + ".time.system");
 }
 
-enum class RusageError { FatalError = 1 };
-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));
-  }
-}
-
-Status launchQueryWithPosixProfiling(const std::string& name,
-                                     std::function<Status()> launcher) {
-  auto rusage_start = callRusage();
-
+void recordRusageStatDifference(CodeProfilerData& start_stats,
+                                CodeProfilerData& end_stats,
+                                const std::string& monitoring_path_prefix) {
+  auto rusage_start = start_stats.takeRusageData();
   if (!rusage_start) {
     LOG(ERROR) << "rusage_start error: "
                << rusage_start.getError().getFullMessageRecursive();
-  }
-
-  const auto start_time_point = std::chrono::steady_clock::now();
-
-  const auto status = launcher();
-
-  const auto query_duration =
-      std::chrono::duration_cast<std::chrono::milliseconds>(
-          std::chrono::steady_clock::now() - start_time_point);
-
-  const auto monitoring_path_prefix =
-      (boost::format("scheduler.executing_query.%s.%s") % name %
-       (status.ok() ? "success" : "failure"))
-          .str();
-
-  if (rusage_start) {
-    const auto rusage_end = callRusage();
-
-    if (rusage_end) {
-      recordRusageStatDifference(
-          *rusage_start, *rusage_end, monitoring_path_prefix);
-    } else {
+  } else {
+    auto rusage_end = end_stats.takeRusageData();
+    if (!rusage_end) {
       LOG(ERROR) << "rusage_end error: "
                  << rusage_end.getError().getFullMessageRecursive();
+    } else {
+      recordRusageStatDifference(
+          *rusage_start, *rusage_end, monitoring_path_prefix);
     }
   }
 
-  monitoring::record(monitoring_path_prefix + ".time.real.millis",
+  const auto query_duration =
+      std::chrono::duration_cast<std::chrono::milliseconds>(
+          end_stats.getWallTime() - start_stats.getWallTime());
+  monitoring::record(monitoring_path_prefix + ".time.wall.millis",
                      query_duration.count(),
                      monitoring::PreAggregationType::Min);
-
-  return status;
 }
+
 } // namespace
 
-Status launchWithProfiling(const std::string& name,
-                           std::function<Status()> launcher) {
+CodeProfiler::CodeProfiler(std::string name)
+    : name_(name), code_profiler_data_(new CodeProfilerData()) {}
+
+CodeProfiler::~CodeProfiler() {
   if (Killswitch::get().isPosixProfilingEnabled()) {
-    return launchQueryWithPosixProfiling(name, launcher);
-  } else {
-    return launcher(); // Just execute the query
+    CodeProfilerData code_profiler_data_end;
+    recordRusageStatDifference(
+        *code_profiler_data_, code_profiler_data_end, name_);
   }
 }
 

diff --git a/osquery/profiler/profiler.h b/osquery/profiler/profiler.h
@@ -10,13 +10,27 @@
 
 #pragma once
 
-#include <functional>
+#include <memory>
 #include <string>
 
-#include <osquery/status.h>
-
 namespace osquery {
-
-Status launchWithProfiling(const std::string& name,
-                           std::function<Status()> launcher);
+namespace {
+class CodeProfilerData;
 }
+
+class CodeProfiler final {
+ public:
+  CodeProfiler(std::string name);
+
+  ~CodeProfiler();
+
+  void appendName(const std::string& appendName) {
+    name_ += appendName;
+  }
+
+ private:
+  std::string name_;
+  std::unique_ptr<CodeProfilerData> code_profiler_data_;
+};
+
+} // namespace osquery
diff --git a/osquery/profiler/windows/profiler.cpp b/osquery/profiler/windows/profiler.cpp
@@ -17,23 +17,38 @@
 #include <osquery/profiler/profiler.h>
 
 namespace osquery {
+namespace {
 
-Status launchWithProfiling(const std::string& name,
-                           std::function<Status()> launcher) {
-  const auto start_time_point = std::chrono::steady_clock::now();
-  const auto status = launcher();
-  const auto monitoring_path_prefix =
-      (boost::format("scheduler.executing_query.%s.%s") % name %
-       (status.ok() ? "success" : "failure"))
-          .str();
-  const auto query_duration =
-      std::chrono::duration_cast<std::chrono::milliseconds>(
-          std::chrono::steady_clock::now() - start_time_point);
+class CodeProfilerData {
+ public:
+  CodeProfilerData() : wall_time_(std::chrono::steady_clock::now()) {}
+
+  const std::chrono::time_point<std::chrono::steady_clock>& getWallTime() {
+    return wall_time_;
+  }
+
+ private:
+  std::chrono::time_point<std::chrono::steady_clock> wall_time_;
+};
+
+} // namespace
+
+CodeProfiler::CodeProfiler(std::string name)
+    : name_(name), code_profiler_data_(new CodeProfilerData()) {}
+
+CodeProfiler::~CodeProfiler() {
   if (Killswitch::get().isWindowsProfilingEnabled()) {
-    monitoring::record(monitoring_path_prefix + ".time.real.millis",
+    CodeProfilerData code_profiler_data_end;
+
+    const auto query_duration =
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            code_profiler_data_end.getWallTime() -
+            code_profiler_data_->getWallTime());
+
+    monitoring::record(monitoring_path_prefix + ".time.wall.millis",
                        query_duration.count(),
                        monitoring::PreAggregationType::Min);
   }
-  return status;
 }
+
 } // namespace osquery