Feature instrumentation profiling

.github/workflows/CI-build-and-test.yml

@@ -38,7 +38,7 @@ jobs:
     - name: Configure CMake
       # Configure CMake in a 'build' subdirectory. `CMAKE_BUILD_TYPE` is only required if you are using a single-configuration generator such as make.
       # See https://cmake.org/cmake/help/latest/variable/CMAKE_BUILD_TYPE.html?highlight=cmake_build_type
-      run: cmake -DTEST_COVERAGE=ON -DCMAKE_PREFIX_PATH=`python3 -c 'import torch;print(torch.utils.cmake_prefix_path)'` -B ${{github.workspace}}/build -DCMAKE_BUILD_TYPE=${{env.BUILD_TYPE}}
+      run: cmake -DNT_TEST_COVERAGE=ON -DCMAKE_PREFIX_PATH=`python3 -c 'import torch;print(torch.utils.cmake_prefix_path)'` -B ${{github.workspace}}/build -DCMAKE_BUILD_TYPE=${{env.BUILD_TYPE}}
 
     - name: Build
       # Build your program with the given configuration

CMakeLists.txt

@@ -3,9 +3,9 @@ set(CMAKE_CXX_STANDARD 17)
 
 project(nuTens)
 
-OPTION(TEST_COVERAGE "TEST_COVERAGE" OFF)
+OPTION(NT_TEST_COVERAGE "produce code coverage reports when running tests" OFF)
 
-IF(TEST_COVERAGE)
+IF(NT_TEST_COVERAGE)
     message("Adding flags to check test coverage")
     add_compile_options("--coverage")
     add_link_options("--coverage")
@@ -22,8 +22,8 @@ CPMAddPackage("gh:gabime/spdlog@1.8.2")
 
 ## check build times
 ## have this optional as it's not supported on all CMake platforms
-OPTION(BUILD_TIMING "output time to build each target" OFF)
-IF(BUILD_TIMING)
+OPTION(NT_BUILD_TIMING "output time to build each target" OFF)
+IF(NT_BUILD_TIMING)
     set_property(GLOBAL PROPERTY RULE_LAUNCH_COMPILE "${CMAKE_COMMAND} -E time")
 ENDIF()
 
@@ -33,4 +33,18 @@ set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} ${TORCH_CXX_FLAGS}")
 
 
 add_subdirectory(nuTens)
-add_subdirectory(tests)
+add_subdirectory(tests)
+
+
+message( STATUS "The following variables have been used to configure the build: " )
+get_cmake_property(_variableNames VARIABLES)
+list (SORT _variableNames)
+foreach (_variableName ${_variableNames})
+    unset(MATCHED)
+    string(REGEX MATCH "^NT_*" MATCHED ${_variableName})
+    if (NOT MATCHED)
+        continue()
+    endif()
+
+    message(STATUS "  ${_variableName}=${${_variableName}}")
+endforeach()

README.md

