Merge pull request #2578 from opensim-org/stopwatch

chrisdembia · web-flow · commit d76e5d4fbe40 · 2019-10-31T02:25:49.000-07:00
Add class Stopwatch
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -16,6 +16,7 @@ v4.1
 - Reading DataTables from files has been simplified. Reading one table from a file typically uses the Table constructor except when the data-source/file contains multiple tables. (In these cases e.g. C3D files, use C3DFileAdapter.read method, then use functions in C3DFileAdapter to get the individual TimeSeriesTable(s)). Writing tables to files has not changed.
 - Exposed convertMillimeters2Meters() in osimC3D.m. This function converts COP and moment data from mm to m and now must be invoked prior to writing force data to file. Previously, this was automatically performed during writing forces to file. 
 - Methods that operate on SimTK::Vec<n> are now available through Java/Matlab and python bindings to add/subtract/divide/multiply vec<n> contents with a scalar (PR #2558)
+- The new Stopwatch class allows C++ API users to easily measure the runtime of their code.
 
 Converting from v4.0 to v4.1
 ----------------------------
diff --git a/OpenSim/Common/Stopwatch.h b/OpenSim/Common/Stopwatch.h
@@ -0,0 +1,89 @@
+#ifndef OPENSIM_STOPWATCH_H_
+#define OPENSIM_STOPWATCH_H_
+/* -------------------------------------------------------------------------- *
+ *                             OpenSim: Stopwatch.h                           *
+ * -------------------------------------------------------------------------- *
+ * The OpenSim API is a toolkit for musculoskeletal modeling and simulation.  *
+ * See http://opensim.stanford.edu and the NOTICE file for more information.  *
+ * OpenSim is developed at Stanford University and supported by the US        *
+ * National Institutes of Health (U54 GM072970, R24 HD065690) and by DARPA    *
+ * through the Warrior Web program.                                           *
+ *                                                                            *
+ * Copyright (c) 2005-2019 Stanford University and the Authors                *
+ * Author(s): Christopher Dembia                                              *
+ *                                                                            *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may    *
+ * not use this file except in compliance with the License. You may obtain a  *
+ * copy of the License at http://www.apache.org/licenses/LICENSE-2.0.         *
+ *                                                                            *
+ * Unless required by applicable law or agreed to in writing, software        *
+ * distributed under the License is distributed on an "AS IS" BASIS,          *
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.   *
+ * See the License for the specific language governing permissions and        *
+ * limitations under the License.                                             *
+ * -------------------------------------------------------------------------- */
+
+/// Record and report elapsed real time ("clock" or "wall" time) in seconds.
+class Stopwatch {
+public:
+    /// This stores the start time as the current time.
+    Stopwatch() { reset(); }
+    /// Reset the start time to the current time.
+    void reset() { m_startTime = SimTK::realTimeInNs(); }
+    /// Return the amount of time that has elapsed since this object was
+    /// constructed or since reset() has been called.
+    double getElapsedTime() const {
+        return SimTK::realTime() - SimTK::nsToSec(m_startTime);
+    }
+    /// Get elapsed time in nanoseconds. See SimTK::realTimeInNs() for more
+    /// information.
+    long long getElapsedTimeInNs() const {
+        return SimTK::realTimeInNs() - m_startTime;
+    }
+    /// This provides the elapsed time as a formatted string (using format()).
+    std::string getElapsedTimeFormatted() const {
+        return formatNs(getElapsedTimeInNs());
+    }
+    /// Format the provided elapsed time in nanoseconds into a string.
+    /// The time may be converted into seconds, milliseconds, or microseconds.
+    /// Additionally, if the time is greater or equal to 60 seconds, the time in
+    /// hours and/or minutes is also added to the string.
+    /// Usually, you can call getElapsedTimeFormatted() instead of calling this
+    /// function directly. If you call this function directly, use
+    /// getElapsedTimeInNs() to get a time in nanoseconds (rather than
+    /// getElapsedTime()).
+    static std::string formatNs(const long long& nanoseconds) {
+        std::stringstream ss;
+        double seconds = SimTK::nsToSec(nanoseconds);
+        int secRounded = (int)std::round(seconds);
+        if (seconds > 1)
+            ss << secRounded << " second(s)";
+        else if (nanoseconds >= 1000000)
+            ss << nanoseconds / 1000000 << " millisecond(s)";
+        else if (nanoseconds >= 1000)
+            ss << nanoseconds / 1000 << " microsecond(s)";
+        else
+            ss << nanoseconds << " nanosecond(s)";
+        int minutes = secRounded / 60;
+        int hours = minutes / 60;
+        if (minutes || hours) {
+            ss << " (";
+            if (hours) {
+                ss << hours << " hour(s), ";
+                ss << minutes % 60 << " minute(s), ";
+                ss << secRounded % 60 << " second(s)";
+            } else {
+                ss << minutes % 60 << " minute(s), ";
+                ss << secRounded % 60 << " second(s)";
+            }
+            ss << ")";
+        }
+        return ss.str();
+    }
+
+private:
+    long long m_startTime;
+};
+
+
+#endif // OPENSIM_STOPWATCH_H_
diff --git a/OpenSim/Common/Test/testC3DFileAdapter.cpp b/OpenSim/Common/Test/testC3DFileAdapter.cpp
@@ -21,16 +21,17 @@
  * -------------------------------------------------------------------------- */
 
 #include "OpenSim/Common/C3DFileAdapter.h"
-#include "OpenSim/Common/TRCFileAdapter.h"
 #include "OpenSim/Common/STOFileAdapter.h"
-#include <OpenSim/Auxiliary/auxiliaryTestFunctions.h>
-
-#include <vector>
-#include <unordered_map>
-#include <cstdlib>
+#include "OpenSim/Common/TRCFileAdapter.h"
 #include <chrono>
-#include <thread>
 #include <cmath>
+#include <cstdlib>
+#include <thread>
+#include <unordered_map>
+#include <vector>
+
+#include <OpenSim/Auxiliary/auxiliaryTestFunctions.h>
+#include <OpenSim/Common/Stopwatch.h>
 
 template<typename ETY = SimTK::Real>
 void compare_tables(const OpenSim::TimeSeriesTable_<ETY>& table1,
@@ -77,26 +78,25 @@ void test(const std::string filename) {
     using namespace std;
 
     // The walking C3D files included in this test should not take more
-    // than 40ms on most hardware. We make the max time 100ms to account
+    // than 40ms on most hardware. We make the max time 200ms to account
     // for potentially slower CI machines.
-    const double MaximumLoadTimeInMS = 100;
+    const long long MaximumLoadTimeInNs = SimTK::secToNs(0.200);
     
-    std::clock_t startTime = std::clock();
+    Stopwatch watch;
     C3DFileAdapter c3dFileAdapter{};
     auto tables = c3dFileAdapter.read(filename);
-
-    double loadTime = 1.e3*(std::clock() - startTime) / CLOCKS_PER_SEC;
+    long long loadTime = watch.getElapsedTimeInNs();
 
     cout << "\tC3DFileAdapter '" << filename << "' loaded in " 
-        << loadTime << "ms" << endl;
+        << watch.formatNs(loadTime) << endl;
 
 /*  Disabled performance test because Travis CI is consistently unable to
     meet this timing requirement. Consider PR#2221 to address this issue
     longer term.
     #ifdef NDEBUG
-    ASSERT(loadTime < MaximumLoadTimeInMS, __FILE__, __LINE__,
+    ASSERT(loadTime < MaximumLoadTimeInNs, __FILE__, __LINE__,
         "Unable to load '" + filename + "' within " + 
-        to_string(MaximumLoadTimeInMS) + "ms.");
+        to_string(MaximumLoadTimeInNs) + "ns.");
     #endif
 */
 
@@ -117,28 +117,28 @@ void test(const std::string filename) {
     marker_table->updTableMetaData().setValueForKey("Units", 
                                                     std::string{"mm"});
     TRCFileAdapter trc_adapter{};
-    std::clock_t t0 = std::clock();
+    watch.reset();
     trc_adapter.write(*marker_table, marker_file);
     cout << "\tWrote '" << marker_file << "' in "
-        << 1.e3*(std::clock() - t0) / CLOCKS_PER_SEC << "ms" << endl;
+        << watch.getElapsedTimeFormatted() << endl;
 
     ASSERT(force_table->getNumRows() > 0, __FILE__, __LINE__,
         "Failed to read forces data from " + filename);
 
     force_table->updTableMetaData().setValueForKey("Units", 
                                                     std::string{"mm"});
     STOFileAdapter sto_adapter{};
-    t0 = std::clock();
+    watch.reset();
     sto_adapter.write((force_table->flatten()), forces_file);
     cout << "\tWrote'" << forces_file << "' in "
-        << 1.e3*(std::clock() - t0) / CLOCKS_PER_SEC << "ms" << endl;
+        << watch.getElapsedTimeFormatted() << endl;
 
     // Verify that marker data was written out and can be read in
-    t0 = std::clock();
+    watch.reset();
     TimeSeriesTable_<SimTK::Vec3> markers(marker_file);
     TimeSeriesTable_<SimTK::Vec3> std_markers("std_" + marker_file);
     cout << "\tRead'" << marker_file << "' and its standard in "
-        << 1.e3*(std::clock() - t0) / CLOCKS_PER_SEC << "ms" << endl;
+        << watch.getElapsedTimeFormatted() << endl;
 
     // Compare C3DFileAdapter read-in and written marker data
     compare_tables<SimTK::Vec3>(markers, *marker_table);
@@ -161,22 +161,24 @@ void test(const std::string filename) {
 
     cout << "\tForces " << forces_file << " equivalent to standard." << endl;
 
-    t0 = std::clock();
-    // Reread in C3D file with forces resolved to the COP 
+    watch.reset();
+    // Reread in C3D file with forces resolved to the COP
     auto c3dFileAdapter2 = C3DFileAdapter{};
-    c3dFileAdapter2.setLocationForForceExpression(C3DFileAdapter::ForceLocation::CenterOfPressure);
+    c3dFileAdapter2.setLocationForForceExpression(
+            C3DFileAdapter::ForceLocation::CenterOfPressure);
     auto tables2 = c3dFileAdapter2.read(filename);
     
-    loadTime = 1.e3*(std::clock() - t0) / CLOCKS_PER_SEC;
+    loadTime = watch.getElapsedTimeInNs();
     cout << "\tC3DFileAdapter '" << filename << "' read with forces at COP in "
-        << loadTime << "ms" << endl;
+        << watch.formatNs(loadTime) << endl;
     // on ci-biulds will define SKIP_TIMING as it is unpredictably slow on some machines
     #if defined(NDEBUG) && !defined(SKIP_TIMING)
-    ASSERT(loadTime < MaximumLoadTimeInMS, __FILE__, __LINE__,
+    ASSERT(loadTime < MaximumLoadTimeInNs, __FILE__, __LINE__,
         "Unable to load '" + filename + "' within " +
-        to_string(MaximumLoadTimeInMS) + "ms.");
+        to_string(MaximumLoadTimeInNs) + "ns.");
     #endif
-    std::shared_ptr<TimeSeriesTableVec3> force_table_cop = c3dFileAdapter.getForcesTable(tables2);
+    std::shared_ptr<TimeSeriesTableVec3> force_table_cop =
+            c3dFileAdapter.getForcesTable(tables2);
     downsample_table(*force_table_cop, 100);
 
     sto_adapter.write(force_table_cop->flatten(), "cop_"+ forces_file);
@@ -189,29 +191,11 @@ void test(const std::string filename) {
                                 SimTK::SqrtEps);
 
     cout << "\tcop_" << forces_file << " is equivalent to its standard."<< endl;
-
-    cout << "\ttestC3DFileAdapter '" << filename << "' completed in "
-        << 1.e3*(std::clock() - startTime) / CLOCKS_PER_SEC  << "ms" << endl;
-
 }
 
 int main() {
-    std::vector<std::string> filenames{};
-    filenames.push_back("walking2.c3d");
-    filenames.push_back("walking5.c3d");
-
-    for(const auto& filename : filenames) {
-        std::cout << "\nTest reading '" + filename + "'." << std::endl;
-        try {
-            test(filename);
-        }
-        catch (const std::exception& ex) {
-            std::cout << "testC3DFileAdapter FAILED: " << ex.what() << std::endl;
-            return 1;
-        }
-    }
-
-    std::cout << "\nAll testC3DFileAdapter cases passed." << std::endl;
-
-    return 0;
+    SimTK_START_TEST("testC3DFileAdapter");
+        SimTK_SUBTEST1(test, "walking2.c3d");
+        SimTK_SUBTEST1(test, "walking5.c3d");
+    SimTK_END_TEST();
 }
diff --git a/OpenSim/Common/osimCommon.h b/OpenSim/Common/osimCommon.h
@@ -33,6 +33,8 @@
 #include "GCVSpline.h"
 #include "IO.h"
 
+#include "Stopwatch.h"
+
 #include "Scale.h"
 #include "SimmSpline.h"
 #include "Constant.h"
diff --git a/OpenSim/Tools/InverseDynamicsTool.cpp b/OpenSim/Tools/InverseDynamicsTool.cpp
@@ -25,13 +25,15 @@
 // INCLUDES
 //=============================================================================
 #include "InverseDynamicsTool.h"
-#include <OpenSim/Simulation/Model/Model.h>
-#include <OpenSim/Simulation/InverseDynamicsSolver.h>
-#include <OpenSim/Common/XMLDocument.h>
-#include <OpenSim/Common/IO.h>
-#include <OpenSim/Common/FunctionSet.h> 
-#include <OpenSim/Common/GCVSplineSet.h>
+
 #include <OpenSim/Common/Constant.h>
+#include <OpenSim/Common/FunctionSet.h>
+#include <OpenSim/Common/GCVSplineSet.h>
+#include <OpenSim/Common/IO.h>
+#include <OpenSim/Common/Stopwatch.h>
+#include <OpenSim/Common/XMLDocument.h>
+#include <OpenSim/Simulation/InverseDynamicsSolver.h>
+#include <OpenSim/Simulation/Model/Model.h>
 
 using namespace OpenSim;
 using namespace std;
@@ -319,7 +321,7 @@ bool InverseDynamicsTool::run()
         // create the solver given the input data
         InverseDynamicsSolver ivdSolver(*_model);
 
-        const clock_t start = clock();
+        Stopwatch watch;
 
         int nt = final_index-start_index+1;
         
@@ -337,7 +339,7 @@ bool InverseDynamicsTool::run()
         success = true;
 
         cout << "InverseDynamicsTool: " << nt << " time frames in " 
-            << (double)(clock()-start)/CLOCKS_PER_SEC << "s\n" <<endl;
+            << watch.getElapsedTimeFormatted() << "\n" <<endl;
     
         JointSet jointsForEquivalentBodyForces;
         getJointsByName(*_model, _jointsForReportingBodyForces, jointsForEquivalentBodyForces);
diff --git a/OpenSim/Tools/InverseKinematicsTool.cpp b/OpenSim/Tools/InverseKinematicsTool.cpp
@@ -24,22 +24,21 @@
 // INCLUDES
 //=============================================================================
 #include "InverseKinematicsTool.h"
-#include <OpenSim/Simulation/Model/Model.h>
-#include <OpenSim/Simulation/InverseKinematicsSolver.h>
-
-#include <OpenSim/Common/IO.h>
-#include <OpenSim/Common/Storage.h>
-#include <OpenSim/Common/FunctionSet.h>
-#include <OpenSim/Common/GCVSplineSet.h>
-#include <OpenSim/Common/Constant.h>
-#include <OpenSim/Common/XMLDocument.h>
-
-#include <OpenSim/Analyses/Kinematics.h>
 
-#include "IKTaskSet.h"
 #include "IKCoordinateTask.h"
 #include "IKMarkerTask.h"
+#include "IKTaskSet.h"
 
+#include <OpenSim/Analyses/Kinematics.h>
+#include <OpenSim/Common/Constant.h>
+#include <OpenSim/Common/FunctionSet.h>
+#include <OpenSim/Common/GCVSplineSet.h>
+#include <OpenSim/Common/IO.h>
+#include <OpenSim/Common/Stopwatch.h>
+#include <OpenSim/Common/Storage.h>
+#include <OpenSim/Common/XMLDocument.h>
+#include <OpenSim/Simulation/InverseKinematicsSolver.h>
+#include <OpenSim/Simulation/Model/Model.h>
 
 using namespace OpenSim;
 using namespace std;
@@ -358,7 +357,7 @@ bool InverseKinematicsTool::run()
         Storage *modelMarkerErrors = _reportErrors ? 
             new Storage(Nframes, "ModelMarkerErrors") : nullptr;
 
-        const clock_t start = clock();
+        Stopwatch watch;
 
         for (int i = start_ix; i <= final_ix; ++i) {
             s.updTime() = times[i];
@@ -460,7 +459,7 @@ bool InverseKinematicsTool::run()
         success = true;
 
         cout << "InverseKinematicsTool completed " << Nframes << " frames in "
-            <<(double)(clock()-start)/CLOCKS_PER_SEC << "s\n" <<endl;
+            << watch.getElapsedTimeFormatted() << "\n" <<endl;
     }
     catch (const std::exception& ex) {
         std::cout << "InverseKinematicsTool Failed: " << ex.what() << std::endl;
