Skip to content

Commit

Permalink
#Centipede Improve readability of logged per-experiment fuzzing stats
Browse files Browse the repository at this point in the history 
- Stop reporting timestamps in stats comparisons between experiments (as well as in non-experiment runs with --v=1 or higher). Timestamps hadn't been reported historically, and their value is dubious in this context. They were added primarily for .csv file dumping.
- Slightly tweaked the logged stats formatting for better readability. Evident in the updated test.

PiperOrigin-RevId: 589253389
  • Loading branch information
@ussuri @copybara-github
ussuri authored and copybara-github committed Dec 13, 2023
1 parent 006be04 commit 4fb348b
Show file tree
Hide file tree
Showing 3 changed files with 40 additions and 58 deletions.
1 change: 0 additions & 1 deletion centipede/BUILD
View file
Original file line number Diff line number Diff line change
Expand Up @@ -365,7 +365,6 @@ cc_library(
"@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",
],
)
Expand Down
43 changes: 16 additions & 27 deletions centipede/stats.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,6 @@
#include "absl/strings/ascii.h"
#include "absl/strings/str_cat.h"
#include "absl/strings/str_format.h"
#include "absl/time/time.h"
#include "absl/types/span.h"
#include "./centipede/environment.h"
#include "./centipede/logging.h"
Expand Down Expand Up @@ -87,7 +86,12 @@ void StatsReporter::ReportCurrStats() {
// StatsLogger

bool StatsLogger::ShouldReportThisField(const Stats::FieldInfo &field) {
return (field.traits & (TraitBits::kFuzzStat | TraitBits::kTimestamp)) != 0;
// Skip timestamps and rusage stats: the former because timestamps are
// not very useful in these logs (only in CSVs), the latter because rusage is
// (at least currently) measured for the whole process, not per shard or
// experiment, so reporting nearly identical numbers would be useless and
// confusing.
return (field.traits & TraitBits::kFuzzStat) != 0;
}

void StatsLogger::PreAnnounceFields(
Expand All @@ -104,16 +108,9 @@ void StatsLogger::SetCurrField(const Stats::FieldInfo &field_info) {
os_ << curr_field_info_.description << ":\n";
}

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) {
if (!curr_experiment_name_.empty()) os_ << curr_experiment_name_ << ": ";
if (!curr_experiment_name_.empty())
os_ << " " << curr_experiment_name_ << ": ";

// Print the requested aggregate stats as well as the full sorted contents of
// `values`.
Expand All @@ -124,21 +121,13 @@ void StatsLogger::ReportCurrFieldSample(std::vector<uint64_t> &&values) {
const double avg = !values.empty() ? (1.0 * sum / values.size()) : 0;

os_ << std::fixed << std::setprecision(1);
if (curr_field_info_.traits & TraitBits::kTimestamp) {
os_ << "min:\t" << FormatTimestamp(min) << "\t"
<< "max:\t" << FormatTimestamp(max);
} else {
if (curr_field_info_.traits & TraitBits::kMin)
os_ << "min:\t" << min << "\t";
if (curr_field_info_.traits & TraitBits::kMax)
os_ << "max:\t" << max << "\t";
if (curr_field_info_.traits & TraitBits::kAvg)
os_ << "avg:\t" << avg << "\t";

os_ << "--";
for (auto value : values) {
os_ << "\t" << value;
}
if (curr_field_info_.traits & TraitBits::kMin) os_ << "min:\t" << min << "\t";
if (curr_field_info_.traits & TraitBits::kMax) os_ << "max:\t" << max << "\t";
if (curr_field_info_.traits & TraitBits::kAvg) os_ << "avg:\t" << avg << "\t";

os_ << "--";
for (const auto value : values) {
os_ << "\t" << value;
}
os_ << "\n";
}
Expand All @@ -147,7 +136,7 @@ void StatsLogger::ReportFlags(const GroupToFlags &group_to_flags) {
std::stringstream fos;
for (const auto &[group_name, group_flags] : group_to_flags) {
if (!group_name.empty() || !group_flags.empty()) {
fos << group_name << ": " << group_flags << "\n";
fos << " " << group_name << ": " << group_flags << "\n";
}
}
if (fos.tellp() != std::streampos{0}) os_ << "Flags:\n" << fos.rdbuf();
Expand Down
54 changes: 24 additions & 30 deletions centipede/stats_test.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -98,26 +98,23 @@ TEST(Stats, PrintStatsToLog) {
const std::vector<std::string_view> kExpectedLogLines = {
"Current stats:",
"Coverage:",
"Experiment A: min:\t21\tmax:\t63\tavg:\t42.0\t--\t21\t63",
"Experiment B: min:\t42\tmax:\t84\tavg:\t63.0\t--\t42\t84",
" Experiment A: min:\t21\tmax:\t63\tavg:\t42.0\t--\t21\t63",
" Experiment B: min:\t42\tmax:\t84\tavg:\t63.0\t--\t42\t84",
"Number of executions:",
"Experiment A: min:\t12\tmax:\t36\tavg:\t24.0\t--\t12\t36",
"Experiment B: min:\t24\tmax:\t48\tavg:\t36.0\t--\t24\t48",
" Experiment A: min:\t12\tmax:\t36\tavg:\t24.0\t--\t12\t36",
" Experiment B: min:\t24\tmax:\t48\tavg:\t36.0\t--\t24\t48",
"Active corpus size:",
"Experiment A: min:\t101\tmax:\t303\tavg:\t202.0\t--\t101\t303",
"Experiment B: min:\t202\tmax:\t404\tavg:\t303.0\t--\t202\t404",
" Experiment A: min:\t101\tmax:\t303\tavg:\t202.0\t--\t101\t303",
" Experiment B: min:\t202\tmax:\t404\tavg:\t303.0\t--\t202\t404",
"Max element size:",
"Experiment A: min:\t103\tmax:\t309\tavg:\t206.0\t--\t103\t309",
"Experiment B: min:\t206\tmax:\t412\tavg:\t309.0\t--\t206\t412",
" Experiment A: min:\t103\tmax:\t309\tavg:\t206.0\t--\t103\t309",
" Experiment B: min:\t206\tmax:\t412\tavg:\t309.0\t--\t206\t412",
"Avg element size:",
"Experiment A: min:\t104\tmax:\t312\tavg:\t208.0\t--\t104\t312",
"Experiment B: min:\t208\tmax:\t416\tavg:\t312.0\t--\t208\t416",
"Timestamp:",
"Experiment A: min:\t1970-01-01T00:00:00\tmax:\t1970-01-01T00:00:02",
"Experiment B: min:\t1970-01-01T00:00:01\tmax:\t1970-01-01T00:00:03",
" Experiment A: min:\t104\tmax:\t312\tavg:\t208.0\t--\t104\t312",
" Experiment B: min:\t208\tmax:\t416\tavg:\t312.0\t--\t208\t416",
"Flags:",
"Experiment A: AAA",
"Experiment B: BBB",
" Experiment A: AAA",
" Experiment B: BBB",
};

LogCapture log_capture;
Expand All @@ -140,26 +137,23 @@ TEST(Stats, PrintStatsToLog) {
const std::vector<std::string_view> kExpectedLogLines = {
"Current stats:",
"Coverage:",
"Experiment A: min:\t22\tmax:\t64\tavg:\t43.0\t--\t22\t64",
"Experiment B: min:\t43\tmax:\t85\tavg:\t64.0\t--\t43\t85",
" Experiment A: min:\t22\tmax:\t64\tavg:\t43.0\t--\t22\t64",
" Experiment B: min:\t43\tmax:\t85\tavg:\t64.0\t--\t43\t85",
"Number of executions:",
"Experiment A: min:\t13\tmax:\t37\tavg:\t25.0\t--\t13\t37",
"Experiment B: min:\t25\tmax:\t49\tavg:\t37.0\t--\t25\t49",
" Experiment A: min:\t13\tmax:\t37\tavg:\t25.0\t--\t13\t37",
" Experiment B: min:\t25\tmax:\t49\tavg:\t37.0\t--\t25\t49",
"Active corpus size:",
"Experiment A: min:\t102\tmax:\t304\tavg:\t203.0\t--\t102\t304",
"Experiment B: min:\t203\tmax:\t405\tavg:\t304.0\t--\t203\t405",
" Experiment A: min:\t102\tmax:\t304\tavg:\t203.0\t--\t102\t304",
" Experiment B: min:\t203\tmax:\t405\tavg:\t304.0\t--\t203\t405",
"Max element size:",
"Experiment A: min:\t104\tmax:\t310\tavg:\t207.0\t--\t104\t310",
"Experiment B: min:\t207\tmax:\t413\tavg:\t310.0\t--\t207\t413",
" Experiment A: min:\t104\tmax:\t310\tavg:\t207.0\t--\t104\t310",
" Experiment B: min:\t207\tmax:\t413\tavg:\t310.0\t--\t207\t413",
"Avg element size:",
"Experiment A: min:\t105\tmax:\t313\tavg:\t209.0\t--\t105\t313",
"Experiment B: min:\t209\tmax:\t417\tavg:\t313.0\t--\t209\t417",
"Timestamp:",
"Experiment A: min:\t1970-01-01T00:00:01\tmax:\t1970-01-01T00:00:03",
"Experiment B: min:\t1970-01-01T00:00:02\tmax:\t1970-01-01T00:00:04",
" Experiment A: min:\t105\tmax:\t313\tavg:\t209.0\t--\t105\t313",
" Experiment B: min:\t209\tmax:\t417\tavg:\t313.0\t--\t209\t417",
"Flags:",
"Experiment A: AAA",
"Experiment B: BBB",
" Experiment A: AAA",
" Experiment B: BBB",
};

LogCapture log_capture;
Expand Down

0 comments on commit 4fb348b

Please sign in to comment.