#Centipede Fuzzing stats: fix bogus initial timestamps + improve logging
- The stats dumping code used to dump timestamps averaged between the fuzzing threads: with slow targets, dumping sometimes occurred before all the threads got a chance to update their stats, resulting in bogus timestamps. Switched to dumping the timestamp min/max, which seems more useful anyway.
- Also, log timestamps as human-readable formatted times, not UNIX micros.
- Also turned off dumping of the individual timestamp values to LOG: dubious value & log pollution.
PiperOrigin-RevId: 554887117
diff --git a/centipede/BUILD b/centipede/BUILD
index 2fb45e4..c2d39b6 100644
--- a/centipede/BUILD
+++ b/centipede/BUILD
@@ -240,6 +240,7 @@
"@com_google_absl//absl/log:check",
"@com_google_absl//absl/strings",
"@com_google_absl//absl/strings:str_format",
+ "@com_google_absl//absl/time",
"@com_google_absl//absl/types:span",
],
)
@@ -976,6 +977,7 @@
":util",
"@com_google_absl//absl/log:log_sink",
"@com_google_absl//absl/log:log_sink_registry",
+ "@com_google_absl//absl/time",
"@com_google_googletest//:gtest_main",
],
)
diff --git a/centipede/stats.cc b/centipede/stats.cc
index 713aef3..b3217a0 100644
--- a/centipede/stats.cc
+++ b/centipede/stats.cc
@@ -25,6 +25,7 @@
#include "absl/log/check.h"
#include "absl/strings/str_format.h"
#include "absl/strings/substitute.h"
+#include "absl/time/time.h"
#include "absl/types/span.h"
#include "./centipede/environment.h"
#include "./centipede/logging.h"
@@ -85,6 +86,14 @@
curr_field_info_ = field_info;
}
+namespace {
+std::string FormatTimestamp(uint64_t unix_micros) {
+ return absl::FormatTime("%Y-%m-%d%ET%H:%M:%S",
+ absl::FromUnixMicros(unix_micros),
+ absl::LocalTimeZone());
+}
+} // namespace
+
void StatsLogger::ReportCurrFieldSample(std::vector<uint64_t> &&values) {
// Print min/max/avg and the full sorted contents of `values`.
std::sort(values.begin(), values.end());
@@ -94,18 +103,19 @@
static_cast<double>(values.size());
os_ << std::fixed << std::setprecision(1);
switch (curr_field_info_.aggregation) {
- case Stats::Aggregation::kMinMaxAvg:
+ case Stats::Aggregation::kMinMaxAvg: {
os_ << "min:\t" << min << "\t"
<< "max:\t" << max << "\t"
<< "avg:\t" << avg << "\t";
- break;
- case Stats::Aggregation::kRoundedAvg:
- os_ << "avg:\t" << std::llrint(avg) << "\t";
- break;
- }
- os_ << "--";
- for (const auto value : values) {
- os_ << "\t" << value;
+ os_ << "--";
+ for (const auto value : values) {
+ os_ << "\t" << value;
+ }
+ } break;
+ case Stats::Aggregation::kMinMax: {
+ os_ << "min:\t" << FormatTimestamp(min) << "\t"
+ << "max:\t" << FormatTimestamp(max);
+ } break;
}
os_ << "\n";
}
@@ -141,8 +151,8 @@
for (const auto &field : fields) {
std::string col_names;
switch (field.aggregation) {
- case Stats::Aggregation::kRoundedAvg:
- col_names = absl::Substitute("$0_Avg,", field.name);
+ case Stats::Aggregation::kMinMax:
+ col_names = absl::Substitute("$0_Min,$0_Max,", field.name);
break;
case Stats::Aggregation::kMinMaxAvg:
col_names = absl::Substitute("$0_Min,$0_Max,$0_Avg,", field.name);
@@ -185,8 +195,8 @@
if (!values.empty()) avg /= values.size();
std::string values_str;
switch (curr_field_info_.aggregation) {
- case Stats::Aggregation::kRoundedAvg:
- values_str = absl::StrFormat("%" PRIu64 ",", std::llrint(avg));
+ case Stats::Aggregation::kMinMax:
+ values_str = absl::StrFormat("%" PRIu64 ",%" PRIu64 ",", min, max);
break;
case Stats::Aggregation::kMinMaxAvg:
values_str =
diff --git a/centipede/stats.h b/centipede/stats.h
index 28c0a10..a42cd83 100644
--- a/centipede/stats.h
+++ b/centipede/stats.h
@@ -45,7 +45,7 @@
std::atomic<uint64_t> max_corpus_element_size;
std::atomic<uint64_t> avg_corpus_element_size;
- enum class Aggregation { kMinMaxAvg, kRoundedAvg };
+ enum class Aggregation { kMinMaxAvg, kMinMax };
struct FieldInfo {
std::atomic<uint64_t> Stats::*field;
@@ -89,7 +89,7 @@
&Stats::unix_micros,
"UnixMicros",
"Timestamp (UNIX micros)",
- Aggregation::kRoundedAvg,
+ Aggregation::kMinMax,
},
};
};
diff --git a/centipede/stats_test.cc b/centipede/stats_test.cc
index eeaa29a..45fa46e 100644
--- a/centipede/stats_test.cc
+++ b/centipede/stats_test.cc
@@ -14,6 +14,7 @@
#include "./centipede/stats.h"
+#include <cstdint>
#include <filesystem> // NOLINT
#include <sstream>
#include <vector>
@@ -22,6 +23,8 @@
#include "gtest/gtest.h"
#include "absl/log/log_sink.h"
#include "absl/log/log_sink_registry.h"
+#include "absl/time/civil_time.h"
+#include "absl/time/time.h"
#include "./centipede/logging.h"
#include "./centipede/test_util.h"
#include "./centipede/util.h"
@@ -43,6 +46,12 @@
std::stringstream captured_log_;
};
+uint64_t CivilTimeToUnixMicros( //
+ int64_t y, int64_t m, int64_t d, int64_t hh, int64_t mm, int64_t ss) {
+ return absl::ToUnixMicros(absl::FromCivil(
+ absl::CivilSecond{y, m, d, hh, mm, ss}, absl::LocalTimeZone()));
+}
+
} // namespace
TEST(Stats, PrintStatsToLog) {
@@ -59,7 +68,7 @@
for (size_t i = 0; i < 4; ++i) {
auto &stats = stats_vec[i];
- stats.unix_micros = i + 1000000;
+ stats.unix_micros = CivilTimeToUnixMicros(1970, 1, 1, 0, 0, i);
stats.max_corpus_element_size = 2 * i + 1;
stats.avg_corpus_element_size = i + 1;
stats.num_executions = i + 100;
@@ -93,8 +102,8 @@
"Experiment A: min:\t1\tmax:\t3\tavg:\t2.0\t--\t1\t3\n"
"Experiment B: min:\t2\tmax:\t4\tavg:\t3.0\t--\t2\t4\n"
"Timestamp (UNIX micros):\n"
- "Experiment A: avg:\t1000001\t--\t1000000\t1000002\n"
- "Experiment B: avg:\t1000002\t--\t1000001\t1000003\n"
+ "Experiment A: min:\t1970-01-01T00:00:00\tmax:\t1970-01-01T00:00:02\n"
+ "Experiment B: min:\t1970-01-01T00:00:01\tmax:\t1970-01-01T00:00:03\n"
"Flags:\n"
"Experiment A: AAA\n"
"Experiment B: BBB\n";
@@ -160,13 +169,13 @@
workdir / "fuzzing-stats-.000000.ExperimentB.csv",
};
const std::vector<std::string_view> kExpectedCsvContents = {
- R"(NumCoveredPcs_Min,NumCoveredPcs_Max,NumCoveredPcs_Avg,NumExecs_Min,NumExecs_Max,NumExecs_Avg,CorpusSize_Min,CorpusSize_Max,CorpusSize_Avg,MaxEltSize_Min,MaxEltSize_Max,MaxEltSize_Avg,AvgEltSize_Min,AvgEltSize_Max,AvgEltSize_Avg,UnixMicros_Avg,
-10,25,17.5,100,102,101.0,1000,3000,2000.0,1,5,3.0,1,3,2.0,1000001,
-11,26,18.5,101,103,102.0,1001,3001,2001.0,2,6,4.0,2,4,3.0,1000002,
+ R"(NumCoveredPcs_Min,NumCoveredPcs_Max,NumCoveredPcs_Avg,NumExecs_Min,NumExecs_Max,NumExecs_Avg,CorpusSize_Min,CorpusSize_Max,CorpusSize_Avg,MaxEltSize_Min,MaxEltSize_Max,MaxEltSize_Avg,AvgEltSize_Min,AvgEltSize_Max,AvgEltSize_Avg,UnixMicros_Min,UnixMicros_Max,
+10,25,17.5,100,102,101.0,1000,3000,2000.0,1,5,3.0,1,3,2.0,1000000,1000002,
+11,26,18.5,101,103,102.0,1001,3001,2001.0,2,6,4.0,2,4,3.0,1000001,1000003,
)",
- R"(NumCoveredPcs_Min,NumCoveredPcs_Max,NumCoveredPcs_Avg,NumExecs_Min,NumExecs_Max,NumExecs_Avg,CorpusSize_Min,CorpusSize_Max,CorpusSize_Avg,MaxEltSize_Min,MaxEltSize_Max,MaxEltSize_Avg,AvgEltSize_Min,AvgEltSize_Max,AvgEltSize_Avg,UnixMicros_Avg,
-15,40,27.5,101,103,102.0,2000,4000,3000.0,3,7,5.0,2,4,3.0,1000002,
-16,41,28.5,102,104,103.0,2001,4001,3001.0,4,8,6.0,3,5,4.0,1000003,
+ R"(NumCoveredPcs_Min,NumCoveredPcs_Max,NumCoveredPcs_Avg,NumExecs_Min,NumExecs_Max,NumExecs_Avg,CorpusSize_Min,CorpusSize_Max,CorpusSize_Avg,MaxEltSize_Min,MaxEltSize_Max,MaxEltSize_Avg,AvgEltSize_Min,AvgEltSize_Max,AvgEltSize_Avg,UnixMicros_Min,UnixMicros_Max,
+15,40,27.5,101,103,102.0,2000,4000,3000.0,3,7,5.0,2,4,3.0,1000001,1000003,
+16,41,28.5,102,104,103.0,2001,4001,3001.0,4,8,6.0,3,5,4.0,1000002,1000004,
)",
};
