GoogleCloudPlatform / GoogleCloudPlatform/cloud-spanner-emulator
Clock/Lock Slowdown
- Dominant language
- C++
- Stars
- 334
- Forks
- 77
- Avg merge
- 8m
- Merged PRs (30d)
- 2
Description
Hello all,
Thanks for creating the Spanner emulator. We use it in our test suite fairly heavily and it has been great for productivity.
Our tests are set up to use a shared emulator instance for all tests, and distinct databases are created for the life of each test. We notice that subsequent runs of our suite against the same emulator process experience a steady increase in wall time with each run (e.g. +0.4s from the prior run for a smaller sub-suite).
We added some instrumentation and it seems like the increase in time comes from `LockManager::WaitForSafeRead`. Our hypothesis is that [`Clock`](https://github.com/GoogleCloudPlatform/cloud-spanner-emulator/blob/845fe2e2e277d8866c5193bdfac885ad293f8e87/common/clock.cc#L40) slowly accumulates a drift away from the system time and has no chance to recover:
```cpp
// dd2313c
absl::Time Clock::Now() {
absl::MutexLock lock(&mu_);
absl::Time now = NowMicros();
absl::Time next_dispensed_time =
last_dispensed_time_ +
std::max(absl::Microseconds(1), now - last_system_time_);
last_system_time_ = now;
last_dispensed_time_ = next_dispensed_time;
return last_dispensed_time_;
}
```
In a run of the sub-suite mentioned earlier we branch down the +1 microsecond path 4000 times (out of 9000 calls to `Clock::Now`). Since `Clock` advances by the elapsed system time otherwise, it permanently moves ahead of the system time an additional ~4ms with each run of the suite.
To test this hypothesis we replaced the Now implementation with one which allows the clock to recover from the drift:
```cpp
absl::Time Clock::Now() {
absl::MutexLock lock(&mu_);
absl::Time now = NowMicros();
if (now <= last_dispensed_time_) {
last_dispensed_time_ += absl::Microseconds(1);
} else {
last_dispensed_time_ = now;
}
return last_dispensed_time_;
}
```
With this in place multiple runs of our suite against the same emulator process complete at roughly the same speed. We also notice that they are slightly faster.
We’re unsure if maintaining the relative system time delta is important for Spanner, or if there is a better way to fix this. It’s also worth noting that our experimental build is running on arm64 macOS which required some patching. As far as I can tell the patches don’t impact this. (As a crude measure, our build with the original Now implementation matches the performance of the official docker image.)
Is there some way the emulator could be updated to avoid this slowdown? Does it sound like our tests are doing something wrong? Happy to provide more information if helpful.
Thanks!
Contributor guide
Assessment
This issue has not been assessed yet.