From e4d304f9344d9223cf49ac5ea7c88899f9316ea2 Mon Sep 17 00:00:00 2001 From: Ladislav Michl Date: Sun, 21 Jan 2024 19:00:57 +0100 Subject: [PATCH] Base: Implement TimeElapsed Some instances of TimeInfo serve the sole purpose of measuring time duration. Using system time is unfortunate as it returns wall clock, which is not guaranteed to be monotonic. Replace such a usage with the new TimeElapsed class based on steady clock. --- src/Base/TimeInfo.h | 34 ++++++++++++++++++++ src/Gui/DAGView/DAGModel.cpp | 4 +-- src/Mod/Fem/App/FemMesh.cpp | 26 ++++++++------- src/Mod/Fem/App/FemVTKTools.cpp | 21 ++++++------ src/Mod/Fem/Gui/ViewProviderFemMesh.cpp | 20 ++++++------ src/Mod/Fem/Gui/ViewProviderFemMeshPyImp.cpp | 6 ++-- src/Mod/Part/Gui/TaskCheckGeometry.cpp | 4 +-- src/Mod/Part/Gui/ViewProviderExt.cpp | 4 +-- src/Mod/Sketcher/App/Sketch.cpp | 14 ++++---- src/Mod/Sketcher/App/planegcs/GCS.cpp | 12 +++---- 10 files changed, 93 insertions(+), 52 deletions(-) diff --git a/src/Base/TimeInfo.h b/src/Base/TimeInfo.h index b8cf9c90f6..433fb7c764 100644 --- a/src/Base/TimeInfo.h +++ b/src/Base/TimeInfo.h @@ -94,6 +94,40 @@ public: } }; // class TimeInfo +using Ticks = std::chrono::steady_clock; + +class TimeElapsed: public std::chrono::time_point +{ +public: + TimeElapsed() + { + setCurrent(); + } + + TimeElapsed(const TimeElapsed&) = default; + TimeElapsed(TimeElapsed&&) = default; + ~TimeElapsed() = default; + + void setCurrent() + { + static_cast&>(*this) = Ticks::now(); + } + + static float diffTimeF(const TimeElapsed& start, const TimeElapsed& end = TimeElapsed()) + { + const std::chrono::duration duration = end - start; + return duration.count(); + } + + static std::string diffTime(const TimeElapsed& start, const TimeElapsed& end = TimeElapsed()) + { + std::stringstream ss; + const std::chrono::duration secs = end - start; + ss << secs.count(); + return ss.str(); + } +}; // class TimeElapsed + } // namespace Base #endif // BASE_TIMEINFO_H diff --git a/src/Gui/DAGView/DAGModel.cpp b/src/Gui/DAGView/DAGModel.cpp index 5b9833924d..b005fc4453 100644 --- a/src/Gui/DAGView/DAGModel.cpp +++ b/src/Gui/DAGView/DAGModel.cpp @@ -460,7 +460,7 @@ void Model::updateSlot() //for speed. Not doing yet, as I want a simple algorithm until //a more complete picture is formed. - Base::TimeInfo startTime; + Base::TimeElapsed startTime; //here we will cycle through the graph updating edges. //we have to do this first and in isolation because everything is dependent on an up to date graph. @@ -761,7 +761,7 @@ void Model::updateSlot() //Modeling_Challenge_Casting_ta4 with 59 features: "Initialize DAG View time: 0.007" //keeping algo simple with extra loops only added 0.002 to above number. -// std::cout << "Initialize DAG View time: " << Base::TimeInfo::diffTimeF(startTime, Base::TimeInfo()) << std::endl; +// std::cout << "Initialize DAG View time: " << Base::TimeElapsed::diffTimeF(startTime, Base::TimeElapsed()) << std::endl; // outputGraphviz(*theGraph, "./graphviz.dot"); graphDirty = false; diff --git a/src/Mod/Fem/App/FemMesh.cpp b/src/Mod/Fem/App/FemMesh.cpp index 008412acb3..8ab5d1eb1a 100644 --- a/src/Mod/Fem/App/FemMesh.cpp +++ b/src/Mod/Fem/App/FemMesh.cpp @@ -1621,7 +1621,7 @@ class CHEXA2Element: public NastranElement void FemMesh::readNastran(const std::string& Filename) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: FemMesh::readNastran() =================================\n"); _Mtrx = Base::Matrix4D(); @@ -1699,7 +1699,7 @@ void FemMesh::readNastran(const std::string& Filename) inputfile.close(); Base::Console().Log(" %f: File read, start building mesh\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // Now fill the SMESH datastructure SMESHDS_Mesh* meshds = this->myMesh->GetMeshDS(); @@ -1709,12 +1709,13 @@ void FemMesh::readNastran(const std::string& Filename) it->addToMesh(meshds); } - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } void FemMesh::readNastran95(const std::string& Filename) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: FemMesh::readNastran95() =================================\n"); _Mtrx = Base::Matrix4D(); @@ -1825,7 +1826,7 @@ void FemMesh::readNastran95(const std::string& Filename) inputfile.close(); Base::Console().Log(" %f: File read, start building mesh\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // Now fill the SMESH datastructure SMESHDS_Mesh* meshds = this->myMesh->GetMeshDS(); @@ -1839,12 +1840,13 @@ void FemMesh::readNastran95(const std::string& Filename) it->addToMesh(meshds); } - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } void FemMesh::readAbaqus(const std::string& FileName) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: FemMesh::readAbaqus() =================================\n"); /* @@ -1878,12 +1880,13 @@ void FemMesh::readAbaqus(const std::string& FileName) catch (Py::Exception& e) { e.clear(); } - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } void FemMesh::readZ88(const std::string& FileName) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: FemMesh::readZ88() =================================\n"); /* @@ -1917,7 +1920,8 @@ void FemMesh::readZ88(const std::string& FileName) catch (Py::Exception& e) { e.clear(); } - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } void FemMesh::read(const char* FileName) @@ -2416,7 +2420,7 @@ void FemMesh::writeABAQUS(const std::string& Filename, int elemParam, bool group void FemMesh::writeZ88(const std::string& FileName) const { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: FemMesh::writeZ88() =================================\n"); /* diff --git a/src/Mod/Fem/App/FemVTKTools.cpp b/src/Mod/Fem/App/FemVTKTools.cpp index 0a3b42de86..ac88e59518 100644 --- a/src/Mod/Fem/App/FemVTKTools.cpp +++ b/src/Mod/Fem/App/FemVTKTools.cpp @@ -267,7 +267,7 @@ void FemVTKTools::importVTKMesh(vtkSmartPointer dataset, FemMesh* me FemMesh* FemVTKTools::readVTKMesh(const char* filename, FemMesh* mesh) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: read FemMesh from VTK unstructuredGrid ======================\n"); Base::FileInfo f(filename); @@ -301,7 +301,8 @@ FemMesh* FemVTKTools::readVTKMesh(const char* filename, FemMesh* mesh) } // Mesh should link to the part feature, in order to set up FemConstraint - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); return mesh; } @@ -543,7 +544,7 @@ void FemVTKTools::exportVTKMesh(const FemMesh* mesh, void FemVTKTools::writeVTKMesh(const char* filename, const FemMesh* mesh) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: write FemMesh from VTK unstructuredGrid ======================\n"); Base::FileInfo f(filename); @@ -561,7 +562,8 @@ void FemVTKTools::writeVTKMesh(const char* filename, const FemMesh* mesh) Base::Console().Error("file name extension is not supported to write VTK\n"); } - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } @@ -611,7 +613,7 @@ App::DocumentObject* createObjectByType(const Base::Type type) App::DocumentObject* FemVTKTools::readResult(const char* filename, App::DocumentObject* res) { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log( "Start: read FemResult with FemMesh from VTK file ======================\n"); Base::FileInfo f(filename); @@ -667,7 +669,8 @@ App::DocumentObject* FemVTKTools::readResult(const char* filename, App::Document } pcDoc->recompute(); - Base::Console().Log(" %f: Done \n", Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::Console().Log(" %f: Done \n", + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); Base::Console().Log("End: read FemResult with FemMesh from VTK file ======================\n"); return result; @@ -689,7 +692,7 @@ void FemVTKTools::writeResult(const char* filename, const App::DocumentObject* r return; } - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log("Start: write FemResult to VTK unstructuredGrid dataset =======\n"); Base::FileInfo f(filename); @@ -702,7 +705,7 @@ void FemVTKTools::writeResult(const char* filename, const App::DocumentObject* r FemVTKTools::exportVTKMesh(&fmesh, grid); Base::Console().Log(" %f: vtk mesh builder finished\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // result FemVTKTools::exportFreeCADResult(res, grid); @@ -719,7 +722,7 @@ void FemVTKTools::writeResult(const char* filename, const App::DocumentObject* r } Base::Console().Log(" %f: writing result object to vtk finished\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); Base::Console().Log("End: write FemResult to VTK unstructuredGrid dataset =======\n"); } diff --git a/src/Mod/Fem/Gui/ViewProviderFemMesh.cpp b/src/Mod/Fem/Gui/ViewProviderFemMesh.cpp index b7829b9521..97832c4ec5 100644 --- a/src/Mod/Fem/Gui/ViewProviderFemMesh.cpp +++ b/src/Mod/Fem/Gui/ViewProviderFemMesh.cpp @@ -796,7 +796,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, lines->coordIndex.setNum(0); return; } - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log( "Start: ViewProviderFEMMeshBuilder::createMesh() =================================\n"); @@ -834,7 +834,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, std::vector facesHelper(numTries); Base::Console().Log(" %f: Start build up %i face helper\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo()), + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed()), facesHelper.size()); Base::BoundBox3d BndBox; @@ -1359,7 +1359,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, if (FaceSize < MaxFacesShowInner) { Base::Console().Log(" %f: Start eliminate internal faces SIMPLE\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // search for double (inside) faces and hide them if (!ShowInner) { @@ -1376,7 +1376,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, } else { Base::Console().Log(" %f: Start eliminate internal faces GRID\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); BndBox.Enlarge(BndBox.CalcDiagonalLength() / 10000.0); // calculate grid properties double edge = pow(FaceSize, 1.0 / 3.0); @@ -1444,7 +1444,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, Base::Console().Log(" %f: Start build up node map\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // sort out double nodes and build up index map std::map mapNodeIndex; @@ -1477,7 +1477,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, } } Base::Console().Log(" %f: Start set point vector\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // set the point coordinates coords->point.setNum(mapNodeIndex.size()); @@ -1495,7 +1495,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, // count triangle size Base::Console().Log(" %f: Start count triangle size\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); int triangleCount = 0; for (int l = 0; l < FaceSize; l++) { if (!facesHelper[l].hide) { @@ -1551,7 +1551,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, } Base::Console().Log(" %f: Start build up triangle vector\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // set the triangle face indices faces->coordIndex.setNum(4 * triangleCount); vFaceElementIdx.resize(triangleCount); @@ -2971,7 +2971,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, faces->coordIndex.finishEditing(); Base::Console().Log(" %f: Start build up edge vector\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // std::map > EdgeMap; // count edges int EdgeSize = 0; @@ -3000,7 +3000,7 @@ void ViewProviderFEMMeshBuilder::createMesh(const App::Property* prop, Base::Console().Log( " %f: Finish =========================================================\n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } diff --git a/src/Mod/Fem/Gui/ViewProviderFemMeshPyImp.cpp b/src/Mod/Fem/Gui/ViewProviderFemMeshPyImp.cpp index 030e262dee..0c1a73660c 100644 --- a/src/Mod/Fem/Gui/ViewProviderFemMeshPyImp.cpp +++ b/src/Mod/Fem/Gui/ViewProviderFemMeshPyImp.cpp @@ -186,7 +186,7 @@ void ViewProviderFemMeshPy::setNodeColor(Py::Dict arg) this->getViewProviderFemMeshPtr()->resetColorByNodeId(); } else { - Base::TimeInfo Start; + Base::TimeElapsed Start; Base::Console().Log( "Start: ViewProviderFemMeshPy::setNodeColor() =================================\n"); // std::map NodeColorMap; @@ -209,12 +209,12 @@ void ViewProviderFemMeshPy::setNodeColor(Py::Dict arg) App::Color(Py::Float(color[0]), Py::Float(color[1]), Py::Float(color[2]), 0); } Base::Console().Log(" %f: Start ViewProviderFemMeshPy::setNodeColor() call \n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); // this->getViewProviderFemMeshPtr()->setColorByNodeId(NodeColorMap); this->getViewProviderFemMeshPtr()->setColorByNodeId(NodeIds, NodeColors); Base::Console().Log(" %f: Finish ViewProviderFemMeshPy::setNodeColor() call \n", - Base::TimeInfo::diffTimeF(Start, Base::TimeInfo())); + Base::TimeElapsed::diffTimeF(Start, Base::TimeElapsed())); } } diff --git a/src/Mod/Part/Gui/TaskCheckGeometry.cpp b/src/Mod/Part/Gui/TaskCheckGeometry.cpp index 4599219825..fb0333edb6 100644 --- a/src/Mod/Part/Gui/TaskCheckGeometry.cpp +++ b/src/Mod/Part/Gui/TaskCheckGeometry.cpp @@ -678,13 +678,13 @@ int TaskCheckGeometryResults::goBOPSingleCheck(const TopoDS_Shape& shapeIn, Resu BOPCheck.CurveOnSurfaceMode() = curveOnSurfaceMode; #ifdef FC_DEBUG - Base::TimeInfo start_time; + Base::TimeElapsed start_time; #endif BOPCheck.Perform(); #ifdef FC_DEBUG - float bopAlgoTime = Base::TimeInfo::diffTimeF(start_time,Base::TimeInfo()); + float bopAlgoTime = Base::TimeElapsed::diffTimeF(start_time, Base::TimeElapsed()); std::cout << std::endl << "BopAlgo check time is: " << bopAlgoTime << std::endl << std::endl; #endif diff --git a/src/Mod/Part/Gui/ViewProviderExt.cpp b/src/Mod/Part/Gui/ViewProviderExt.cpp index 8b425d3b99..e0fd102b58 100644 --- a/src/Mod/Part/Gui/ViewProviderExt.cpp +++ b/src/Mod/Part/Gui/ViewProviderExt.cpp @@ -921,7 +921,7 @@ void ViewProviderPartExt::updateVisual() } // time measurement and book keeping - Base::TimeInfo start_time; + Base::TimeElapsed start_time; int numTriangles=0,numNodes=0,numNorms=0,numFaces=0,numEdges=0,numLines=0; std::set faceEdges; @@ -1281,7 +1281,7 @@ void ViewProviderPartExt::updateVisual() # ifdef FC_DEBUG // printing some information - Base::Console().Log("ViewProvider update time: %f s\n",Base::TimeInfo::diffTimeF(start_time,Base::TimeInfo())); + Base::Console().Log("ViewProvider update time: %f s\n",Base::TimeElapsed::diffTimeF(start_time,Base::TimeElapsed())); Base::Console().Log("Shape tria info: Faces:%d Edges:%d Nodes:%d Triangles:%d IdxVec:%d\n",numFaces,numEdges,numNodes,numTriangles,numLines); # else (void)numEdges; diff --git a/src/Mod/Sketcher/App/Sketch.cpp b/src/Mod/Sketcher/App/Sketch.cpp index 315676f99c..bf68f40fae 100644 --- a/src/Mod/Sketcher/App/Sketch.cpp +++ b/src/Mod/Sketcher/App/Sketch.cpp @@ -197,7 +197,7 @@ int Sketch::setUpSketch(const std::vector& GeoList, const std::vector& ConstraintList, int extGeoCount) { - Base::TimeInfo start_time; + Base::TimeElapsed start_time; clear(); @@ -339,10 +339,10 @@ int Sketch::setUpSketch(const std::vector& GeoList, calculateDependentParametersElements(); if (debugMode == GCS::Minimal || debugMode == GCS::IterationLevel) { - Base::TimeInfo end_time; + Base::TimeElapsed end_time; Base::Console().Log("Sketcher::setUpSketch()-T:%s\n", - Base::TimeInfo::diffTime(start_time, end_time).c_str()); + Base::TimeElapsed::diffTime(start_time, end_time).c_str()); } return GCSsys.dofsNumber(); @@ -4538,21 +4538,21 @@ bool Sketch::updateNonDrivingConstraints() int Sketch::solve() { - Base::TimeInfo start_time; + Base::TimeElapsed start_time; std::string solvername; auto result = internalSolve(solvername); - Base::TimeInfo end_time; + Base::TimeElapsed end_time; if (debugMode == GCS::Minimal || debugMode == GCS::IterationLevel) { Base::Console().Log("Sketcher::Solve()-%s-T:%s\n", solvername.c_str(), - Base::TimeInfo::diffTime(start_time, end_time).c_str()); + Base::TimeElapsed::diffTime(start_time, end_time).c_str()); } - SolveTime = Base::TimeInfo::diffTimeF(start_time, end_time); + SolveTime = Base::TimeElapsed::diffTimeF(start_time, end_time); return result; } diff --git a/src/Mod/Sketcher/App/planegcs/GCS.cpp b/src/Mod/Sketcher/App/planegcs/GCS.cpp index b5b7600189..cb87fc5892 100644 --- a/src/Mod/Sketcher/App/planegcs/GCS.cpp +++ b/src/Mod/Sketcher/App/planegcs/GCS.cpp @@ -5043,7 +5043,7 @@ int System::diagnose(Algorithm alg) if (qrAlgorithm == EigenDenseQR) { #ifdef PROFILE_DIAGNOSE - Base::TimeInfo DenseQR_start_time; + Base::TimeElapsed DenseQR_start_time; #endif if (J.rows() > 0) { int rank = 0; // rank is not cheap to retrieve from qrJT in DenseQR @@ -5101,9 +5101,9 @@ int System::diagnose(Algorithm alg) } } #ifdef PROFILE_DIAGNOSE - Base::TimeInfo DenseQR_end_time; + Base::TimeElapsed DenseQR_end_time; - auto SolveTime = Base::TimeInfo::diffTimeF(DenseQR_start_time, DenseQR_end_time); + auto SolveTime = Base::TimeElapsed::diffTimeF(DenseQR_start_time, DenseQR_end_time); Base::Console().Log("\nDenseQR - Lapsed Time: %f seconds\n", SolveTime); #endif @@ -5112,7 +5112,7 @@ int System::diagnose(Algorithm alg) #ifdef EIGEN_SPARSEQR_COMPATIBLE else if (qrAlgorithm == EigenSparseQR) { #ifdef PROFILE_DIAGNOSE - Base::TimeInfo SparseQR_start_time; + Base::TimeElapsed SparseQR_start_time; #endif if (J.rows() > 0) { int rank = 0; @@ -5178,9 +5178,9 @@ int System::diagnose(Algorithm alg) } #ifdef PROFILE_DIAGNOSE - Base::TimeInfo SparseQR_end_time; + Base::TimeElapsed SparseQR_end_time; - auto SolveTime = Base::TimeInfo::diffTimeF(SparseQR_start_time, SparseQR_end_time); + auto SolveTime = Base::TimeElapsed::diffTimeF(SparseQR_start_time, SparseQR_end_time); Base::Console().Log("\nSparseQR - Lapsed Time: %f seconds\n", SolveTime); #endif