]> git.ipfire.org Git - thirdparty/ccache.git/commitdiff
Add stats log file, logging input file and result (#854)
authorAnders Björklund <anders.f.bjorklund@gmail.com>
Tue, 15 Jun 2021 19:21:35 +0000 (21:21 +0200)
committerGitHub <noreply@github.com>
Tue, 15 Jun 2021 19:21:35 +0000 (21:21 +0200)
doc/MANUAL.adoc
src/Config.cpp
src/Config.hpp
src/Statistics.cpp
src/Statistics.hpp
src/ccache.cpp
unittest/test_Config.cpp
unittest/test_Statistics.cpp

index 3c82439311d9c167bdf80dbdac6c40dbfe5d15cf..2856d68dd0d0495b6afb59f376fc8413432fbb0a 100644 (file)
@@ -153,6 +153,11 @@ compiler's documentation.
     (environment variable, configuration file or compile-time default) in
     human-readable format.
 
+*`--show-log-stats`*::
+
+    Print statistics counters from the stats log in human-readable format.
+    See <<config_stats_log,*stats_log*>>.
+
 *`-s`*, *`--show-stats`*::
 
     Print a summary of configuration and statistics counters in human-readable
@@ -844,6 +849,14 @@ information.
     If true, ccache will update the statistics counters on each compilation.
     The default is true.
 
+[[config_stats_log]] *stats_log* (*CCACHE_STATSLOG*)::
+
+    If set to a file path, ccache will write statistics counter updates to the
+    specified file. This is useful for getting statistics for individual builds.
+    To show a summary of the current stats log, use: `ccache --show-log-stats`.
++
+NOTE: Lines in the stats log starting with a hash sign (`#`) are comments.
+
 [[config_temporary_dir]] *temporary_dir* (*CCACHE_TEMPDIR*)::
 
     This option specifies where ccache will put temporary files. The default is
index 9e7092360f887044e34b2c701efd1de52b4890ce..06e35cabf1a24178df76110fe91438559fc0a06c 100644 (file)
@@ -78,6 +78,7 @@ enum class ConfigItem {
   run_second_cpp,
   sloppiness,
   stats,
+  stats_log,
   temporary_dir,
   umask,
 };
@@ -119,6 +120,7 @@ const std::unordered_map<std::string, ConfigItem> k_config_key_table = {
   {"run_second_cpp", ConfigItem::run_second_cpp},
   {"sloppiness", ConfigItem::sloppiness},
   {"stats", ConfigItem::stats},
+  {"stats_log", ConfigItem::stats_log},
   {"temporary_dir", ConfigItem::temporary_dir},
   {"umask", ConfigItem::umask},
 };
@@ -161,6 +163,7 @@ const std::unordered_map<std::string, std::string> k_env_variable_table = {
   {"RECACHE", "recache"},
   {"SLOPPINESS", "sloppiness"},
   {"STATS", "stats"},
+  {"STATSLOG", "stats_log"},
   {"TEMPDIR", "temporary_dir"},
   {"UMASK", "umask"},
 };
@@ -632,6 +635,9 @@ Config::get_string_value(const std::string& key) const
   case ConfigItem::stats:
     return format_bool(m_stats);
 
+  case ConfigItem::stats_log:
+    return m_stats_log;
+
   case ConfigItem::temporary_dir:
     return m_temporary_dir;
 
@@ -871,6 +877,10 @@ Config::set_item(const std::string& key,
     m_stats = parse_bool(value, env_var_key, negate);
     break;
 
+  case ConfigItem::stats_log:
+    m_stats_log = Util::expand_environment_variables(value);
+    break;
+
   case ConfigItem::temporary_dir:
     m_temporary_dir = Util::expand_environment_variables(value);
     m_temporary_dir_configured_explicitly = true;
index eb574dc8c45f0f45fc5c73afb0a6611f4b8eb7b2..1fd560cea8e8297a066e56a04fa9ae748ad33461 100644 (file)
@@ -77,6 +77,7 @@ public:
   bool run_second_cpp() const;
   uint32_t sloppiness() const;
   bool stats() const;
+  const std::string& stats_log() const;
   const std::string& temporary_dir() const;
   uint32_t umask() const;
 
@@ -169,6 +170,7 @@ private:
   bool m_run_second_cpp = true;
   uint32_t m_sloppiness = 0;
   bool m_stats = true;
+  std::string m_stats_log;
   std::string m_temporary_dir;
   uint32_t m_umask = std::numeric_limits<uint32_t>::max(); // Don't set umask
 
@@ -401,6 +403,12 @@ Config::stats() const
   return m_stats;
 }
 
+inline const std::string&
+Config::stats_log() const
+{
+  return m_stats_log;
+}
+
 inline const std::string&
 Config::temporary_dir() const
 {
index 08ad8928c9af7b834029b07451a928416d577de6..ba98a76c1817389b1d3ad52aa269a4d88a8d6308 100644 (file)
 
 #include "AtomicFile.hpp"
 #include "Config.hpp"
+#include "File.hpp"
 #include "Lockfile.hpp"
 #include "Logging.hpp"
 #include "Util.hpp"
+#include "assertions.hpp"
 #include "exceptions.hpp"
 #include "fmtmacros.hpp"
 
-const unsigned FLAG_NOZERO = 1; // don't zero with the -z option
-const unsigned FLAG_ALWAYS = 2; // always show, even if zero
-const unsigned FLAG_NEVER = 4;  // never show
+#include <fstream>
+#include <unordered_map>
+
+const unsigned FLAG_NOZERO = 1;     // don't zero with the -z option
+const unsigned FLAG_ALWAYS = 2;     // always show, even if zero
+const unsigned FLAG_NEVER = 4;      // never show
+const unsigned FLAG_NOSTATSLOG = 8; // don't show for statslog
 
 using nonstd::nullopt;
 using nonstd::optional;
@@ -88,8 +94,8 @@ for_each_level_1_and_2_stats_file(
   }
 }
 
-static std::pair<Counters, time_t>
-collect_counters(const Config& config)
+std::pair<Counters, time_t>
+Statistics::collect_counters(const Config& config)
 {
   Counters counters;
   uint64_t zero_timestamp = 0;
@@ -173,11 +179,14 @@ const StatisticsField k_statistics_fields[] = {
   STATISTICS_FIELD(bad_output_file, "could not write to output file"),
   STATISTICS_FIELD(no_input_file, "no input file"),
   STATISTICS_FIELD(error_hashing_extra_file, "error hashing extra file"),
-  STATISTICS_FIELD(cleanups_performed, "cleanups performed", FLAG_ALWAYS),
-  STATISTICS_FIELD(files_in_cache, "files in cache", FLAG_NOZERO | FLAG_ALWAYS),
+  STATISTICS_FIELD(
+    cleanups_performed, "cleanups performed", FLAG_NOSTATSLOG | FLAG_ALWAYS),
+  STATISTICS_FIELD(files_in_cache,
+                   "files in cache",
+                   FLAG_NOZERO | FLAG_NOSTATSLOG | FLAG_ALWAYS),
   STATISTICS_FIELD(cache_size_kibibyte,
                    "cache size",
-                   FLAG_NOZERO | FLAG_ALWAYS,
+                   FLAG_NOZERO | FLAG_NOSTATSLOG | FLAG_ALWAYS,
                    format_size_times_1024),
   STATISTICS_FIELD(obsolete_max_files, "OBSOLETE", FLAG_NOZERO | FLAG_NEVER),
   STATISTICS_FIELD(obsolete_max_size, "OBSOLETE", FLAG_NOZERO | FLAG_NEVER),
@@ -215,6 +224,34 @@ read(const std::string& path)
   return counters;
 }
 
+Counters
+read_log(const std::string& path)
+{
+  Counters counters;
+
+  std::unordered_map<std::string, Statistic> m;
+  for (const auto& field : k_statistics_fields) {
+    m[field.id] = field.statistic;
+  }
+
+  std::ifstream in(path);
+  std::string line;
+  while (std::getline(in, line, '\n')) {
+    if (line[0] == '#') {
+      continue;
+    }
+    auto search = m.find(line);
+    if (search != m.end()) {
+      Statistic statistic = search->second;
+      counters.increment(statistic, 1);
+    } else {
+      LOG("Unknown statistic: {}", line);
+    }
+  }
+
+  return counters;
+}
+
 optional<Counters>
 update(const std::string& path,
        std::function<void(Counters& counters)> function)
@@ -244,14 +281,48 @@ update(const std::string& path,
   return counters;
 }
 
-optional<std::string>
+void
+log_result(const std::string& path,
+           const std::string& input,
+           const std::string& result)
+{
+  File file(path, "ab");
+  if (file) {
+    PRINT(*file, "# {}\n", input);
+    PRINT(*file, "{}\n", result);
+  } else {
+    LOG("Failed to open {}: {}", path, strerror(errno));
+  }
+}
+
+static const StatisticsField*
 get_result(const Counters& counters)
 {
   for (const auto& field : k_statistics_fields) {
     if (counters.get(field.statistic) != 0 && !(field.flags & FLAG_NOZERO)) {
-      return field.message;
+      return &field;
     }
   }
+  return nullptr;
+}
+
+optional<std::string>
+get_result_id(const Counters& counters)
+{
+  const auto result = get_result(counters);
+  if (result) {
+    return result->id;
+  }
+  return nullopt;
+}
+
+optional<std::string>
+get_result_message(const Counters& counters)
+{
+  const auto result = get_result(counters);
+  if (result) {
+    return result->message;
+  }
   return nullopt;
 }
 
@@ -274,17 +345,35 @@ zero_all_counters(const Config& config)
 }
 
 std::string
-format_human_readable(const Config& config)
+format_stats_log(const Config& config)
+{
+  std::string result;
+
+  result += FMT("{:36}{}\n", "stats log", config.stats_log());
+
+  return result;
+}
+
+std::string
+format_config_header(const Config& config)
 {
-  Counters counters;
-  time_t last_updated;
-  std::tie(counters, last_updated) = collect_counters(config);
   std::string result;
 
   result += FMT("{:36}{}\n", "cache directory", config.cache_dir());
   result += FMT("{:36}{}\n", "primary config", config.primary_config_path());
   result += FMT(
     "{:36}{}\n", "secondary config (readonly)", config.secondary_config_path());
+
+  return result;
+}
+
+std::string
+format_human_readable(const Counters& counters,
+                      time_t last_updated,
+                      bool from_log)
+{
+  std::string result;
+
   if (last_updated > 0) {
     const auto tm = Util::localtime(last_updated);
     char timestamp[100] = "?";
@@ -306,6 +395,11 @@ format_human_readable(const Config& config)
       continue;
     }
 
+    // don't show cache directory info if reading from a log
+    if (from_log && (k_statistics_fields[i].flags & FLAG_NOSTATSLOG)) {
+      continue;
+    }
+
     const std::string value =
       k_statistics_fields[i].format
         ? k_statistics_fields[i].format(counters.get(statistic))
@@ -320,6 +414,14 @@ format_human_readable(const Config& config)
     }
   }
 
