From: Anders Björklund Date: Tue, 15 Jun 2021 19:21:35 +0000 (+0200) Subject: Add stats log file, logging input file and result (#854) X-Git-Tag: v4.4~202 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=fe22a1de5149dfb2a1e8188ba1eb6d9eec8dc283;p=thirdparty%2Fccache.git Add stats log file, logging input file and result (#854) --- diff --git a/doc/MANUAL.adoc b/doc/MANUAL.adoc index 3c8243931..2856d68dd 100644 --- a/doc/MANUAL.adoc +++ b/doc/MANUAL.adoc @@ -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 <>. + *`-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 diff --git a/src/Config.cpp b/src/Config.cpp index 9e7092360..06e35cabf 100644 --- a/src/Config.cpp +++ b/src/Config.cpp @@ -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 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 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; diff --git a/src/Config.hpp b/src/Config.hpp index eb574dc8c..1fd560cea 100644 --- a/src/Config.hpp +++ b/src/Config.hpp @@ -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::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 { diff --git a/src/Statistics.cpp b/src/Statistics.cpp index 08ad8928c..ba98a76c1 100644 --- a/src/Statistics.cpp +++ b/src/Statistics.cpp @@ -20,15 +20,21 @@ #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 +#include + +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 -collect_counters(const Config& config) +std::pair +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 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 update(const std::string& path, std::function function) @@ -244,14 +281,48 @@ update(const std::string& path, return counters; } -optional +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 +get_result_id(const Counters& counters) +{ + const auto result = get_result(counters); + if (result) { + return result->id; + } + return nullopt; +} + +optional +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); diff --git a/src/Statistics.hpp b/src/Statistics.hpp index 34a99824c..75bd2fd8f 100644 --- a/src/Statistics.hpp +++ b/src/Statistics.hpp @@ -26,6 +26,7 @@ #include "third_party/nonstd/optional.hpp" #include +#include #include 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 update(const std::string& path, std::function); +// 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 get_result(const Counters& counters); +nonstd::optional 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 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 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 diff --git a/src/ccache.cpp b/src/ccache.cpp index 87e4f94e7..5b1db3b43 100644 --- a/src/ccache.cpp +++ b/src/ccache.cpp @@ -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); diff --git a/unittest/test_Config.cpp b/unittest/test_Config.cpp index e509c9cee..b0523356a 100644 --- a/unittest/test_Config.cpp +++ b/unittest/test_Config.cpp @@ -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", }; diff --git a/unittest/test_Statistics.cpp b/unittest/test_Statistics.cpp index 0e647fb2e..5d10966d7 100644 --- a/unittest/test_Statistics.cpp +++ b/unittest/test_Statistics.cpp @@ -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();