Adds elapsed time to gtest's textual output. Original patch by balazs.dan.

[Zhanyong, 2008-07-16 21:29:10]

Balazs created this patch for this issue:
http://code.google.com/p/googletest/issues/detail?id=6.

I have uploaded the patch to the Rietveld Code Review Tool such that it can be
reviewed before being committed.

[chandlerc, 2008-07-16 21:47:43]

FYI

http://codereview.appspot.com/2574/diff/1/4
File src/gtest.cc (right):

http://codereview.appspot.com/2574/diff/1/4#newcode2358
Line 2358: printf("%s from %s\t%d msec\n\n", counts.c_str(),
test_case_name_.c_str(), test_case->elapsed_time());
80 cols?

[Zhanyong, 2008-07-16 22:42:54]

http://codereview.appspot.com/2574/diff/1/3
File src/gtest-internal-inl.h (right):

http://codereview.appspot.com/2574/diff/1/3#newcode76
Line 76: GTEST_DECLARE_bool(print_time);
Style nit: could you sort the list alphabetically by the flags' names?

I noticed that stack_trace_depth and show_internal_stack_frames are backwards. 
Could you fix it as well?

http://codereview.appspot.com/2574/diff/1/3#newcode88
Line 88: const char kPrintTimeFlag[] = "print_time";
Similarly, sort the list wherever print_time is used.

http://codereview.appspot.com/2574/diff/1/4
File src/gtest.cc (right):

http://codereview.appspot.com/2574/diff/1/4#newcode190
Line 190: print_time,
Sort this?

http://codereview.appspot.com/2574/diff/1/4#newcode2356
Line 2356: ColoredPrintf(COLOR_GREEN, "[----------] ");
We shouldn't affect the current format when --gtest_print_time is not set.  We
prefer its compactness. :)