+  return result;
+}
+
+std::string
+format_config_footer(const Config& config)
+{
+  std::string result;
+
   if (config.max_files() != 0) {
     result += FMT("{:32}{:8}\n", "max files", config.max_files());
   }
@@ -332,11 +434,8 @@ format_human_readable(const Config& config)
 }
 
 std::string
-format_machine_readable(const Config& config)
+format_machine_readable(const Counters& counters, time_t last_updated)
 {
-  Counters counters;
-  time_t last_updated;
-  std::tie(counters, last_updated) = collect_counters(config);
   std::string result;
 
   result += FMT("stats_updated_timestamp\t{}\n", last_updated);
index 34a99824c90cff2766d6a8cea22db30a78a52978..75bd2fd8f1e17f257f09de97ab197d6104e48de5 100644 (file)
@@ -26,6 +26,7 @@
 #include "third_party/nonstd/optional.hpp"
 
 #include <functional>
+#include <sstream>
 #include <string>
 
 class Config;
@@ -35,24 +36,51 @@ namespace Statistics {
 // Read counters from `path`. No lock is acquired.
 Counters read(const std::string& path);
 
+// Read counters from lines of text in `path`.
+Counters read_log(const std::string& path);
+
 // Acquire a lock, read counters from `path`, call `function` with the counters,
 // write the counters to `path` and release the lock. Returns the resulting
 // counters or nullopt on error (e.g. if the lock could not be acquired).
 nonstd::optional<Counters> update(const std::string& path,
                                   std::function<void(Counters& counters)>);
 
+// Write input and result to the file in `path`.
+void log_result(const std::string& path,
+                const std::string& input,
+                const std::string& result);
+
 // Return a human-readable string representing the final ccache result, or
 // nullopt if there was no result.
-nonstd::optional<std::string> get_result(const Counters& counters);
+nonstd::optional<std::string> get_result_message(const Counters& counters);
+
+// Return a machine-readable string representing the final ccache result, or
+// nullopt if there was no result.
+nonstd::optional<std::string> get_result_id(const Counters& counters);
 
 // Zero all statistics counters except those tracking cache size and number of
 // files in the cache.
 void zero_all_counters(const Config& config);
 
+// Collect cache statistics from all statistics counters.
+std::pair<Counters, time_t> collect_counters(const Config& config);
+
+// Format stats log in human-readable format.
+std::string format_stats_log(const Config& config);
+
+// Format config header in human-readable format.
+std::string format_config_header(const Config& config);
+
 // Format cache statistics in human-readable format.
-std::string format_human_readable(const Config& config);
+std::string format_human_readable(const Counters& counters,
+                                  time_t last_updated,
+                                  bool from_log);
+
+// Format config footer in human-readable format.
+std::string format_config_footer(const Config& config);
 
 // Format cache statistics in machine-readable format.
-std::string format_machine_readable(const Config& config);
+std::string format_machine_readable(const Counters& counters,
+                                    time_t last_updated);
 
 } // namespace Statistics
index 87e4f94e7cae04ad187a3d9de95862534637be87..5b1db3b43807962e8f550dace79d678fe77c0830 100644 (file)
@@ -129,6 +129,8 @@ Common options:
     -x, --show-compression     show compression statistics
     -p, --show-config          show current configuration options in
                                human-readable format
+        --show-log-stats       print statistics counters from the stats log
+                               in human-readable format
     -s, --show-stats           show summary of configuration and statistics
                                counters in human-readable format
     -z, --zero-stats           zero statistics counters
@@ -2209,12 +2211,20 @@ finalize_stats_and_trigger_cleanup(Context& ctx)
   }
 
   if (!config.log_file().empty() || config.debug()) {
-    const auto result = Statistics::get_result(ctx.counter_updates);
+    const auto result = Statistics::get_result_message(ctx.counter_updates);
     if (result) {
       LOG("Result: {}", *result);
     }
   }
 
