Print at least three significant digits for times. #701

EricWF · 2018-10-10T21:11:13Z

Some benchmarks are particularly sensitive and they run in less than
a nanosecond. In order for the console reporter to provide meaningful
output for such benchmarks it needs to be able to display the times
using more resolution than a single nanosecond.

This patch changes the console reporter to print at least three
significant digits for all results.

LebedevRI · 2018-10-10T21:19:03Z

I wonder if it would be good to introduce something like a scientific notation "time unit" (i.e. autodetect each time)

AppVeyorBot · 2018-10-10T21:25:28Z

❌ Build benchmark 1514 failed (commit e2e04fa150 by @EricWF)

LebedevRI · 2018-10-10T21:32:05Z

src/console_reporter.cc

@@ -98,6 +98,20 @@ static void IgnoreColorPrint(std::ostream& out, LogColor, const char* fmt,
  va_end(args);
 }

+static std::string FormatTime(double time) {
+  // Align decimal places...
+  if (time < 1) {


Nit: 1 is int, time is double.

Ack. Fixed.

LebedevRI · 2018-10-10T21:32:47Z

src/console_reporter.cc

  }

  if (!result.report_big_o && !result.report_rms) {
-    printer(Out, COLOR_CYAN, "%10lld", result.iterations);
+    printer(Out, COLOR_CYAN, "%12lld", result.iterations);


Hm, why change the iteration print format?

To align it with the Iterations header.

LebedevRI · 2018-10-10T21:35:21Z

src/console_reporter.cc

+  if (time < 100) {
+    return FormatString("%12.1f  ", time);
+  }
+  return FormatString("%10.0f    ", time);


Have you considered letting the format string figure out the necessary padding at least?
(see man 3 vsprintf)

Could you clarify a bit?

The reason for the current implementation of FormatString is to ensure columns with the same place value align. For example.

Benchmark Time CPU Iterations ---------------------------------------------------------------------------------------------------- BM_empty 0.572 ns 0.572 ns 1000000000 BM_empty/threads:72 0.021 ns 1.50 ns 958819032 BM_spin_empty/8 7.47 ns 7.47 ns 180868971 BM_spin_empty/512 954 ns 953 ns 1466617 BM_spin_empty/8192 15449 ns 15447 ns 90954 BM_spin_empty/8/threads:72 0.258 ns 18.2 ns 72560520 BM_spin_empty/512/threads:72 22.2 ns 1564 ns 872568 BM_spin_empty/8192/threads:72 382 ns 26233 ns 38664

I'm not too familiar with printf specifiers, but if there is a tool I can use to do that, please let me know.

I'll double-check if this can be achieved with the format specifiers,
but that new extra width looks worrying :(
I don't think we can do anything about it though; i like this in general.

Yeah, I don't love the extra width either. But being able to see sub-nanosecond results is worth the hit I think.

coveralls · 2018-10-11T01:19:07Z

Coverage increased (+0.06%) to 89.347% when pulling 9ba6c8e on efcs:print-more-precision into b171791 on google:master.

AppVeyorBot · 2018-10-11T02:07:05Z

✅ Build benchmark 1515 completed (commit a310dd0e40 by @EricWF)

LebedevRI · 2018-10-11T14:36:48Z

I like this, but that padding/alignment is really bothering me :/

How important is it to do that alignment of . separator? Can it be avoided?

EricWF · 2018-10-11T16:00:58Z

How important is it to do that alignment of . separator? Can it be avoided?

I think it's pretty important. It's allows you to understand the magnitude of a benchmark by glancing.

What's you're objection exactly? To readability? Do you think the space between the value and ns is ugly?

LebedevRI · 2018-10-11T16:39:26Z

How important is it to do that alignment of . separator? Can it be avoided?

I think it's pretty important.

It's allows you to understand the magnitude of a benchmark by glancing.

True.

What's you're objection exactly? To readability? Do you think the space between the value and ns is ugly?

Readability is good; but yes, i don't like that wasted space, and the yet-increased width of the user-counter-less line.

EricWF · 2018-10-11T17:14:20Z

How important is it to do that alignment of . separator? Can it be avoided?

I think it's pretty important.

It's allows you to understand the magnitude of a benchmark by glancing.

True.

What's you're objection exactly? To readability? Do you think the space between the value and ns is ugly?

Readability is good; but yes, i don't like that wasted space, and the yet-increased width of the user-counter-less line.

Arguabbly the space isn't "wasted", since I think we agree it has value in representing magnitude. Otherwise we would just remove it. But it's not ideal either.

I can get rid of a little width (4 characters) if we don't care about making BigO calculations aligned with everything else, but that's ugly and doesn't help much.

Do you think this issue should block the revision?

LebedevRI · 2018-10-11T17:21:40Z

Do you think this issue should block the revision?

There are two things here as far as i can see:

Always print at least 3 significant digits
Align/pad .

I like 1., but i'm not quite sure about 2. yet.
So i guess i'll defer to @dominichamon.

EricWF · 2018-10-11T17:28:53Z

A couple of alternative solutions:

Add a flag to change the alignment to always be right aligned to the unit, which should waste less space. But IMO getting the old behavior back isn't worth the cost of another flag.
Use the "wasted space" explicitly so it seems "less wasted". That is, fill the wasted space with three trailing decimal digits for all outputs. I don't like this either because those digits aren't significant and make it harder to see the information that is.
Just right align everything all the time. This means it's a lot harder for the user to determine the magnitude of a benchmark, and ever harder yet to compare two benchmarks next to each other.

LebedevRI · 2018-10-11T17:41:51Z

A couple of alternative solutions:

Add a flag to change the alignment to always be right aligned to the unit, which should waste less space. But IMO getting the old behavior back isn't worth the cost of another flag.

I agree, a flag for this does not sound good.

Use the "wasted space" explicitly so it seems "less wasted". That is, fill the wasted space with three trailing decimal digits for all outputs. I don't like this either because those digits aren't significant and make it harder to see the information that is.

And what is even worse, those 'zeros' are likely straight-up a lie.

Just right align everything all the time. This means it's a lot harder for the user to determine the magnitude of a benchmark, and ever harder yet to compare two benchmarks next to each other.

I would personally go with 3., but it is also possible that i'm simply too picky here.
(Though it is undeniable that the new layout is more width-consuming.)

As i said, i'll defer to @dominichamon..

LebedevRI · 2018-10-11T17:48:25Z

(Though it is undeniable that the new layout is more width-consuming.)

(I.e. if one day i/someone else "finishes" support for custom timers, and a new time column can be arbitrarily added, the width will be in short supply)

dmah42 · 2018-10-15T09:15:38Z

What's wrong with always printing 3 decimal places instead of 3 significant digits, and not having the check for < 100?

LebedevRI · 2018-10-15T09:32:24Z

If the time is 52321 ms, does one care if it is 52321.000 ms or 52321.444 ms ?
I'd think that goes against the reason for setting the time units in the first place..

dmah42 · 2018-10-15T09:47:15Z

oh you updated that from .666 so i wouldn't complain about rounding :P

I think we're hitting newer use cases as this project gets broader adoption. In general, the library was expected to be used to run benchmarks with similar timescales, so you'd get ns or ms all the way down. If we're not seeing that then we need to think a bit about how to handle it.

One option is to pick a base time scale for the entire run and use that everywhere. I'm not sure that's a great idea, but it would at least make eyeballing the runs easy. When you mix timescales you need to take care that, say, 10ms and 100ns are not being mixed up by the reader.

High-level answer: I'm not a fan of the extra whitespace between the numbers and the units.

LebedevRI · 2018-10-15T09:53:32Z

oh you updated that from .666 so i wouldn't complain about rounding :P

:P

High-level answer: I'm not a fan of the extra whitespace between the numbers and the units.

Any opinion on simply not having those whitespaces, will that also be confusing?

dmah42 · 2018-10-15T09:55:24Z

I think it would be. You'd have

100 ns
100 us

or worse

100 ns
 10 us

and would have to take care if you're comparing by eye. Perhaps we should have something like: one time scale per benchmark family?

LebedevRI · 2018-10-15T09:56:56Z

That is not what i meant. I was literally talking about the current code, but without that padding with spaces.
I.e.

...
100 ms
0.1 ms
  1 ms
...

dmah42 · 2018-10-15T09:58:23Z

If it doesn't change time unit i think that's ok.

EricWF · 2018-10-21T23:16:45Z

I think we're hitting newer use cases as this project gets broader adoption. In general, the library was expected to be used to run benchmarks with similar timescales, so you'd get ns or ms all the way down. If we're not seeing that then we need to think a bit about how to handle it.

One option is to pick a base time scale for the entire run and use that everywhere. I'm not sure that's a great idea, but it would at least make eyeballing the runs easy. When you mix timescales you need to take care that, say, 10ms and 100ns are not being mixed up by the reader.

Unless the user explicitly changes the time unit for a benchmark, this is the behavior we have today.
So in almost all cases I suspect we won't be mixing up the reader.

That is not what i meant. I was literally talking about the current code, but without that padding with spaces.
I.e.
...
100 ms
0.1 ms
  1 ms
...
If it doesn't change time unit i think that's ok.

I personally find the other format easier to read at a glance. Especially as numbers are flying by which is often the case.

EricWF · 2018-10-21T23:20:57Z

Test... I'm having trouble posting.

Some benchmarks are particularly sensitive and they run in less than a nanosecond. In order for the console reporter to provide meaningful output for such benchmarks it needs to be able to display the times using more resolution than a single nanosecond. This patch changes the console reporter to print at least three significant digits for all results. Unlike the initial attempt, this patch does not align the decimal point.

EricWF · 2018-11-21T21:54:34Z

I've updated the patch to no longer align the decimal point as requested.

AppVeyorBot · 2018-11-21T22:49:26Z

✅ Build benchmark 1565 completed (commit 0ca09d3fe9 by @EricWF)

AppVeyorBot · 2018-11-22T00:07:42Z

✅ Build benchmark 1566 completed (commit 5e0cb5180f by @EricWF)

LebedevRI

Can some test be updated to fully show all the spaces?
And/or, could you post a screenshot?

LebedevRI · 2018-11-22T06:06:48Z

src/console_reporter.cc

@@ -98,6 +98,21 @@ static void IgnoreColorPrint(std::ostream& out, LogColor, const char* fmt,
  va_end(args);
 }

+
+static std::string FormatTime(double time) {
+  // Align decimal places...


Comment outdated

LebedevRI · 2018-11-22T06:07:11Z

test/reporter_output_test.cc

@@ -521,7 +521,7 @@ ADD_CASES(TC_ConsoleOut, {{"^BM_UserStats/iterations:5/repeats:3/manual_time [ "
                          {"^BM_UserStats/iterations:5/repeats:3/"
                           "manual_time_median [ ]* 150 ns %time [ ]*3$"},
                          {"^BM_UserStats/iterations:5/repeats:3/"
-                           "manual_time_stddev [ ]* 0 ns %time [ ]*3$"},
+                           "manual_time_stddev [ ]* 0.000 ns %time [ ]*3$"},


Should the zero be treated differently?

dmah42 · 2018-11-22T10:05:51Z

LGTM. I ran it and master and took a diff and it looks much nicer with the extra precision.

LebedevRI

LG in general, i really like this.
It would be great to have better test coverage for this though.

LebedevRI · 2018-11-24T16:09:54Z

src/console_reporter.cc

@@ -53,7 +53,7 @@ bool ConsoleReporter::ReportContext(const Context& context) {
 }

 void ConsoleReporter::PrintHeader(const Run& run) {
-  std::string str = FormatString("%-*s %13s %13s %10s", static_cast<int>(name_field_width_),
+  std::string str = FormatString("%-*s %13s %15s %12s", static_cast<int>(name_field_width_),


I'm not sure, is this still needed now that no alignment happens?

Yes. There was a bug originally where we misaligned the last couple fields of the header when complexity was involved.

googlebot added the cla: yes label Oct 10, 2018

LebedevRI reviewed Oct 10, 2018

View reviewed changes

EricWF requested a review from dmah42 October 11, 2018 15:58

EricWF force-pushed the print-more-precision branch from cc13eea to 9ba6c8e Compare November 21, 2018 21:35

LebedevRI reviewed Nov 22, 2018

View reviewed changes

LebedevRI approved these changes Nov 24, 2018

View reviewed changes

EricWF merged commit 4528c76 into google:master Dec 14, 2018

Print at least three significant digits for times. #701

Print at least three significant digits for times. #701

Conversation

EricWF commented Oct 10, 2018

LebedevRI commented Oct 10, 2018

AppVeyorBot commented Oct 10, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Oct 11, 2018 • edited Loading

AppVeyorBot commented Oct 11, 2018

LebedevRI commented Oct 11, 2018

EricWF commented Oct 11, 2018

LebedevRI commented Oct 11, 2018 • edited Loading

EricWF commented Oct 11, 2018

LebedevRI commented Oct 11, 2018

EricWF commented Oct 11, 2018

LebedevRI commented Oct 11, 2018

LebedevRI commented Oct 11, 2018

dmah42 commented Oct 15, 2018

LebedevRI commented Oct 15, 2018 • edited Loading

dmah42 commented Oct 15, 2018

LebedevRI commented Oct 15, 2018

dmah42 commented Oct 15, 2018

LebedevRI commented Oct 15, 2018 • edited Loading

dmah42 commented Oct 15, 2018

EricWF commented Oct 21, 2018

EricWF commented Oct 21, 2018

EricWF commented Nov 21, 2018

AppVeyorBot commented Nov 21, 2018

AppVeyorBot commented Nov 22, 2018

LebedevRI left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dmah42 commented Nov 22, 2018

LebedevRI left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Oct 11, 2018 •

edited

Loading

LebedevRI commented Oct 11, 2018 •

edited

Loading

LebedevRI commented Oct 15, 2018 •

edited

Loading

LebedevRI commented Oct 15, 2018 •

edited

Loading