http://codereview.appspot.com/2574/diff/1/4#newcode2357
Line 2357: if (GTEST_FLAG(print_time)) {
The output looks like this now:

[==========] Running 245 tests from 43 test cases.
[----------] Global test environment set-up.
[----------] 2 tests from NullLiteralTest
[ RUN      ] NullLiteralTest.IsTrueForNullLiterals
[       OK ] NullLiteralTest.IsTrueForNullLiterals      0 msec
[ RUN      ] NullLiteralTest.IsFalseForNonNullLiterals
[       OK ] NullLiteralTest.IsFalseForNonNullLiterals  0 msec
[----------] 2 tests from NullLiteralTest       0 msec

[----------] 6 tests from ToUtf8StringTest
[ RUN      ] ToUtf8StringTest.CanEncodeNul
[       OK ] ToUtf8StringTest.CanEncodeNul      0 msec
[ RUN      ] ToUtf8StringTest.CanEncodeAscii
[       OK ] ToUtf8StringTest.CanEncodeAscii    0 msec
[ RUN      ] ToUtf8StringTest.CanEncode8To11Bits
[       OK ] ToUtf8StringTest.CanEncode8To11Bits        0 msec
[ RUN      ] ToUtf8StringTest.CanEncode12To16Bits
[       OK ] ToUtf8StringTest.CanEncode12To16Bits       0 msec
[ RUN      ] ToUtf8StringTest.CanEncode17To21Bits
[       OK ] ToUtf8StringTest.CanEncode17To21Bits       0 msec
[ RUN      ] ToUtf8StringTest.CanEncodeInvalidCodePoint
[       OK ] ToUtf8StringTest.CanEncodeInvalidCodePoint 0 msec
[----------] 6 tests from ToUtf8StringTest      0 msec

...

[----------] Global test environment tear-down
[==========] 245 tests from 43 test cases ran.  12 msec
[  PASSED  ] 245 tests.

It's hard to find the time info as it's not vertically aligned.
Perhaps something like:

[----------] 2 tests from NullLiteralTest
[ RUN      ] NullLiteralTest.IsTrueForNullLiterals
[     1 ms ] NullLiteralTest.IsTrueForNullLiterals
[ RUN      ] NullLiteralTest.IsFalseForNonNullLiterals
[ 12345 ms ] NullLiteralTest.IsFalseForNonNullLiterals
[ RUN      ] NullLiteralTest.Bar
[  FAILED  ] NullLiteralTest.Bar
[ 14000 ms ] 3 tests from NullLiteralTest

Note:

- When we print the time, we don't have to print OK - the absence of
  FAILED is enough to indicate success.

- When a test fails, we may not need to print the time it takes.
  After all, there's a bigger problem to worry about.  If someone can
  think of a way to print both "FAILED" and the time nicely, that
  would be better though.

Keir, what do you think?

http://codereview.appspot.com/2574/diff/1/4#newcode2358
Line 2358: printf("%s from %s\t%d msec\n\n", counts.c_str(),
test_case_name_.c_str(), test_case->elapsed_time());
What Chandler said.  We format code to fit within 80 columns.

elapsed_time()'s type is not necessarily int.  In fact, it's most likely to be a
64-bit integer.  Therefore you cannot print it using %d. 
internal::StreamableToString(test_case->elapsed_time()).c_str() should work.

http://codereview.appspot.com/2574/diff/1/4#newcode3533
Line 3533: ParseBoolFlag(arg, kPrintTimeFlag, &GTEST_FLAG(print_time))
Remember to sort this list.

http://codereview.appspot.com/2574/diff/1/2
File test/gtest_unittest.cc (right):

http://codereview.appspot.com/2574/diff/1/2#newcode812
Line 812: testing::GTEST_FLAG(print_time) = false;
Sort it.

[Zhanyong, 2008-07-23 22:10:46]

Thanks for addressing the comments thoroughly, Balazs.

In addition to some nits, we also need a test to verify the change of the output
format.  The easiest way is probably to modify gtest_output_test.py to:

1. invoke gtest_output_test_ twice, the second time with flags
"--gtest_print_time --gtest_filter=A.B:A.C:B.D".  The filter is to avoid a large
output - we are not interested in verifying everything again, so a small number
of test cases will be enough.

2. strip the timing info from the output of the second run.

3. concatenate the output from the two runs, and compare it with the golden
file.

http://codereview.appspot.com/2574/diff/6/31
File src/gtest.cc (right):

http://codereview.appspot.com/2574/diff/6/31#newcode2359
Line 2359: printf("%s from %s (%s ms total)\n\n", counts.c_str(),
test_case_name_.c_str(),
Reformat this line to fit within 80 columns.

http://codereview.appspot.com/2574/diff/6/31#newcode2440
Line 2440: if (GTEST_FLAG(print_time)) {
The if- and else- branches have much in common.  Can you merge the duplicated
code?

  printf(...);
  if (GTEST_FLAG(print_time)) {
    printf(...);
  }
  ColoredPrintf(COLOR_GREEN, "\n[  PASSED  ] ");

http://codereview.appspot.com/2574/diff/6/29
File test/gtest_unittest.cc (right):

http://codereview.appspot.com/2574/diff/6/29#newcode3977
Line 3977: "foo.exe",
Style: indentation is off.

http://codereview.appspot.com/2574/diff/6/29#newcode3990
Line 3990: };
Remove one space in the indentation.

http://codereview.appspot.com/2574/diff/6/29#newcode4009
Line 4009: "foo.exe",
The same.

http://codereview.appspot.com/2574/diff/6/29#newcode4011
Line 4011: };
The same.

http://codereview.appspot.com/2574/diff/6/29#newcode4019
Line 4019: "foo.exe",
The same.

[Balazs.Dan, 2008-07-24 02:04:33]

Ok, I will try to modify the gtest_output_test.py, but I'm not an python
expert..

[Balazs.Dan, 2008-07-24 02:05:07]

http://codereview.appspot.com/2574/diff/6/31
File src/gtest.cc (right):

http://codereview.appspot.com/2574/diff/6/31#newcode2440
Line 2440: if (GTEST_FLAG(print_time)) {
This will print the "end of line" in green, thus the output will differ.
However, I can do this:
  printf(...);
  if (GTEST_FLAG(print_time)) {
    printf(...);
  }
  printf("\n");
  ColoredPrintf(COLOR_GREEN, "[  PASSED  ] ");

But, this will decrease the performance and wont be much more compact..

[Vlad, 2008-07-24 02:20:54]

http://codereview.appspot.com/2574/diff/6/31
File src/gtest.cc (right):

http://codereview.appspot.com/2574/diff/6/31#newcode2440
Line 2440: if (GTEST_FLAG(print_time)) {
On 2008/07/24 02:05:07, Balazs.Dan wrote:
> This will print the "end of line" in green, thus the output will differ.
> However, I can do this:
>   printf(...);
>   if (GTEST_FLAG(print_time)) {
>     printf(...);
>   }
>   printf("\n");
>   ColoredPrintf(COLOR_GREEN, "[  PASSED  ] ");
> 
> But, this will decrease the performance and wont be much more compact..

How about this:

string time_printout;
if (GTEST_FLAG(print_time)) {
  time_printout = string(" (") +
      internal::StreamableToString(impl->elapsed_time()) + " ms total)";
}
printf("%s from %s ran.%s\n",
    FormatTestCount(impl->test_to_run_count()).c_str(),
    FormatTestCaseCount(
        impl->test_case_to_run_count()).c_str(),
    time_printout.c_str());