Report timing

[MartinDelille]

This PR aims to fix #148 but is still a work in progress.

I just moved the timing computation to progress_bar.h and wanted to know if it looked fine for you?

[codecov-io]

Codecov Report

Merging #150 into master will increase coverage by 0.03%. The diff coverage is 100%.

@@            Coverage Diff             @@
##           master     #150      +/-   ##
==========================================
+ Coverage   98.62%   98.66%   +0.03%     
==========================================
  Files          36       36              
  Lines         948      975      +27     
==========================================
+ Hits          935      962      +27     
  Misses         13       13

Impacted Files	Coverage Δ
bandit/controller.h	97.05% <100%> (+0.12%)	:arrow_up:
bandit/reporters/progress_base.h	100% <100%> (ø)	:arrow_up:
bandit/reporters/xunit.h	100% <100%> (ø)	:arrow_up:
bandit/reporters/info.h	100% <100%> (ø)	:arrow_up:
bandit/runner.h	90.9% <100%> (+0.11%)	:arrow_up:
bandit/options.h	97.87% <100%> (+0.04%)	:arrow_up:

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 1708155...505b4eb. Read the comment docs.

[MartinDelille]

@sbeyer I add the --report-timing option (basing myself on the --dry-run option) but it currently doing nothing.

I'm not really sure how to pass this option to the reporter. Through the run_policies? through the controller? directly to the reporter? Through one of the interface?

A design issue is that this option should be default to:

• true for the xunit reporter
• false otherwise

I'm not sure how to handle that.

[sbeyer]

I just moved the timing computation to progress_bar.h and wanted to know if it looked fine for you?

If you would have asked me in advance, I would have said that the timing computation goes to a separate class (separation of concerns), but seeing progress_base.h in its entirety, I think it's okay to have it there. Thank you.

Nitpicking: I prefer the standard commit message format where the first letter is upper-cased (as you did in your second commit) :smile:

I'm not really sure how to pass this option to the reporter. Through the run_policies? through the controller? directly to the reporter? Through one of the interface?

It's interesting how complicated the architecture of bandit is already. :smile: The run policies define "what tests should be run" (and also: "how" since --break-on-failure and --dry-run is handled, but this will change before version 3.0); the controller is the "main" thing where all is plugged together (and it is configurable, e.g., you can say which run policy, formatter, reporter, etc. are plugged together); the reporter manages the way things are presented to the user. "Timing" doesn't really fit in any class of this, but we currently think of it as time measurement is something the reporter does, so you should pass it directly to the constructors of the reporters that can handle this option (in runner.h method use_default_reporters()).

A design issue is that this option should be default to:

* `true` for the `xunit` reporter

* `false` otherwise

That would be a bad design decision. It should always default to false. This will, by default, make the xunit reporter return 0.0 as it has been before commit 8704dc233510abab71f9fd58a846a1b94085ab23.

[MartinDelille]

Thank you for this detailed answer!

If you would have asked me in advance, I would have said that the timing computation goes to a separate class (separation of concerns), but seeing progress_base.h in its entirety, I think it's okay to have it there. Thank you.