@@ -47,7 +47,7 @@ make test
 - [x] Doxygen documentation with automatic deployment
 - [x] Add test coverage checks into CI
 - [x] Integrate linting ( [cpp-linter](https://github.com/cpp-linter)? )
-- [ ] Add instrumentation library for benchmarking and profiling
+- [x] Add instrumentation library for benchmarking and profiling
 - [ ] Add suite of benchmarking tests
 - [ ] Integrate benchmarks into CI ( maybe use [hyperfine](https://github.com/sharkdp/hyperfine) and [bencher](https://bencher.dev/) for this? )
 - [ ] Add proper unit tests

nuTens/CMakeLists.txt

@@ -1,14 +1,15 @@
 
-
-## set up logging
+########################
+#### set up logging ####
+########################
 add_library(logging logging.hpp)
 target_link_libraries(logging spdlog::spdlog)
 set_target_properties(logging PROPERTIES LINKER_LANGUAGE CXX)
 
-set( LOG_LEVEL "INFO" CACHE STRING "the level of detail to log to the console" )
+set( NT_LOG_LEVEL "INFO" CACHE STRING "the level of detail to log to the console" )
 
-## Convert LOG_LEVEL to all upper case so that we aren't case sensitive to user input
-string( TOUPPER "${LOG_LEVEL}" LOG_LEVEL_UPPER )
+## Convert NT_LOG_LEVEL to all upper case so that we aren't case sensitive to user input
+string( TOUPPER "${NT_LOG_LEVEL}" LOG_LEVEL_UPPER )
 
 ## Check the specified log level is valid
 set(VALID_LOG_OPTIONS SILENT ERROR WARNING INFO DEBUG TRACE)
@@ -24,17 +25,28 @@ target_compile_definitions(logging PUBLIC NT_LOG_LEVEL=NT_LOG_LEVEL_${LOG_LEVEL_
 
 
 
+################################
+#### set up instrumentation ####
+################################
+add_library(instrumentation instrumentation.hpp)
+set_target_properties(instrumentation PROPERTIES LINKER_LANGUAGE CXX)
+
+option( NT_PROFILING "enable profiling of the code" OFF )
+if( NT_PROFILING )
+    target_compile_definitions( instrumentation PUBLIC USE_PROFILING )
+endif()
+
 
 ## if user wants to use pch then we use the pch
 ## people, especially if developing, might want to use this as including tensor related things
 ## can be excruciatingly sloow when building
-OPTION(USE_PCH "USE_PCH" OFF)
-IF(USE_PCH)
+OPTION(NT_USE_PCH "NT_USE_PCH" OFF)
+IF(NT_USE_PCH)
     message("Using precompiled header")
 
     add_library(nuTens-pch nuTens-pch.hpp)
 
-    SET(PCH_LIBS "${PCH_LIBS};logging")
+    SET(PCH_LIBS "${PCH_LIBS};logging;instrumentation")
 
     ## the headers included in the PCH will (at some point) depend on which tensor library is being used
     IF(TORCH_FOUND)
@@ -50,7 +62,7 @@ IF(USE_PCH)
     target_precompile_headers(nuTens-pch PUBLIC nuTens-pch.hpp)
     set_target_properties(nuTens-pch PROPERTIES LINKER_LANGUAGE CXX)
 
-ENDIF() ## end USE_PCH block
+ENDIF() ## end NT_USE_PCH block
 
 
 

nuTens/instrumentation.hpp

@@ -0,0 +1,197 @@
+#pragma once
+
+#include <algorithm>
+#include <chrono>
+#include <fstream>
+#include <string>
+#include <thread>
+#include <utility>
+/*! \file instrumentation.hpp
+    \brief Define utilities for instrumentation of the code
+
+    This is the home of anything that gets placed inside other classes or functions in order to instrument the code.
+   e.g. for profiling or debugging. Everything should ideally be macro-fied so it can be included only for certain
+   builds, or specified by build time options.
+*/
+
+struct ProfileResult
+{
+    /// @brief Hold the results of a profiled function to be written out.
+
+    std::string name;
+    long start;
+    long end;
+    uint32_t threadID;
+};
+
+class ProfileWriter
+{
+    /*! @class ProfileWriter
+     * @brief Singleton class to collect timing information for functions and write out to a file that can be inspected
+     * later with visual profiling tool
+     *
+     * Writes out profiling information in a json format readable by chrome tracing
+     * (https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/) Use the macros provided to instrument
+     * the code like: \code{.cpp}
+     *
+     * \code{.cpp}
+     *
+     * Then open up your favourite chromium based browser and go to chrome://tracing. You can then just drag and drop
+     * the profiling json file and should see a lovely display of the collected profile information.
+     */
+
+    /// \todo currently only suppor the format used by chrome tracing. Would be nice to support other formats too.
+    /// Should just be a case of adding additional option for writeProfile and header and footer
+
+  public:
+    /// @brief Constructor
+    ProfileWriter()  
+    {
+    }
+
+    /// @brief Set up the session
+    /// @param[in] name The name of the timer
+    /// @param[in] filePath The destination of the output file
+    void beginSession(const std::string &name, const std::string &filePath = "results.json")
+    {
+        _outputStream.open(filePath);
+        writeHeader();
+        _name = name;
+    }
+
+    /// @brief Close the session and clean up
+    void endSession()
+    {
+        writeFooter();
+        _outputStream.close();
+        _name = "";
+        _profileCount = 0;
+    }
+
+    /// @brief Write out the results of a profiled function
+    /// @param[in] result The result to write
+    void writeProfile(const ProfileResult &result)
+    {
+        if (_profileCount++ > 0)
+        {
+            _outputStream << ",";
+        }
+
+        std::string name = result.name;
+        std::replace(name.begin(), name.end(), '"', '\'');
+
+        _outputStream << "{";
+        _outputStream << R"("cat":"function",)";
+        _outputStream << "\"dur\":" << (result.end - result.start) << ',';
+        _outputStream << R"("name":")" << name << "\",";
+        _outputStream << R"("ph":"X",)";
+        _outputStream << "\"pid\":0,";
+        _outputStream << "\"tid\":" << result.threadID << ",";
+        _outputStream << "\"ts\":" << result.start;
+        _outputStream << "}";
+
+        _outputStream.flush();
+    }
+
+    /// @brief Write the file header
+    void writeHeader()
+    {
+        _outputStream << R"({"otherData": {},"traceEvents":[)";
+        _outputStream.flush();
+    }
+
+    /// @brief Write the file footer
+    void writeFooter()
+    {
+        _outputStream << "]}";
+        _outputStream.flush();
+    }
+
+    /// @brief Get a reference to the ProfileWriter, if it has not yet been instantiated, this will do so
+    static ProfileWriter &get()
+    {
+        static ProfileWriter instance; // this will be instantiated the first time ProfileWriter::get() is called and
+                                       // killed at the end of the program
+        return instance;
+    }
+
+  private:
+    std::string _name;
+    std::ofstream _outputStream;
+    uint _profileCount{0};
+};
+
+class InstrumentationTimer
+/*!
+ * @class InstrumentationTimer
+ * @brief Class to perform the actual timing
+ *
+ *
+ *
+ */
+{
+  public:
+    /// @brief Construct an InstrumentationTimer object and start the clock
+    /// @param[in] name The name of the profile. Typically use __FUNCSIG__ so it's clear which part of the code is being
+    /// profiled.
+    InstrumentationTimer(std::string name) : _name(std::move(name)), _stopped(false)
+    {
+        _startTimepoint = std::chrono::high_resolution_clock::now();
+    }
+
+    /// @brief Destroy the timer object and stop the timer by calling stop()
+    ~InstrumentationTimer()
+    {
+        if (!_stopped) {
+            stop();
+    }
+}
+    /// @brief Stop the timer and write out the profile result using the ProfileWriter
+    void stop()
+    {
+        auto endTimepoint = std::chrono::high_resolution_clock::now();
+
+        long long start =
+            std::chrono::time_point_cast<std::chrono::microseconds>(_startTimepoint).time_since_epoch().count();
+        long long end =
+            std::chrono::time_point_cast<std::chrono::microseconds>(endTimepoint).time_since_epoch().count();
+
+        uint32_t threadID = std::hash<std::thread::id>{}(std::this_thread::get_id());
+        ProfileWriter::get().writeProfile({_name, start, end, threadID});
+
+        _stopped = true;
+    }
+
+  private:
+    std::string _name;
+    std::chrono::time_point<std::chrono::high_resolution_clock> _startTimepoint;
+    bool _stopped;
+};
+
+/// @brief Begin a profiling session
+/// Will open up the results json file and set things up.
+/// If USE_PROFILING not defined will be empty so that it can be stripped from non-debug builds
+/// @param[in] sessionName The name of the session
+#ifdef USE_PROFILING
+// NOLINTNEXTLINE
+#define NT_PROFILE_BEGINSESSION(sessionName)                                                                           \
+    ProfileWriter::get().beginSession(sessionName, std::string(sessionName) + "-profile.json")
+#else
+#define NT_PROFILE_BEGINSESSION(sessionName)
+#endif
+
+/// @brief Profile the current scope
+#ifdef USE_PROFILING
+// NOLINTNEXTLINE
+#define NT_PROFILE() InstrumentationTimer timer##__LINE__(std::string(__PRETTY_FUNCTION__))
+#else
+#define NT_PROFILE()
+#endif
+
+/// @brief End the profiling session
+#ifdef USE_PROFILING
+// NOLINTNEXTLINE
+#define NT_PROFILE_ENDSESSION() ProfileWriter::get().endSession()
+#else
+#define NT_PROFILE_ENDSESSION()
+#endif

nuTens/nuTens-pch.hpp

@@ -6,6 +6,7 @@
 #include <complex>
 #include <iostream>
 #include <map>
+#include <nuTens/instrumentation.hpp>
 #include <nuTens/logging.hpp>
 #include <variant>
 #include <vector>

nuTens/propagator/CMakeLists.txt

@@ -13,7 +13,7 @@ IF(USE_PCH)
     target_precompile_headers(propagator REUSE_FROM tensor)
 ENDIF()
 
-target_link_libraries(propagator PUBLIC tensor constants)
+target_link_libraries(propagator PUBLIC tensor constants instrumentation)
 
 target_include_directories(propagator PUBLIC "${CMAKE_SOURCE_DIR}")
 set_target_properties(propagator PROPERTIES LINKER_LANGUAGE CXX)

nuTens/propagator/base-matter-solver.hpp

@@ -1,5 +1,6 @@
 #pragma once
 
+#include <nuTens/instrumentation.hpp>
 #include <nuTens/tensors/tensor.hpp>
 
 class BaseMatterSolver

nuTens/propagator/const-density-solver.cpp

@@ -2,6 +2,7 @@
 
 void ConstDensityMatterSolver::calculateEigenvalues(const Tensor &energies, Tensor &eigenvectors, Tensor &eigenvalues)
 {
+    NT_PROFILE();
     Tensor hamiltonian;
     hamiltonian.zeros({energies.getBatchDim(), nGenerations, nGenerations}, NTdtypes::kComplexFloat);
 

nuTens/propagator/const-density-solver.hpp

@@ -42,8 +42,9 @@
 
     /// @brief Set a new PMNS matrix for this solver
     /// @param newPMNS The new matrix to set
-    inline void setPMNS(const Tensor &newPMNS)
+    inline void setPMNS(const Tensor &newPMNS) override
     {
+        NT_PROFILE();
         PMNS = newPMNS;
 
         // construct the outer product of the electron neutrino row of the PMNS
@@ -54,8 +55,9 @@
 
     /// @brief Set new mass eigenvalues for this solver
     /// @param newMasses The new masses
-    inline void setMasses(const Tensor &newMasses)
+    inline void setMasses(const Tensor &newMasses) override
     {
+        NT_PROFILE();
         masses = newMasses;
 
         // construct the diagonal mass^2 matrix used in the hamiltonian
@@ -76,7 +78,7 @@
     /// shape should look like {Nbatches, 1, 1}.
     /// @param[out] eigenvectors The returned eigenvectors
     /// @param[out] eigenvalues The corresponding eigenvalues
     void calculateEigenvalues(const Tensor &energies, Tensor &eigenvectors, Tensor &eigenvalues);
 
   private:
     Tensor PMNS;

nuTens/propagator/propagator.cpp

@@ -2,6 +2,8 @@
 
 Tensor Propagator::calculateProbs(const Tensor &energies) const
 {
+    NT_PROFILE();
+
     Tensor ret;
 
     // if a matter solver was specified, use effective values for masses and PMNS
@@ -27,6 +29,8 @@ Tensor Propagator::calculateProbs(const Tensor &energies) const
 
 Tensor Propagator::_calculateProbs(const Tensor &energies, const Tensor &massesSq, const Tensor &PMNS) const
 {
+    NT_PROFILE();
+
     Tensor weightMatrix;
     weightMatrix.ones({energies.getBatchDim(), _nGenerations, _nGenerations}, NTdtypes::kComplexFloat)
         .requiresGrad(false);