+  if (!config.stats_log().empty()) {
+    const auto result_id = Statistics::get_result_id(ctx.counter_updates);
+    if (result_id) {
+      Statistics::log_result(
+        config.stats_log(), ctx.args_info.input_file, *result_id);
+    }
+  }
+
   if (!config.stats()) {
     return;
   }
@@ -2597,6 +2607,7 @@ handle_main_options(int argc, const char* const* argv)
     EXTRACT_RESULT,
     HASH_FILE,
     PRINT_STATS,
+    SHOW_LOG_STATS,
   };
   static const struct option options[] = {
     {"checksum-file", required_argument, nullptr, CHECKSUM_FILE},
@@ -2618,6 +2629,7 @@ handle_main_options(int argc, const char* const* argv)
     {"set-config", required_argument, nullptr, 'o'},
     {"show-compression", no_argument, nullptr, 'x'},
     {"show-config", no_argument, nullptr, 'p'},
+    {"show-log-stats", no_argument, nullptr, SHOW_LOG_STATS},
     {"show-stats", no_argument, nullptr, 's'},
     {"version", no_argument, nullptr, 'V'},
     {"zero-stats", no_argument, nullptr, 'z'},
@@ -2695,9 +2707,15 @@ handle_main_options(int argc, const char* const* argv)
       break;
     }
 
