Skip to content

Commit

Permalink
Revised Timer, now using std::chrono (#3484)
Browse files Browse the repository at this point in the history
* Remove resume functionality
This is not used and is only available for non logging timers whcih makes it inconsistent.

* Move to chrono timings

* Return duration instead of scalar

* Remove boost timer dependency

* Switch to microseconds as default

* Fix with cast

* Addapt logging to new std::chrono clocks

* Remove missed boost timer dependencies

* Partially revert boost dependency removal

* Remove list_timings from python wrapper

* Readd elapsed for pyhton testing

* Ruff

* Ruff 2

* Doc

* Some simplifications

* Try removing cast

* Simplification

* Doc improvement

* Fixes for timer

* Dox updates

* Updates

* Various fixes

* Doc improvements

* Remove debug

---------

Co-authored-by: schnellerhase <[email protected]>
garth-wells and schnellerhase authored Oct 28, 2024

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature.
1 parent 5c1b88e commit a33486f
Showing 20 changed files with 175 additions and 226 deletions.
2 changes: 1 addition & 1 deletion .github/workflows/ccpp.yml
Original file line number Diff line number Diff line change
@@ -89,7 +89,7 @@ jobs:
- name: Install dependencies
run: |
sudo apt-get update
sudo apt-get install catch2 cmake g++ libboost-dev libboost-timer-dev libhdf5-mpi-dev libparmetis-dev libpugixml-dev libspdlog-dev mpi-default-dev ninja-build pkg-config
sudo apt-get install catch2 cmake g++ libboost-dev libhdf5-mpi-dev libparmetis-dev libpugixml-dev libspdlog-dev mpi-default-dev ninja-build pkg-config
- name: Set up Python
uses: actions/setup-python@v5
with:
2 changes: 1 addition & 1 deletion cpp/CMakeLists.txt
Original file line number Diff line number Diff line change
@@ -303,7 +303,7 @@ endif()

set(Boost_USE_MULTITHREADED $ENV{BOOST_USE_MULTITHREADED})
set(Boost_VERBOSE TRUE)
find_package(Boost 1.70 REQUIRED timer)
find_package(Boost 1.70 REQUIRED)
set_package_properties(
Boost PROPERTIES
TYPE REQUIRED
2 changes: 1 addition & 1 deletion cpp/cmake/templates/DOLFINXConfig.cmake.in
Original file line number Diff line number Diff line change
@@ -22,7 +22,7 @@ if(DEFINED ENV{BOOST_ROOT} OR DEFINED BOOST_ROOT)
endif()
set(Boost_USE_MULTITHREADED $ENV{BOOST_USE_MULTITHREADED})
set(Boost_VERBOSE TRUE)
find_package(Boost 1.70 REQUIRED timer)
find_package(Boost 1.70 REQUIRED)

if(@ufcx_FOUND@)
find_dependency(ufcx)
2 changes: 1 addition & 1 deletion cpp/demo/custom_kernel/main.cpp
Original file line number Diff line number Diff line change
@@ -269,7 +269,7 @@ void assemble(MPI_Comm comm)
assemble_matrix1<T>(mesh->geometry(), *V->dofmap(), kernel_a, cells);
assemble_vector1<T>(mesh->geometry(), *V->dofmap(), kernel_L, cells);

list_timings(comm, {TimingType::wall});
list_timings(comm);
}

int main(int argc, char* argv[])
1 change: 0 additions & 1 deletion cpp/dolfinx/CMakeLists.txt
Original file line number Diff line number Diff line change
@@ -97,7 +97,6 @@ target_link_libraries(dolfinx PUBLIC Basix::basix)

# Boost
target_link_libraries(dolfinx PUBLIC Boost::headers)
target_link_libraries(dolfinx PUBLIC Boost::timer)

# MPI
target_link_libraries(dolfinx PUBLIC MPI::MPI_CXX)
1 change: 0 additions & 1 deletion cpp/dolfinx/common/CMakeLists.txt
Original file line number Diff line number Diff line change
@@ -25,7 +25,6 @@ target_sources(
${CMAKE_CURRENT_SOURCE_DIR}/log.cpp
${CMAKE_CURRENT_SOURCE_DIR}/MPI.cpp
${CMAKE_CURRENT_SOURCE_DIR}/Table.cpp
${CMAKE_CURRENT_SOURCE_DIR}/Timer.cpp
${CMAKE_CURRENT_SOURCE_DIR}/TimeLogger.cpp
${CMAKE_CURRENT_SOURCE_DIR}/TimeLogManager.cpp
${CMAKE_CURRENT_SOURCE_DIR}/timing.cpp
2 changes: 2 additions & 0 deletions cpp/dolfinx/common/TimeLogManager.h
Original file line number Diff line number Diff line change
@@ -6,6 +6,8 @@

#pragma once

#include "TimeLogger.h"

namespace dolfinx::common
{

60 changes: 16 additions & 44 deletions cpp/dolfinx/common/TimeLogger.cpp
Original file line number Diff line number Diff line change
@@ -8,42 +8,34 @@
#include "MPI.h"
#include "log.h"
#include <iostream>
#include <variant>

using namespace dolfinx;
using namespace dolfinx::common;

//-----------------------------------------------------------------------------
void TimeLogger::register_timing(std::string task, double wall, double user,
double system)
void TimeLogger::register_timing(std::string task, double time)
{
assert(wall >= 0.0);
assert(user >= 0.0);
assert(system >= 0.0);
assert(time >= 0.0);

// Print a message
std::string line = "Elapsed wall, usr, sys time: " + std::to_string(wall)
+ ", " + std::to_string(user) + ", "
+ std::to_string(system) + " (" + task + ")";
std::string line
= "Elapsed time: " + std::to_string(time) + " (" + task + ")";
spdlog::debug(line.c_str());

// Store values for summary
if (auto it = _timings.find(task); it != _timings.end())
{
std::get<0>(it->second) += 1;
std::get<1>(it->second) += wall;
std::get<2>(it->second) += user;
std::get<3>(it->second) += system;
std::get<1>(it->second) += time;
}
else
_timings.insert({task, {1, wall, user, system}});
_timings.insert({task, {1, time}});
}
//-----------------------------------------------------------------------------
void TimeLogger::list_timings(MPI_Comm comm, std::set<TimingType> type,
Table::Reduction reduction)
void TimeLogger::list_timings(MPI_Comm comm, Table::Reduction reduction) const
{
// Format and reduce to rank 0
Table timings = this->timings(type);
Table timings = this->timings();
timings = timings.reduce(comm, reduction);
const std::string str = "\n" + timings.str();

@@ -52,44 +44,23 @@ void TimeLogger::list_timings(MPI_Comm comm, std::set<TimingType> type,
std::cout << str << std::endl;
}
//-----------------------------------------------------------------------------
Table TimeLogger::timings(std::set<TimingType> type)
Table TimeLogger::timings() const
{
// Generate log::timing table
Table table("Summary of timings");

bool time_wall = type.find(TimingType::wall) != type.end();
bool time_user = type.find(TimingType::user) != type.end();
bool time_sys = type.find(TimingType::system) != type.end();

for (auto& it : _timings)
{
const std::string task = it.first;
const auto [num_timings, wall, usr, sys] = it.second;
// NB - the cast to std::variant should not be needed: needed by Intel
// compiler.
table.set(task, "reps",
std::variant<std::string, int, double>(num_timings));
if (time_wall)
{
table.set(task, "wall avg", wall / static_cast<double>(num_timings));
table.set(task, "wall tot", wall);
}
if (time_user)
{
table.set(task, "usr avg", usr / static_cast<double>(num_timings));
table.set(task, "usr tot", usr);
}
if (time_sys)
{
table.set(task, "sys avg", sys / static_cast<double>(num_timings));
table.set(task, "sys tot", sys);
}
std::string task = it.first;
auto [num_timings, time] = it.second;
table.set(task, "reps", num_timings);
table.set(task, "avg", time / static_cast<double>(num_timings));
table.set(task, "tot", time);
}

return table;
}
//-----------------------------------------------------------------------------
std::tuple<int, double, double, double> TimeLogger::timing(std::string task)
std::pair<int, double> TimeLogger::timing(std::string task) const
{
// Find timing
auto it = _timings.find(task);
@@ -98,6 +69,7 @@ std::tuple<int, double, double, double> TimeLogger::timing(std::string task)
throw std::runtime_error("No timings registered for task \"" + task
+ "\".");
}

return it->second;
}
//-----------------------------------------------------------------------------
21 changes: 8 additions & 13 deletions cpp/dolfinx/common/TimeLogger.h
Original file line number Diff line number Diff line change
@@ -10,15 +10,13 @@
#include "timing.h"
#include <map>
#include <mpi.h>
#include <set>
#include <string>
#include <tuple>
#include <utility>

namespace dolfinx::common
{

/// Timer logging

class TimeLogger
{
public:
@@ -35,29 +33,26 @@ class TimeLogger
~TimeLogger() = default;

/// Register timing (for later summary)
void register_timing(std::string task, double wall, double user,
double system);
void register_timing(std::string task, double wall);

/// Return a summary of timings and tasks in a Table
Table timings(std::set<TimingType> type);
Table timings() const;

/// List a summary of timings and tasks. Reduction type is
/// printed.
/// @param comm MPI Communicator
/// @param type Set of possible timings: wall, user or system
/// @param reduction Reduction type (min, max or average)
void list_timings(MPI_Comm comm, std::set<TimingType> type,
Table::Reduction reduction);
void list_timings(MPI_Comm comm, Table::Reduction reduction) const;

/// Return timing
/// @brief Return timing.
/// @param[in] task The task name to retrieve the timing for
/// @returns Values (count, total wall time, total user time, total
/// system time) for given task.
std::tuple<int, double, double, double> timing(std::string task);
std::pair<int, double> timing(std::string task) const;

private:
// List of timings for tasks, map from string to (num_timings,
// total_wall_time, total_user_time, total_system_time)
std::map<std::string, std::tuple<int, double, double, double>> _timings;
// total_wall_time)
std::map<std::string, std::pair<int, double>> _timings;
};
} // namespace dolfinx::common
55 changes: 0 additions & 55 deletions cpp/dolfinx/common/Timer.cpp

This file was deleted.

118 changes: 85 additions & 33 deletions cpp/dolfinx/common/Timer.h
Original file line number Diff line number Diff line change
@@ -1,63 +1,115 @@
// Copyright (C) 2008 Anders Logg, 2015 Jan Blechta
// Copyright (C) 2008-2015 Anders Logg, Jan Blechta, Paul T. Kühner and Garth N.
// Wells
//
// This file is part of DOLFINx (https://www.fenicsproject.org)
//
// SPDX-License-Identifier: LGPL-3.0-or-later

#pragma once

#include <array>
#include <boost/timer/timer.hpp>
#include "TimeLogManager.h"
#include <chrono>
#include <optional>
#include <string>

namespace dolfinx::common
{

/// A timer can be used for timing tasks. The basic usage is
///
/// Timer timer("Assembling over cells");
/// @brief Timer for measuring and logging elapsed time durations.
///
/// The basic usage is
/// \code{.cpp}
/// Timer timer("Assembling over cells");
/// \endcode
/// The timer is started at construction and timing ends when the timer
/// is destroyed (goes out of scope). It is also possible to start and
/// stop a timer explicitly by
///
/// timer.start(); timer.stop();
///
/// Timings are stored globally and a summary may be printed by calling
///
/// is destroyed (goes out of scope). The timer can be started (reset)
/// and stopped explicitly by
/// \code{.cpp}
/// timer.start();
/// /* .... */
/// timer.stop();
/// \endcode
/// A summary of registered elapsed times can be printed by calling
/// \code{.cpp}
/// list_timings();

/// \endcode
template <typename T = std::chrono::high_resolution_clock>
class Timer
{
public:
/// Create timer
/// @brief Create and start timer.
///
/// Elapsed is optionally registered in the logger (in seconds) when
/// the Timer destructor is called.
///
/// If a task name is provided this enables logging to logger, otherwise (i.e.
/// no task provided) nothing gets logged.
Timer(std::optional<std::string> task = std::nullopt);
/// @param[in] task Name used to registered the elapsed time in the
/// logger. If no name is set, the elapsed time is not registered in
/// the logger.
Timer(std::optional<std::string> task = std::nullopt) : _task(task) {}

/// Destructor
~Timer();
/// If timer is still running, it is stopped. Elapsed time is
/// registered in the logger.
~Timer()
{
if (_start_time.has_value()) // Timer is running
{
_acc += T::now() - _start_time.value();
_start_time = std::nullopt;
}

/// Zero and start timer
void start();
if (_task.has_value())
{
using X = std::chrono::duration<double, std::ratio<1>>;
TimeLogManager::logger().register_timing(
_task.value(), std::chrono::duration_cast<X>(_acc).count());
}
}

/// Resume timer. Not well-defined for logging timer
void resume();
/// Reset elapsed time and (re-)start timer.
void start()
{
_acc = T::duration::zero();
_start_time = T::now();
}

/// Stop timer, return wall time elapsed and store timing data into
/// logger
double stop();
/// @brief Elapsed time since time has been started.
///
/// Default duration unit is seconds.
///
/// @return Elapsed time duration.
template <typename Period = std::ratio<1>>
std::chrono::duration<double, Period> elapsed() const
{
if (_start_time.has_value()) // Timer is running
return T::now() - _start_time.value() + _acc;
else // Timer is stoped
return _acc;
}

/// @brief Stop timer and return elapsed time.
///
/// Default duration unit is seconds.
///
/// @return Elapsed time duration.
template <typename Period = std::ratio<1>>
std::chrono::duration<double, Period> stop()
{
if (_start_time.has_value()) // Timer is running
{
_acc += T::now() - _start_time.value();
_start_time = std::nullopt;
}

/// Return wall, user and system time in seconds
std::array<double, 3> elapsed() const;
return _acc;
}

private:
// Name of task
// Name of task to register in logger
std::optional<std::string> _task;

// Implementation of timer
boost::timer::cpu_timer _timer;
// Elapsed time offset
T::duration _acc = T::duration::zero();

// Store start time *std::nullopt if timer has been stopped)
std::optional<typename T::time_point> _start_time = T::now();
};
} // namespace dolfinx::common
12 changes: 5 additions & 7 deletions cpp/dolfinx/common/timing.cpp
Original file line number Diff line number Diff line change
@@ -11,19 +11,17 @@
#include "Timer.h"

//-----------------------------------------------------------------------
dolfinx::Table dolfinx::timings(std::set<TimingType> type)
dolfinx::Table dolfinx::timings()
{
return dolfinx::common::TimeLogManager::logger().timings(type);
return dolfinx::common::TimeLogManager::logger().timings();
}
//-----------------------------------------------------------------------------
void dolfinx::list_timings(MPI_Comm comm, std::set<TimingType> type,
Table::Reduction reduction)
void dolfinx::list_timings(MPI_Comm comm, Table::Reduction reduction)
{
dolfinx::common::TimeLogManager::logger().list_timings(comm, type, reduction);
dolfinx::common::TimeLogManager::logger().list_timings(comm, reduction);
}
//-----------------------------------------------------------------------------
std::tuple<std::size_t, double, double, double>
dolfinx::timing(std::string task)
std::pair<std::size_t, double> dolfinx::timing(std::string task)
{
return dolfinx::common::TimeLogManager::logger().timing(task);
}
21 changes: 5 additions & 16 deletions cpp/dolfinx/common/timing.h
Original file line number Diff line number Diff line change
@@ -8,40 +8,29 @@

#include "Table.h"
#include <mpi.h>
#include <set>
#include <string>
#include <tuple>
#include <utility>

namespace dolfinx
{
/// @brief Timing types.
enum class TimingType : int
{
wall = 0, ///< Wall-clock time
user = 1, ///< User (cpu) time
system = 2 ///< System (kernel) time
};

/// @brief Return a summary of timings and tasks in a Table.
/// @param[in] type Timing type.
/// @return Table with timings.
Table timings(std::set<TimingType> type);
Table timings();

/// @brief List a summary of timings and tasks.
///
/// ``MPI_AVG`` reduction is printed.
///
/// @param[in] comm MPI Communicator.
/// @param[in] type Timing type.
/// @param[in] reduction MPI Reduction to apply (min, max or average).
void list_timings(MPI_Comm comm, std::set<TimingType> type,
void list_timings(MPI_Comm comm,
Table::Reduction reduction = Table::Reduction::max);

/// @brief Return timing (count, total wall time, total user time, total
/// system time) for given task.
/// @param[in] task Name of a task
/// @return The (count, total wall time, total user time, total system
/// time) for the task.
std::tuple<std::size_t, double, double, double> timing(std::string task);
/// @return The (count, total wall time) for the task.
std::pair<std::size_t, double> timing(std::string task);

} // namespace dolfinx
1 change: 0 additions & 1 deletion cpp/vcpkg.json
Original file line number Diff line number Diff line change
@@ -4,7 +4,6 @@
"boost-algorithm",
"boost-functional",
"boost-lexical-cast",
"boost-timer",
"boost-unordered",
"boost-uuid",
"catch2",
1 change: 0 additions & 1 deletion docker/Dockerfile.redhat
Original file line number Diff line number Diff line change
@@ -20,7 +20,6 @@ RUN dnf -y update && \
dnf -y install \
bison \
boost-devel \
boost-timer \
boost-program-options \
cmake \
gcc \
1 change: 0 additions & 1 deletion docker/Dockerfile.test-env
Original file line number Diff line number Diff line change
@@ -80,7 +80,6 @@ RUN export DEBIAN_FRONTEND=noninteractive && \
g++ \
gfortran \
libboost-dev \
libboost-timer-dev \
liblapack-dev \
libopenblas-dev \
libpugixml-dev \
13 changes: 4 additions & 9 deletions python/dolfinx/common.py
Original file line number Diff line number Diff line change
@@ -41,20 +41,18 @@
"ufcx_signature",
]

TimingType = _cpp.common.TimingType
Reduction = _cpp.common.Reduction


def timing(task: str):
return _cpp.common.timing(task)


def list_timings(comm, timing_types: list, reduction=Reduction.max):
"""Print out a summary of all Timer measurements, with a choice of
wall time, system time or user time. When used in parallel, a
def list_timings(comm, reduction=Reduction.max):
"""Print out a summary of all Timer measurements. When used in parallel, a
reduction is applied across all processes. By default, the maximum
time is shown."""
_cpp.common.list_timings(comm, timing_types, reduction)
_cpp.common.list_timings(comm, reduction)


class Timer:
@@ -88,7 +86,7 @@ class Timer:
may be printed using functions ``timing``, ``timings``,
``list_timings``, ``dump_timings_to_xml``, e.g.::
list_timings(comm, [TimingType.wall, TimingType.user])
list_timings(comm)
"""

_cpp_object: _cpp.common.Timer
@@ -109,9 +107,6 @@ def start(self):
def stop(self):
return self._cpp_object.stop()

def resume(self):
self._cpp_object.resume()

def elapsed(self):
return self._cpp_object.elapsed()

66 changes: 31 additions & 35 deletions python/dolfinx/wrappers/common.cpp
Original file line number Diff line number Diff line change
@@ -4,34 +4,32 @@
//
// SPDX-License-Identifier: LGPL-3.0-or-later

#include "MPICommWrapper.h"
#include "array.h"
#include "caster_mpi.h"
#include <complex>
#include <dolfinx/common/IndexMap.h>
#include <dolfinx/common/Scatterer.h>
#include <dolfinx/common/Table.h>
#include <dolfinx/common/Timer.h>
#include <dolfinx/common/defines.h>
#include <dolfinx/common/log.h>
#include <dolfinx/common/timing.h>
#include <dolfinx/common/utils.h>
#include <memory>
#include <optional>
#include <span>
#include <string>
#include <vector>

#include <nanobind/nanobind.h>
#include <nanobind/ndarray.h>
#include <nanobind/stl/array.h>
#include <nanobind/stl/chrono.h>
#include <nanobind/stl/optional.h>
#include <nanobind/stl/pair.h>
#include <nanobind/stl/string.h>
#include <nanobind/stl/tuple.h>
#include <nanobind/stl/vector.h>

#include <dolfinx/common/IndexMap.h>
#include <dolfinx/common/Scatterer.h>
#include <dolfinx/common/Table.h>
#include <dolfinx/common/Timer.h>
#include <dolfinx/common/defines.h>
#include <dolfinx/common/log.h>
#include <dolfinx/common/timing.h>
#include <dolfinx/common/utils.h>

#include "MPICommWrapper.h"
#include "array.h"
#include "caster_mpi.h"
#include <optional>
#include <span>
#include <string>
#include <vector>

namespace nb = nanobind;

@@ -164,30 +162,28 @@ void common(nb::module_& m)
},
nb::arg("global"));
// dolfinx::common::Timer
nb::class_<dolfinx::common::Timer>(m, "Timer", "Timer class")
nb::class_<dolfinx::common::Timer<std::chrono::high_resolution_clock>>(
m, "Timer", "Timer class")
.def(nb::init<std::optional<std::string>>(), nb::arg("task").none())
.def("start", &dolfinx::common::Timer::start, "Start timer")
.def("stop", &dolfinx::common::Timer::stop, "Stop timer")
.def("resume", &dolfinx::common::Timer::resume)
.def("elapsed", &dolfinx::common::Timer::elapsed);
.def("start",
&dolfinx::common::Timer<std::chrono::high_resolution_clock>::start,
"Start timer")
.def("elapsed",
&dolfinx::common::Timer<
std::chrono::high_resolution_clock>::elapsed<>,
"Elapsed time")
.def("stop",
&dolfinx::common::Timer<std::chrono::high_resolution_clock>::stop<>,
"Stop timer");

// dolfinx::common::Timer enum
nb::enum_<dolfinx::TimingType>(m, "TimingType")
.value("wall", dolfinx::TimingType::wall)
.value("system", dolfinx::TimingType::system)
.value("user", dolfinx::TimingType::user);

m.def("timing", &dolfinx::timing);

m.def(
"list_timings",
[](MPICommWrapper comm, std::vector<dolfinx::TimingType> type,
dolfinx::Table::Reduction reduction)
{
std::set<dolfinx::TimingType> _type(type.begin(), type.end());
dolfinx::list_timings(comm.get(), _type, reduction);
},
nb::arg("comm"), nb::arg("type"), nb::arg("reduction"));
[](MPICommWrapper comm, dolfinx::Table::Reduction reduction)
{ dolfinx::list_timings(comm.get(), reduction); }, nb::arg("comm"),
nb::arg("reduction"));

