Skip to content

Commit

Permalink
Introduce per-thread times to console and json reporters
Browse files Browse the repository at this point in the history 
See #1834 for detailed description of why this is useful.
  • Loading branch information
@dmah42
dmah42 committed Aug 7, 2024
1 parent b884717 commit 3053d1b
Show file tree
Hide file tree
Showing 7 changed files with 104 additions and 53 deletions.
24 changes: 15 additions & 9 deletions src/console_reporter.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -59,9 +59,9 @@ bool ConsoleReporter::ReportContext(const Context& context) {

BENCHMARK_EXPORT
void ConsoleReporter::PrintHeader(const Run& run) {
std::string str =
FormatString("%-*s %13s %15s %12s", static_cast<int>(name_field_width_),
"Benchmark", "Time", "CPU", "Iterations");
std::string str = FormatString(
"%-*s %13s %15s %15s %12s", static_cast<int>(name_field_width_),
"Benchmark", "Time", "Per-Thread Time", "CPU", "Iterations");
if (!run.counters.empty()) {
if (output_options_ & OO_Tabular) {
for (auto const& c : run.counters) {
Expand Down Expand Up @@ -151,26 +151,32 @@ void ConsoleReporter::PrintRunData(const Run& result) {
}

const double real_time = result.GetAdjustedRealTime();
const double per_thread_real_time =
real_time * static_cast<double>(result.threads);
const double cpu_time = result.GetAdjustedCPUTime();
const std::string real_time_str = FormatTime(real_time);
const std::string per_thread_real_time_str = FormatTime(per_thread_real_time);
const std::string cpu_time_str = FormatTime(cpu_time);

if (result.report_big_o) {
std::string big_o = GetBigOString(result.complexity);
printer(Out, COLOR_YELLOW, "%10.2f %-4s %10.2f %-4s ", real_time,
big_o.c_str(), cpu_time, big_o.c_str());
printer(Out, COLOR_YELLOW, "%10.2f %-4s %10.2f %-4s %10.2f %-4s ",
real_time, big_o.c_str(), per_thread_real_time, big_o.c_str(),
cpu_time, big_o.c_str());
} else if (result.report_rms) {
printer(Out, COLOR_YELLOW, "%10.0f %-4s %10.0f %-4s ", real_time * 100, "%",
printer(Out, COLOR_YELLOW, "%10.0f %-4s %10.0f %-4s %10.0f %-4s ",
real_time * 100, "%", per_thread_real_time * 100, "%",
cpu_time * 100, "%");
} else if (result.run_type != Run::RT_Aggregate ||
result.aggregate_unit == StatisticUnit::kTime) {
const char* timeLabel = GetTimeUnitString(result.time_unit);
printer(Out, COLOR_YELLOW, "%s %-4s %s %-4s ", real_time_str.c_str(),
printer(Out, COLOR_YELLOW, "%s %-4s %s %-4s %s %-4s ",
real_time_str.c_str(), timeLabel, per_thread_real_time_str.c_str(),
timeLabel, cpu_time_str.c_str(), timeLabel);
} else {
assert(result.aggregate_unit == StatisticUnit::kPercentage);
printer(Out, COLOR_YELLOW, "%10.2f %-4s %10.2f %-4s ",
(100. * result.real_accumulated_time), "%",
printer(Out, COLOR_YELLOW, "%10.2f %-4s %10s %-4s %10.2f %-4s ",
(100. * result.real_accumulated_time), "%", " ", " ",
(100. * result.cpu_accumulated_time), "%");
}

Expand Down
14 changes: 14 additions & 0 deletions src/json_reporter.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -274,11 +274,25 @@ void JSONReporter::PrintRunData(Run const& run) {
run.aggregate_unit == StatisticUnit::kTime) {
out << indent << FormatKV("real_time", run.GetAdjustedRealTime())
<< ",\n";
if (run.threads != 1) {
out << indent
<< FormatKV(
"per_thread_real_time",
run.GetAdjustedRealTime() * static_cast<double>(run.threads))
<< ",\n";
}
out << indent << FormatKV("cpu_time", run.GetAdjustedCPUTime());
} else {
assert(run.aggregate_unit == StatisticUnit::kPercentage);
out << indent << FormatKV("real_time", run.real_accumulated_time)
<< ",\n";
if (run.threads != 1) {
out << indent
<< FormatKV(
"per_thread_real_time",
run.real_accumulated_time * static_cast<double>(run.threads))

This comment has been minimized.

Sign in to view

Copy link
@oontvoo

oontvoo Aug 12, 2024

Member

Sorry, I'm confused - should this be division? (total accumulated time divided by the number of threads?)

This comment has been minimized.

Sign in to view

Copy link
@LebedevRI

LebedevRI Aug 12, 2024

Collaborator

(Note that this commit is outdated and does not represent the current state of the PR)

No, because real_accumulated_time was already divided by run.threads,
this just reverts that.
<< ",\n";
}
out << indent << FormatKV("cpu_time", run.cpu_accumulated_time);
}
out << ",\n"
Expand Down
4 changes: 2 additions & 2 deletions test/complexity_test.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,9 +25,9 @@ int AddComplexityTest(const std::string &test_name,
{"%rms", "[ ]*[0-9]+ %"}});
AddCases(
TC_ConsoleOut,
{{"^%bigo_name %bigo_str %bigo_str[ ]*$"},
{{"^%bigo_name %bigo_str %bigo_str %bigo_str[ ]*$"},
{"^%bigo_name", MR_Not}, // Assert we we didn't only matched a name.
{"^%rms_name %rms %rms[ ]*$", MR_Next}});
{"^%rms_name %rms %rms %rms[ ]*$", MR_Next}});
AddCases(
TC_JSONOut,
{{"\"name\": \"%bigo_name\",$"},
Expand Down
14 changes: 7 additions & 7 deletions test/output_test_helper.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,14 +50,14 @@ SubMap& GetSubstitutions() {
{"%int", "[ ]*[0-9]+"},
{" %s ", "[ ]+"},
{"%time", "[ ]*" + time_re + "[ ]+ns"},
{"%console_report", "[ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns [ ]*[0-9]+"},
{"%console_report", "[ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns [ ]*[0-9]+"},
{"%console_percentage_report", "[ ]*" + percentage_re + "[ ]+% [ ]*" + percentage_re + "[ ]+% [ ]*[0-9]+"},
{"%console_us_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*[0-9]+"},
{"%console_ms_report", "[ ]*" + time_re + "[ ]+ms [ ]*" + time_re + "[ ]+ms [ ]*[0-9]+"},
{"%console_s_report", "[ ]*" + time_re + "[ ]+s [ ]*" + time_re + "[ ]+s [ ]*[0-9]+"},
{"%console_time_only_report", "[ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns"},
{"%console_us_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*[0-9]+"},
{"%console_us_time_only_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us"},
{"%console_us_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*[0-9]+"},
{"%console_ms_report", "[ ]*" + time_re + "[ ]+ms [ ]*" + time_re + "[ ]+ms [ ]*" + time_re + "[ ]+ms [ ]*[0-9]+"},
{"%console_s_report", "[ ]*" + time_re + "[ ]+s [ ]*" + time_re + "[ ]+s [ ]*" + time_re + "[ ]+s [ ]*[0-9]+"},
{"%console_time_only_report", "[ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns"},
{"%console_us_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*[0-9]+"},
{"%console_us_time_only_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us"},
{"%csv_header",
"name,iterations,real_time,cpu_time,time_unit,bytes_per_second,"
"items_per_second,label,error_occurred,error_message"},
Expand Down
56 changes: 31 additions & 25 deletions test/reporter_output_test.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@
// ========================================================================= //

ADD_CASES(TC_ConsoleOut, {{"^[-]+$", MR_Next},
{"^Benchmark %s Time %s CPU %s Iterations$", MR_Next},
{"^Benchmark %s Time %s Per-Thread Time %s CPU %s Iterations$", MR_Next},
{"^[-]+$", MR_Next}});
static int AddContextCases() {
AddCases(TC_ConsoleErr,
Expand Down Expand Up @@ -417,8 +417,8 @@ void BM_Complexity_O1(benchmark::State& state) {
BENCHMARK(BM_Complexity_O1)->Range(1, 1 << 18)->Complexity(benchmark::o1);
SET_SUBSTITUTIONS({{"%bigOStr", "[ ]* %float \\([0-9]+\\)"},
{"%RMS", "[ ]*[0-9]+ %"}});
ADD_CASES(TC_ConsoleOut, {{"^BM_Complexity_O1_BigO %bigOStr %bigOStr[ ]*$"},
{"^BM_Complexity_O1_RMS %RMS %RMS[ ]*$"}});
ADD_CASES(TC_ConsoleOut, {{"^BM_Complexity_O1_BigO %bigOStr %bigOStr %bigOStr[ ]*$"},
{"^BM_Complexity_O1_RMS %RMS %RMS %RMS[ ]*$"}});

// ========================================================================= //
// ----------------------- Testing Aggregate Output ------------------------ //
Expand All @@ -436,7 +436,8 @@ ADD_CASES(TC_ConsoleOut,
{"^BM_Repeat/repeats:2 %console_report$"},
{"^BM_Repeat/repeats:2_mean %console_time_only_report [ ]*2$"},
{"^BM_Repeat/repeats:2_median %console_time_only_report [ ]*2$"},
{"^BM_Repeat/repeats:2_stddev %console_time_only_report [ ]*2$"}});
{"^BM_Repeat/repeats:2_stddev %console_time_only_report [ ]*2$"},
{"^BM_Repeat/repeats:2_cv %console_percentage_report[ ]*$"}});
ADD_CASES(TC_JSONOut, {{"\"name\": \"BM_Repeat/repeats:2\",$"},
{"\"family_index\": 15,$", MR_Next},
{"\"per_family_instance_index\": 0,$", MR_Next},
Expand Down Expand Up @@ -496,7 +497,8 @@ ADD_CASES(TC_ConsoleOut,
{"^BM_Repeat/repeats:3 %console_report$"},
{"^BM_Repeat/repeats:3_mean %console_time_only_report [ ]*3$"},
{"^BM_Repeat/repeats:3_median %console_time_only_report [ ]*3$"},
{"^BM_Repeat/repeats:3_stddev %console_time_only_report [ ]*3$"}});
{"^BM_Repeat/repeats:3_stddev %console_time_only_report [ ]*3$"},
{"^BM_Repeat/repeats:3_cv %console_percentage_report[ ]*$"}});
ADD_CASES(TC_JSONOut, {{"\"name\": \"BM_Repeat/repeats:3\",$"},
{"\"family_index\": 16,$", MR_Next},
{"\"per_family_instance_index\": 0,$", MR_Next},
Expand Down Expand Up @@ -566,7 +568,8 @@ ADD_CASES(TC_ConsoleOut,
{"^BM_Repeat/repeats:4 %console_report$"},
{"^BM_Repeat/repeats:4_mean %console_time_only_report [ ]*4$"},
{"^BM_Repeat/repeats:4_median %console_time_only_report [ ]*4$"},
{"^BM_Repeat/repeats:4_stddev %console_time_only_report [ ]*4$"}});
{"^BM_Repeat/repeats:4_stddev %console_time_only_report [ ]*4$"},
{"^BM_Repeat/repeats:4_cv %console_percentage_report[ ]*$"}});
ADD_CASES(TC_JSONOut, {{"\"name\": \"BM_Repeat/repeats:4\",$"},
{"\"family_index\": 17,$", MR_Next},
{"\"per_family_instance_index\": 0,$", MR_Next},
Expand Down Expand Up @@ -666,7 +669,8 @@ ADD_CASES(
{{".*BM_SummaryRepeat/repeats:3 ", MR_Not},
{"^BM_SummaryRepeat/repeats:3_mean %console_time_only_report [ ]*3$"},
{"^BM_SummaryRepeat/repeats:3_median %console_time_only_report [ ]*3$"},
{"^BM_SummaryRepeat/repeats:3_stddev %console_time_only_report [ ]*3$"}});
{"^BM_SummaryRepeat/repeats:3_stddev %console_time_only_report [ ]*3$"},
{"^BM_SummaryRepeat/repeats:3_cv %console_percentage_report[ ]*$"}});
ADD_CASES(TC_JSONOut,
{{".*BM_SummaryRepeat/repeats:3 ", MR_Not},
{"\"name\": \"BM_SummaryRepeat/repeats:3_mean\",$"},
Expand Down Expand Up @@ -717,7 +721,8 @@ ADD_CASES(
{{".*BM_SummaryDisplay/repeats:2 ", MR_Not},
{"^BM_SummaryDisplay/repeats:2_mean %console_time_only_report [ ]*2$"},
{"^BM_SummaryDisplay/repeats:2_median %console_time_only_report [ ]*2$"},
{"^BM_SummaryDisplay/repeats:2_stddev %console_time_only_report [ ]*2$"}});
{"^BM_SummaryDisplay/repeats:2_stddev %console_time_only_report [ ]*2$"},
{"^BM_SummaryDisplay/repeats:2_cv %console_percentage_report[ ]*$"}});
ADD_CASES(TC_JSONOut,
{{".*BM_SummaryDisplay/repeats:2 ", MR_Not},
{"\"name\": \"BM_SummaryDisplay/repeats:2_mean\",$"},
Expand Down Expand Up @@ -772,7 +777,8 @@ ADD_CASES(
{"^BM_RepeatTimeUnit/repeats:3_median %console_us_time_only_report [ "
"]*3$"},
{"^BM_RepeatTimeUnit/repeats:3_stddev %console_us_time_only_report [ "
"]*3$"}});
"]*3$"},
{"^BM_RepeatTimeUnit/repeats:3_cv %console_percentage_report[ ]*$"}});
ADD_CASES(TC_JSONOut,
{{".*BM_RepeatTimeUnit/repeats:3 ", MR_Not},
{"\"name\": \"BM_RepeatTimeUnit/repeats:3_mean\",$"},
Expand Down Expand Up @@ -837,19 +843,19 @@ BENCHMARK(BM_UserStats)
// check that user-provided stats is calculated, and is after the default-ones
// empty string as name is intentional, it would sort before anything else
ADD_CASES(TC_ConsoleOut, {{"^BM_UserStats/iterations:5/repeats:3/manual_time [ "
"]* 150 ns %time [ ]*5$"},
"]*150 ns [ ]*150 ns [ ]*%time [ ]*5$"},
{"^BM_UserStats/iterations:5/repeats:3/manual_time [ "
"]* 150 ns %time [ ]*5$"},
"]*150 ns [ ]*150 ns %time [ ]*5$"},
{"^BM_UserStats/iterations:5/repeats:3/manual_time [ "
"]* 150 ns %time [ ]*5$"},
"]*150 ns [ ]*150 ns %time [ ]*5$"},
{"^BM_UserStats/iterations:5/repeats:3/"
"manual_time_mean [ ]* 150 ns %time [ ]*3$"},
"manual_time_mean [ ]*150 ns [ ]*150 ns %time [ ]*3$"},
{"^BM_UserStats/iterations:5/repeats:3/"
"manual_time_median [ ]* 150 ns %time [ ]*3$"},
"manual_time_median [ ]*150 ns [ ]*150 ns %time [ ]*3$"},
{"^BM_UserStats/iterations:5/repeats:3/"
"manual_time_stddev [ ]* 0.000 ns %time [ ]*3$"},
{"^BM_UserStats/iterations:5/repeats:3/manual_time_ "
"[ ]* 150 ns %time [ ]*3$"}});
"manual_time_stddev [ ]*0.000 ns [ ]*0.000 ns %time [ ]*3$"},
{"^BM_UserStats/iterations:5/repeats:3/manual_time_cv "
"%console_percentage_report[ ]*$"}});
ADD_CASES(
TC_JSONOut,
{{"\"name\": \"BM_UserStats/iterations:5/repeats:3/manual_time\",$"},
Expand Down Expand Up @@ -971,19 +977,19 @@ BENCHMARK(BM_UserPercentStats)
// anything else
ADD_CASES(TC_ConsoleOut,
{{"^BM_UserPercentStats/iterations:5/repeats:3/manual_time [ "
"]* 150 ns %time [ ]*5$"},
"]*150 ns [ ]*150 ns [ ]*%time [ ]*5$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/manual_time [ "
"]* 150 ns %time [ ]*5$"},
"]* 150 ns [ ]*150 ns [ ]*%time [ ]*5$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/manual_time [ "
"]* 150 ns %time [ ]*5$"},
"]* 150 ns [ ]*150 ns [ ]*%time [ ]*5$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/"
"manual_time_mean [ ]* 150 ns %time [ ]*3$"},
"manual_time_mean [ ]* 150 ns [ ]*150 ns [ ]*%time [ ]*3$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/"
"manual_time_median [ ]* 150 ns %time [ ]*3$"},
"manual_time_median [ ]* 150 ns [ ]*150 ns [ ]*%time [ ]*3$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/"
"manual_time_stddev [ ]* 0.000 ns %time [ ]*3$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/manual_time_ "
"[ ]* 1.00 % [ ]* 1.00 %[ ]*3$"}});
"manual_time_stddev [ ]* 0.000 ns [ ]*0.000 ns [ ]*%time [ ]*3$"},
{"^BM_UserPercentStats/iterations:5/repeats:3/manual_time_cv "
"%console_percentage_report[ ]*$"}});
ADD_CASES(
TC_JSONOut,
{{"\"name\": \"BM_UserPercentStats/iterations:5/repeats:3/manual_time\",$"},
Expand Down
Loading

0 comments on commit 3053d1b

Please sign in to comment.