-    case PRINT_STATS:
-      PRINT_RAW(stdout, Statistics::format_machine_readable(ctx.config));
+    case PRINT_STATS: {
+      Counters counters;
+      time_t last_updated;
+      std::tie(counters, last_updated) =
+        Statistics::collect_counters(ctx.config);
+      PRINT_RAW(stdout,
+                Statistics::format_machine_readable(counters, last_updated));
       break;
+    }
 
     case 'c': // --cleanup
     {
@@ -2775,9 +2793,30 @@ handle_main_options(int argc, const char* const* argv)
       ctx.config.visit_items(configuration_printer);
       break;
 
-    case 's': // --show-stats
-      PRINT_RAW(stdout, Statistics::format_human_readable(ctx.config));
+    case SHOW_LOG_STATS: {
+      if (ctx.config.stats_log().empty()) {
+        throw Fatal("No stats log has been configured");
+      }
+      PRINT_RAW(stdout, Statistics::format_stats_log(ctx.config));
+      Counters counters = Statistics::read_log(ctx.config.stats_log());
+      auto st = Stat::stat(ctx.config.stats_log(), Stat::OnError::log);
+      PRINT_RAW(stdout,
+                Statistics::format_human_readable(counters, st.mtime(), true));
       break;
+    }
+
+    case 's': { // --show-stats
+      PRINT_RAW(stdout, Statistics::format_config_header(ctx.config));
+      Counters counters;
+      time_t last_updated;
+      std::tie(counters, last_updated) =
+        Statistics::collect_counters(ctx.config);
+      PRINT_RAW(
+        stdout,
+        Statistics::format_human_readable(counters, last_updated, false));
+      PRINT_RAW(stdout, Statistics::format_config_footer(ctx.config));
+      break;
+    }
 
     case 'V': // --version
       PRINT(VERSION_TEXT, CCACHE_NAME, CCACHE_VERSION);
index e509c9cee9932ac551afd08bf3da50ed554866a4..b0523356ad2bfc87a0dadb92b37385d077027b28 100644 (file)
@@ -405,6 +405,7 @@ TEST_CASE("Config::visit_items")
     " file_stat_matches, file_stat_matches_ctime, pch_defines, system_headers,"
     " clang_index_store, ivfsoverlay\n"
     "stats = false\n"
+    "stats_log = sl\n"
     "temporary_dir = td\n"
     "umask = 022\n");
 
