Skip to content

Commit ec840cf

Browse files
driver: Add basic timing information to output (#140)
1 parent 0c6c099 commit ec840cf

File tree

2 files changed

+56
-7
lines changed

2 files changed

+56
-7
lines changed

indexer/Driver.cc

Lines changed: 25 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,7 @@
4545
#include "indexer/Path.h"
4646
#include "indexer/RAII.h"
4747
#include "indexer/ScipExtras.h"
48+
#include "indexer/Timer.h"
4849

4950
namespace boost_ip = boost::interprocess;
5051

@@ -575,11 +576,22 @@ class Driver {
575576
}
576577

577578
void run() {
578-
auto compdbGuard = this->openCompilationDatabase();
579-
this->spawnWorkers(compdbGuard);
580-
this->runJobsTillCompletionAndShutdownWorkers();
581-
this->emitScipIndex();
582-
spdlog::debug("indexing complete; driver shutting down now, kthxbai");
579+
ManualTimer total, indexing, merging;
580+
unsigned numTus;
581+
582+
TIME_IT(total, {
583+
auto compdbGuard = this->openCompilationDatabase();
584+
this->spawnWorkers(compdbGuard);
585+
TIME_IT(indexing,
586+
numTus = this->runJobsTillCompletionAndShutdownWorkers());
587+
TIME_IT(merging, this->emitScipIndex());
588+
spdlog::debug("indexing complete; driver shutting down now, kthxbai");
589+
});
590+
using secs = std::chrono::seconds;
591+
fmt::print("Finished indexing {} translation units in {:.1f}s (indexing: "
592+
"{:.1f}s, merging: {:.1f}s).\n",
593+
numTus, total.value<secs>(), indexing.value<secs>(),
594+
merging.value<secs>());
583595
}
584596

585597
private:
@@ -710,15 +722,21 @@ class Driver {
710722
return commands.size();
711723
}
712724

713-
void runJobsTillCompletionAndShutdownWorkers() {
725+
/// Returns the number of TUs processed
726+
unsigned runJobsTillCompletionAndShutdownWorkers() {
727+
unsigned numJobs = 0;
714728
this->scheduler.runJobsTillCompletion(
715-
[this]() -> void { this->processOneJobResult(); },
729+
[this, &numJobs]() -> void {
730+
this->processOneJobResult();
731+
numJobs++;
732+
},
716733
[this]() -> size_t { return this->refillJobs(); },
717734
[this](ToBeScheduledWorkerId &&workerId, JobId jobId) -> void {
718735
this->assignJobToWorker(std::move(workerId), jobId);
719736
});
720737
this->shutdownAllWorkers();
721738
this->scheduler.waitForAllWorkers();
739+
return numJobs / 2; // Each TU has exactly 2 jobs.
722740
}
723741

724742
FileGuard openCompilationDatabase() {

indexer/Timer.h

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
// NOTE(ref: based-on-sorbet): Based on Sorbet files:
55
// - common/Counters.h
66
// - common/Timer.h
7+
#include <chrono>
78

89
#include "spdlog/logger.h"
910

@@ -52,6 +53,36 @@ class Timer {
5253
~Timer();
5354
};
5455

56+
class ManualTimer {
57+
std::chrono::steady_clock::time_point startInstant;
58+
std::chrono::duration<std::chrono::steady_clock::rep,
59+
std::chrono::steady_clock::period>
60+
duration;
61+
62+
public:
63+
ManualTimer() : startInstant(), duration(0) {}
64+
65+
void start() {
66+
this->startInstant = std::chrono::steady_clock::now();
67+
}
68+
69+
void stop() {
70+
this->duration = std::chrono::steady_clock::now() - startInstant;
71+
}
72+
73+
template <typename D> double value() const {
74+
return std::chrono::duration<double, typename D::period>(this->duration)
75+
.count();
76+
}
77+
};
78+
5579
} // namespace scip_clang
5680

81+
#define TIME_IT(timer_, op_) \
82+
do { \
83+
timer_.start(); \
84+
op_; \
85+
timer_.stop(); \
86+
} while (0)
87+
5788
#endif // SCIP_CLANG_TIMER_H

0 commit comments

Comments
 (0)