You mean by creating a new class like time_base (or any naming you'll find more suitable) that would inherit progress_base and be inherited by colored_base and xunit? If yes I can definitely change that!

Nitpicking: I prefer the standard commit message format where the first letter is upper-cased (as you did in your second commit) 😄

No problem!

"Timing" doesn't really fit in any class of this, but we currently think of it as time measurement is something the reporter does, so you should pass it directly to the constructors of the reporters that can handle this option (in runner.h method use_default_reporters()).

Ok that's what I started was thinking about and I think I found a way to transmit the report_timing parameter.

A design issue is that this option should be default to:

• true for the xunit reporter
• false otherwise

That would be a bad design decision. It should always default to false. This will, by default, make the xunit reporter return 0.0 as it has been before commit 8704dc2.

I was just worrying about all current bandit xunit reporter user will need to add the --report-timing option in the future but if you're fine with this I totally agree that this would be the best design decision.

[MartinDelille]

What do you think of this first implementation?

It currently only show timing per test. No total duration is displayed (which would make sense for dots reporter for example) but that would no be hard to add (and would do it in this PR).

I doesn't handle timing per context which would imply to store context start timing in the stacks.

I need to add test for the xunit reporter.

[MartinDelille]

I'm wondering what is going wrong with this gigantic duration in the failing and errored case because I don't reproduce (I'm using clang).

[sbeyer]

I'm wondering what is going wrong with this gigantic duration in the failing and errored case because I don't reproduce (I'm using clang).

Can you enable the undefined-behavior sanitizer (UBSan) of clang and check again?

[MartinDelille]

Can you enable the undefined-behavior sanitizer (UBSan) of clang and check again?

I'm not very familiar with cmake but I added this to the CMakeLists.txt:

set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -fsanitize=undefined")

The tests pass without error on my mac.

[MartinDelille]

Any idea how to solve this CI issue?

[sbeyer]

Any idea how to solve this CI issue?

Not yet. I just pulled your PR to check with my own setup (g++ 9 with UBSan and ASan activated), and I get "-0.000 seconds" where AppVeyor gets "-6277438562204192487878988888393020692503707483087375482269988814848.000 seconds". Not quite sure what's happening at the moment. Will look later.

[MartinDelille]

Ok I will try to set up a windows machine to try to reproduce the bug.

[sbeyer]

Ok I will try to set up a windows machine to try to reproduce the bug.

As I said, it is also weird with my setup under Linux, so I guess as long as this problem is not solved, there is no need to setup a Windows machine. Here, the debugger says

Breakpoint 1, bandit::reporter::progress_base::update_test_duration (this=0x60d0000002b0)
    at /home/sbeyer/src/banditcpp/bandit/bandit/reporters/progress_base.h:104
104         testcase_duration_ = std::chrono::high_resolution_clock::now() - testcase_start_time_point_;
(gdb) p testcase_duration_ 
$6 = {__r = -1.8325506472120096e-06}

i.e., that the time difference is negative, that's why I get the -0.000 seconds output. I wonder why this happens, and moreover, why this happens reproducible every single time. Some type problem? Using std::chrono::milliseconds (integer type instead of double) did not change anything; and the example on cppreference is just the same, only with auto. I'm puzzled.

[sbeyer]

A heads-up: Although my sanitizers did not notice any uninitialized values, the static analysis by Coverity Scan did (on the master branch in the xunit code). I will check if this is a true positive and if a fix for that might solve our problem here.

[sbeyer]

Okay, I totally don't understand this (edit: even less after using cppinsights), but explicitly calling the default constructor for testcase_duration_ solves the problem on my machine. So, could you try this change?

diff --git a/bandit/reporters/progress_base.h b/bandit/reporters/progress_base.h
index f4b26f3..c3de618 100644
--- a/bandit/reporters/progress_base.h
+++ b/bandit/reporters/progress_base.h
@@ -13,7 +13,8 @@ namespace bandit {
     struct progress_base : public interface {
       progress_base(const detail::failure_formatter_t& formatter)
           : specs_run_(0), specs_succeeded_(0), specs_failed_(0), specs_skipped_(0),
-            failure_formatter_(formatter) {}
+            failure_formatter_(formatter),
+            testcase_start_time_point_(), testcase_duration_(), testsuite_runtime_() {}

       progress_base& operator=(const progress_base&) {
         return *this;

[MartinDelille]

It pass! I don't recall what the problem was exactly but I know that the advantage of using clang compiler is to avoid this kind of annoying problems.

[sbeyer]

I checked again and spotted the bad guy. It is unrelated to your patch. The bad guy is the info reporter: overridden methods do not always call the respective progress_base base method, hence the timing updates are not performed. I will fix this in a separate branch. I will also give you a further review; then you could rebase on top of current master and we can finally merge this fine work. Thank you very much!

[MartinDelille]

Thank you again for the awesome work your doing on this project!

[MartinDelille]

Ok I fixed the problem and rebased as you requested. I sometime keep intermediate commit before merge it helps during development to keep a track on fix, but I'm totally fine with keeping a clean history before merging.

Don't hesitate if you have more feedback!

[sbeyer]

Thank you very much!

[MartinDelille]

It was very instructive to work on this pull request ! Thank you for taking the time to help me merge it !