Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
47 changes: 31 additions & 16 deletions src/support/timing.h
Original file line number Diff line number Diff line change
Expand Up @@ -14,38 +14,53 @@
* limitations under the License.
*/

//
// Timing helper
//

#ifndef wasm_support_timing_h
#define wasm_support_timing_h

#include <chrono>
#include <iostream>
#include <string>
#include <utility>

namespace wasm {

// A utility for measuring time between readings as well as total elapsed time.
// The timer starts upon construction, but can be restarted.
class Timer {
std::string name;
std::chrono::steady_clock::time_point startTime;
double total = 0;
std::chrono::steady_clock::time_point lastTime;

public:
Timer(std::string name = "") : name(name) {}
Timer() { restart(); }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This makes the following pattern I use more difficult:

static Timer timer("work");

int foo() {
  ..
  timer.start(); ... timer.end();
  ..
}

int bar() {
  ..
  timer.start(); ... timer.end();
  ..
}

To collect timings from multiple functions (or multiple invocations of the same function), it seems better to manually start?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In that case it's trivial to just have a different timer for each function.

In DAE2 I currently have lines that look like this just to measure parts of a larger operation:

TIME(timer.stop(); timer.dump(); timer = Timer("rewrite"); timer.start());

With this change, this just becomes this:

TIME(std::cerr << "some time: " << timer.lastElapsed() << "\n");

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In that case it's trivial to just have a different timer for each function.

But imagine that the timer measures a certain type of shared work. E.g. it's nice to see the total validation time across all functions, or the total LocalGraph time over multiple invocations of the same function (each of which might be very fast).

How about adding a RunningTimer for what you want?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In that case, the global state can be the time and it can be updated locally by doing Timer localTimer; ... globalTime += localTimer.totalElapsed(). This is the same number of lines necessary for that use case in the current API, but plays better with multithreading. I don't think it's worth having multiple timer utilities when there is only a single usage checked in.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fair enough.


void start() { startTime = std::chrono::steady_clock::now(); }
// Resets the timer's start time and returns the time since its last start.
void restart() {
auto now = std::chrono::steady_clock::now();
lastTime = startTime = now;
}

void stop() {
total += std::chrono::duration<double>(std::chrono::steady_clock::now() -
startTime)
.count();
// The time since the timer was started.
double totalElapsed() {
auto now = std::chrono::steady_clock::now();
auto sinceStart = std::chrono::duration<double>(now - startTime).count();
return sinceStart;
}

double getTotal() { return total; }
// The time since the last `lastElapsed` measurement, if any, or since the
// timer started.
double lastElapsed() {
auto now = std::chrono::steady_clock::now();
auto sinceLast = std::chrono::duration<double>(now - lastTime).count();
lastTime = now;
return sinceLast;
}

void dump() { std::cerr << "<Timer " << name << ": " << getTotal() << ">\n"; }
// The time elapsed since the last measurement and the total elapsed time.
std::pair<double, double> elapsed() {
auto now = std::chrono::steady_clock::now();
auto sinceLast = std::chrono::duration<double>(now - lastTime).count();
auto sinceStart = std::chrono::duration<double>(now - startTime).count();
lastTime = now;
return {sinceLast, sinceStart};
}
};

} // namespace wasm
Expand Down
8 changes: 2 additions & 6 deletions src/tools/wasm-reduce/wasm-reduce.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -97,7 +97,6 @@ struct ProgramResult {
#ifdef _WIN32
void getFromExecution(std::string command) {
Timer timer;
timer.start();
SECURITY_ATTRIBUTES saAttr;
saAttr.nLength = sizeof(SECURITY_ATTRIBUTES);
saAttr.bInheritHandle = TRUE;
Expand Down Expand Up @@ -176,15 +175,13 @@ struct ProgramResult {
output.append(chBuf);
}
}
timer.stop();
time = timer.getTotal();
time = timer.totalElapsed();
}
#else // POSIX
// runs the command and notes the output
// TODO: also stderr, not just stdout?
void getFromExecution(std::string command) {
Timer timer;
timer.start();
const int MAX_BUFFER = 1024;
char buffer[MAX_BUFFER];
FILE* stream = popen(
Expand All @@ -195,8 +192,7 @@ struct ProgramResult {
output.append(buffer);
}
code = pclose(stream);
timer.stop();
time = timer.getTotal();
time = timer.totalElapsed();
}
#endif // _WIN32

Expand Down
Loading