m.def(
"init_logging",
16 changes: 13 additions & 3 deletions python/test/unit/common/test_timer.py
Original file line number Diff line number Diff line change
@@ -8,6 +8,8 @@

from time import sleep

import pytest

from dolfinx import common


@@ -17,8 +19,10 @@ def test_context_manager_named():

# Execute task in the context manager
t = common.Timer(task)
t.start()
sleep(0.05)
assert t.elapsed()[0] > 0.035
t.stop()
assert t.elapsed().total_seconds() > 0.035
del t

# Check timing
@@ -29,6 +33,12 @@ def test_context_manager_named():

def test_context_manager_anonymous():
"""Test that anonymous Timer works as context manager"""
with common.Timer() as t:
timer = common.Timer()
with timer:
sleep(0.05)
assert t.elapsed()[0] > 0.035

assert timer.elapsed().total_seconds() > 0.035


if __name__ == "__main__":
pytest.main([__file__])
4 changes: 2 additions & 2 deletions python/test/unit/fem/test_custom_jit_kernels.py
Original file line number Diff line number Diff line change
@@ -19,7 +19,7 @@
import ffcx.codegeneration.utils
from dolfinx import cpp as _cpp
from dolfinx import fem, la
from dolfinx.common import TimingType, list_timings
from dolfinx.common import list_timings
from dolfinx.fem import Form, Function, IntegralType, form_cpp_class, functionspace
from dolfinx.mesh import create_unit_square

@@ -114,7 +114,7 @@ def test_numba_assembly(dtype):
assert np.isclose(Anorm, 56.124860801609124)
assert np.isclose(bnorm, 0.0739710713711999)

list_timings(MPI.COMM_WORLD, [TimingType.wall])
list_timings(MPI.COMM_WORLD)


@pytest.mark.parametrize("dtype", [np.float32, np.float64, np.complex64, np.complex128])

0 comments on commit a33486f

Please sign in to comment.