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/dispatcher/CMakeLists.txt

@@ -21,7 +21,21 @@ ADD_OSQUERY_LIBRARY(FALSE osquery_dispatcher_runners
   "${CMAKE_CURRENT_LIST_DIR}/scheduler.h"
   "${CMAKE_CURRENT_LIST_DIR}/distributed_runner.cpp"
   "${CMAKE_CURRENT_LIST_DIR}/distributed_runner.h"
+  "${CMAKE_CURRENT_LIST_DIR}/query_profiler.h"
 )
+if(POSIX)
+  target_sources(libosquery
+    PRIVATE
+      "${CMAKE_CURRENT_LIST_DIR}/posix/query_profiler.cpp"
+  )
+endif()
+
+if(WINDOWS)
+  target_sources(libosquery
+    PRIVATE
+      "${CMAKE_CURRENT_LIST_DIR}/windows/query_profiler.cpp"
+  )
+endif()
 
 ADD_OSQUERY_TEST_ADDITIONAL(
   "${CMAKE_CURRENT_LIST_DIR}/tests/scheduler_tests.cpp"

osquery/dispatcher/posix/query_profiler.cpp

@@ -0,0 +1,162 @@
+/**
+ *  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/dispatcher/query_profiler.h>
+#include <osquery/killswitch.h>
+#include <osquery/logger.h>
+#include <osquery/numeric_monitoring.h>
+
+namespace osquery {
+namespace {
+
+int getRusageWho() {
+  return
+#ifdef __linux__
+      RUSAGE_THREAD; // Linux supports more granular profiling
+#else
+      RUSAGE_SELF;
+#endif
+}
+
+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::P50);
+  } 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");
+}
+
+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));
+  }
+}
+
+void launchQueryWithPosixProfiling(const std::string& name,
+                                   std::function<Status()> launchQuery) {
+  const auto start_time_point = std::chrono::steady_clock::now();
+  auto rusage_start = callRusage();
+
+  if (!rusage_start) {
+    LOG(ERROR) << "rusage_start error: "
+               << rusage_start.getError().getFullMessageRecursive();
+  }
+
+  const auto status = launchQuery();
+  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 {
+      LOG(ERROR) << "rusage_end error: "
+                 << rusage_end.getError().getFullMessageRecursive();
+    }
+  }
+
+  const auto query_duration =
+      std::chrono::duration_cast<std::chrono::microseconds>(
+          std::chrono::steady_clock::now() - start_time_point);
+
+  monitoring::record(monitoring_path_prefix + ".time.real.millis",
+                     query_duration.count(),
+                     monitoring::PreAggregationType::Min);
+}
+} // namespace
+void launchQueryWithProfiling(const std::string& name,
+                              std::function<Status()> launchQuery) {
+  if (Killswitch::get().isPosixProfilingEnabled()) {
+    launchQueryWithPosixProfiling(name, launchQuery);
+  } else {
+    launchQuery(); // Just execute the query
+  }
+}
+
+} // namespace osquery

osquery/dispatcher/query_profiler.h

@@ -0,0 +1,21 @@
+/**
+ *  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 <functional>
+#include <string>
+
+#include <osquery/status.h>
+
+namespace osquery {
+void launchQueryWithProfiling(const std::string& name,
+                              std::function<Status()> launchQuery);
+}

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>
@@ -24,6 +26,7 @@
 
 #include "osquery/config/parsers/decorators.h"
 #include "osquery/core/process.h"
+#include "osquery/dispatcher/query_profiler.h"
 #include "osquery/dispatcher/scheduler.h"
 #include "osquery/sql/sqlite_util.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,8 @@ void SchedulerRunner::start() {
           if (query.splayed_interval > 0 && i % query.splayed_interval == 0) {
             TablePlugin::kCacheInterval = query.splayed_interval;
             TablePlugin::kCacheStep = i;
-            launchQueryWithProfiling(name, query);
+            launchQueryWithProfiling(
+                name, std::bind(launchQuery, std::ref(name), std::ref(query)));
           }
         }));
     // Configuration decorators run on 60 second intervals only.

osquery/dispatcher/windows/query_profiler.cpp

@@ -0,0 +1,37 @@
+/**
+ *  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.
+ */
+
+#include <chrono>
+
+#include <boost/format.hpp>
+
+#include <osquery/dispatcher/query_profiler.h>
+#include <osquery/killswitch.h>
+#include <osquery/numeric_monitoring.h>
+
+namespace osquery {
+void launchQueryWithProfiling(const std::string& name,
+                              std::function<Status()> launchQuery) {
+  const auto start_time_point = std::chrono::steady_clock::now();
+  const auto status = launchQuery();
+  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::microseconds>(
+          std::chrono::steady_clock::now() - start_time_point);
+  if (Killswitch::get().isWindowsProfilingEnabled()) {
+    monitoring::record(monitoring_path_prefix + ".time.real.millis",
+                       query_duration.count(),
+                       monitoring::PreAggregationType::Min);
+  }
+}
+} // namespace osquery

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() {