@@ -462,6 +463,7 @@ TEST_CASE("Config::visit_items")
     " time_macros, pch_defines, file_stat_matches, file_stat_matches_ctime,"
     " system_headers, clang_index_store, ivfsoverlay",
     "(test.conf) stats = false",
+    "(test.conf) stats_log = sl",
     "(test.conf) temporary_dir = td",
     "(test.conf) umask = 022",
   };
index 0e647fb2e43818eefaf8555df5d1a482bfb34f00..5d10966d78b2d176ac5617ba2edd2b9865dc36cb 100644 (file)
@@ -80,6 +80,17 @@ TEST_CASE("Read future counters")
   }
 }
 
+TEST_CASE("Read log")
+{
+  TestContext test_context;
+
+  Util::write_file("stats.log", "# comment\ndirect_cache_hit\n");
+  Counters counters = Statistics::read_log("stats.log");
+
+  CHECK(counters.get(Statistic::direct_cache_hit) == 1);
+  CHECK(counters.get(Statistic::cache_miss) == 0);
+}
+
 TEST_CASE("Update")
 {
   TestContext test_context;
@@ -100,4 +111,32 @@ TEST_CASE("Update")
   CHECK(counters->get(Statistic::cache_miss) == 33);
 }
 
+TEST_CASE("Get result")
+{
+  TestContext test_context;
+
+  auto counters = Statistics::update(
+    "test", [](Counters& cs) { cs.increment(Statistic::cache_miss, 1); });
+  REQUIRE(counters);
+
+  auto result = Statistics::get_result_message(*counters);
+  REQUIRE(result);
+}
+
+TEST_CASE("Log result")
+{
+  TestContext test_context;
+
+  auto counters = Statistics::update(
+    "test", [](Counters& cs) { cs.increment(Statistic::cache_miss, 1); });
+  REQUIRE(counters);
+
+  auto result_id = Statistics::get_result_id(*counters);
+  REQUIRE(result_id);
+  Statistics::log_result("stats.log", "test.c", *result_id);
+
+  auto statslog = Util::read_file("stats.log");
+  REQUIRE(statslog.find(*result_id + "\n") != std::string::npos);
+}
+
 TEST_SUITE_END();