Add elapsed time report for unit test runner:

When unit tests are complete, the longest running tests if any are logged.

src/beast/beast/unit_test/reporter.h

@@ -25,179 +25,307 @@
 #include <beast/streams/abstract_ostream.h>
 #include <beast/streams/basic_std_ostream.h>
 #include <boost/optional.hpp>
+#include <algorithm>
+#include <chrono>
 #include <functional>
+#include <iomanip>
 #include <iostream>
+#include <sstream>
+#include <string>
+#include <utility>
 
 namespace beast {
 namespace unit_test {
 
+namespace detail {
+
 /** A simple test runner that writes everything to a stream in real time.
     The totals are output when the object is destroyed.
 */
+template <class = void>
 class reporter : public runner
 {
 private:
+    using clock_type = std::chrono::steady_clock;
+
     struct case_results
     {
         std::string name;
-        std::size_t total;
+        std::size_t total = 0;
-        std::size_t failed;
+        std::size_t failed = 0;
 
-        case_results (std::string const& name_ = "")
+        case_results (std::string const& name_ = "");
-            : name (name_)
-            , total (0)
-            , failed (0)
-        {
-        }
     };
 
     struct suite_results
     {
         std::string name;
-        std::size_t cases;
+        std::size_t cases = 0;
-        std::size_t total;
+        std::size_t total = 0;
-        std::size_t failed;
+        std::size_t failed = 0;
+        typename clock_type::time_point start =
+            clock_type::now();
 
         explicit
-        suite_results (std::string const& name_ = "")
+        suite_results (std::string const& name_ = "");
-            : name (name_)
-            , cases (0)
-            , total (0)
-            , failed (0)
-        {
-        }
 
         void
-        add (case_results const& r)
+        add (case_results const& r);
-        {
-            ++cases;
-            total += r.total;
-            failed += r.failed;
-        }
     };
 
     struct results
     {
-        std::size_t suites;
+        using run_time = std::pair<std::string,
-        std::size_t cases;
+            typename clock_type::duration>;
-        std::size_t total;
-        std::size_t failed;
 
-        results()
+        enum
-            : suites (0)
-            , cases (0)
-            , total (0)
-            , failed (0)
         {
-        }
+            max_top = 10
-
-        void
-        add (suite_results const& r)
-        {
-            ++suites;
-            total += r.total;
-            cases += r.cases;
-            failed += r.failed;
-        }
         };
 
-    boost::optional <std_ostream> m_std_ostream;
+        std::size_t suites = 0;
-    std::reference_wrapper <abstract_ostream> m_stream;
+        std::size_t cases = 0;
-    results m_results;
+        std::size_t total = 0;
-    suite_results m_suite;
+        std::size_t failed = 0;
-    case_results m_case;
+        std::vector<run_time> top;
+        typename clock_type::time_point start =
+            clock_type::now();
+
+        void
+        add (suite_results const& r);
+    };
+
+    boost::optional <std_ostream> std_ostream_;
+    std::reference_wrapper <abstract_ostream> stream_;
+    results results_;
+    suite_results suite_results_;
+    case_results case_results_;
 
 public:
     reporter (reporter const&) = delete;
     reporter& operator= (reporter const&) = delete;
 
-    explicit reporter (std::ostream& stream = std::cout)
+    ~reporter();
-        : m_std_ostream (std::ref (stream))
-        , m_stream (*m_std_ostream)
-    {
-    }
-
-    ~reporter()
-    {
-        m_stream.get() <<
-            amount (m_results.suites, "suite") << ", " <<
-            amount (m_results.cases, "case") << ", " <<
-            amount (m_results.total, "test") << " total, " <<
-            amount (m_results.failed, "failure")
-            ;
-    }
 
     explicit
-    reporter (abstract_ostream& stream)
+    reporter (std::ostream& stream = std::cout);
-        : m_stream (stream)
+
-    {
+    explicit
-    }
+    reporter (abstract_ostream& stream);
 
 private:
-    virtual
+    static
-    void
+    std::string
-    on_suite_begin (suite_info const& info) override
+    fmtdur (typename clock_type::duration const& d);
-    {
-        m_suite = suite_results (info.full_name());
-    }
 
     virtual
     void
-    on_suite_end() override
+    on_suite_begin (suite_info const& info) override;
-    {
-        m_results.add (m_suite);
-    }
 
     virtual
     void
-    on_case_begin (std::string const& name) override
+    on_suite_end() override;
-    {
-        m_case = case_results (name);
-
-        m_stream.get() <<
-            m_suite.name <<
-            (m_case.name.empty() ?
-                "" : (" " + m_case.name))
-        ;
-    }
 
     virtual
     void
-    on_case_end() override
+    on_case_begin (std::string const& name) override;
-    {
-        m_suite.add (m_case);
-    }
 
     virtual
     void
-    on_pass() override
+    on_case_end() override;
-    {
-        ++m_case.total;
-    }
 
     virtual
     void
-    on_fail (std::string const& reason) override
+    on_pass() override;
-    {
-        ++m_case.failed;
-        ++m_case.total;
-
-        m_stream.get() <<
-            "#" << m_case.total <<
-            " failed" <<
-            (reason.empty() ? "" : ": ") << reason
-            ;
-    }
 
     virtual
     void
-    on_log (std::string const& s) override
+    on_fail (std::string const& reason) override;
-    {
+
-        m_stream.get() <<
+    virtual
-            s;
+    void
-    }
+    on_log (std::string const& s) override;
 };
 
+//------------------------------------------------------------------------------
+
+template <class _>
+reporter<_>::case_results::case_results (
+        std::string const& name_)
+    : name (name_)
+{
+}
+
+template <class _>
+reporter<_>::suite_results::suite_results (
+        std::string const& name_)
+    : name (name_)
+{
+}
+
+template <class _>
+void
+reporter<_>::suite_results::add (case_results const& r)
+{
+    ++cases;
+    total += r.total;
+    failed += r.failed;
+}
+
+template <class _>
+void
+reporter<_>::results::add (
+    suite_results const& r)
+{
+    ++suites;
+    total += r.total;
+    cases += r.cases;
+    failed += r.failed;
+
+    auto const elapsed =
+        clock_type::now() - r.start;
+    if (elapsed >= std::chrono::seconds(1))
+    {
+        auto const iter = std::lower_bound(top.begin(),
+            top.end(), elapsed,
+            [](run_time const& t1,
+                typename clock_type::duration const& t2)
+            {
+                return t1.second > t2;
+            });
+        if (iter != top.end())
+        {
+            if (top.size() == max_top)
+                top.resize(top.size() - 1);
+            top.emplace(iter, r.name, elapsed);
+        }
+        else if (top.size() < max_top)
+        {
+            top.emplace_back(r.name, elapsed);
+        }
+    }
+}
+
+//------------------------------------------------------------------------------
+
+template <class _>
+reporter<_>::reporter (
+        std::ostream& stream)
+    : std_ostream_ (std::ref (stream))
+    , stream_ (*std_ostream_)
+{
+}
+
+template <class _>
+reporter<_>::~reporter()
+{
+    if (results_.top.size() > 0)
+    {
+        stream_.get() << "Longest suite times:";
+        for (auto const& i : results_.top)
+            stream_.get() << std::setw(8) <<
+                fmtdur(i.second) << " " << i.first;
+    }
+    auto const elapsed =
+        clock_type::now() - results_.start;
+    stream_.get() <<
+        fmtdur(elapsed) << ", " <<
+        amount (results_.suites, "suite") << ", " <<
+        amount (results_.cases, "case") << ", " <<
+        amount (results_.total, "test") << " total, " <<
+        amount (results_.failed, "failure");
+}
+
+template <class _>
+reporter<_>::reporter (
+        abstract_ostream& stream)
+    : stream_ (stream)
+{
+}
+
+template <class _>
+std::string
+reporter<_>::fmtdur (
+    typename clock_type::duration const& d)
+{
+    using namespace std::chrono;
+    auto const ms =
+        duration_cast<milliseconds>(d);
+    if (ms < seconds(1))
+        return std::to_string(ms.count()) + "ms";
+    std::stringstream ss;
+    ss << std::fixed << std::setprecision(1) <<
+        (ms.count()/1000.) << "s";
+    return ss.str();
+}
+
+template <class _>
+void
+reporter<_>::on_suite_begin (
+    suite_info const& info)
+{
+    suite_results_ = suite_results (info.full_name());
+}
+
+template <class _>
+void
+reporter<_>::on_suite_end()
+{
+    results_.add (suite_results_);
+}
+
+template <class _>
+void
+reporter<_>::on_case_begin (
+    std::string const& name)
+{
+    case_results_ = case_results (name);
+
+    stream_.get() <<
+        suite_results_.name <<
+        (case_results_.name.empty() ?
+            "" : (" " + case_results_.name));
+}
+
+template <class _>
+void
+reporter<_>::on_case_end()
+{
+    suite_results_.add (case_results_);
+}
+
+template <class _>
+void
+reporter<_>::on_pass()
+{
+    ++case_results_.total;
+}
+
+template <class _>
+void
+reporter<_>::on_fail (
+    std::string const& reason)
+{
+    ++case_results_.failed;
+    ++case_results_.total;
+    stream_.get() <<
+        "#" << case_results_.total <<
+        " failed" <<
+        (reason.empty() ? "" : ": ") << reason;
+}
+
+template <class _>
+void
+reporter<_>::on_log (
+    std::string const& s)
+{
+    stream_.get() << s;
+}
+
+} // detail
+
+using reporter = detail::reporter<>;
+
 } // unit_test
 } // beast
 

src/ripple/rpc/impl/TransactionSign.cpp

@@ -23,7 +23,7 @@
 #include <ripple/json/json_reader.h>
 #include <ripple/protocol/TxFlags.h>
 #include <ripple/rpc/impl/TransactionSign.h>
-#include <beast/unit_test.h>
+#include <beast/unit_test/suite.h>
 
 namespace ripple {
 

src/ripple/rpc/tests/JSONRPC.test.cpp

@@ -23,7 +23,7 @@
 #include <ripple/json/json_reader.h>
 #include <ripple/protocol/TxFlags.h>
 #include <ripple/rpc/impl/TransactionSign.h>
-#include <beast/unit_test.h>
+#include <beast/unit_test/suite.h>
 
 namespace ripple {