2 * Copyright 2017 Facebook, Inc.
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
8 * http://www.apache.org/licenses/LICENSE-2.0
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
16 #ifndef __STDC_FORMAT_MACROS
17 #define __STDC_FORMAT_MACROS
20 #include <folly/io/async/test/TimeUtil.h>
25 #include <sys/types.h>
27 #include <sys/utsname.h>
34 #include <folly/Conv.h>
35 #include <folly/ScopeGuard.h>
36 #include <folly/portability/SysSyscall.h>
37 #include <folly/portability/Unistd.h>
38 #include <folly/portability/Windows.h>
40 #include <glog/logging.h>
43 using namespace std::chrono;
48 static pid_t gettid() {
49 return pid_t(GetCurrentThreadId());
53 * glibc doesn't provide gettid(), so define it ourselves.
55 static pid_t gettid() {
56 return syscall(FOLLY_SYS_gettid);
60 static int getLinuxVersion(StringPiece release) {
61 auto dot1 = release.find('.');
62 if (dot1 == StringPiece::npos) {
63 throw std::invalid_argument("could not find first dot");
65 auto v1 = folly::to<int>(release.subpiece(0, dot1));
67 auto dot2 = release.find('.', dot1 + 1);
68 if (dot2 == StringPiece::npos) {
69 throw std::invalid_argument("could not find second dot");
71 auto v2 = folly::to<int>(release.subpiece(dot1 + 1, dot2 - (dot1 + 1)));
73 int dash = release.find('-', dot2 + 1);
74 auto v3 = folly::to<int>(release.subpiece(dot2 + 1, dash - (dot2 + 1)));
76 return ((v1 * 1000 + v2) * 1000) + v3;
81 * Determine the time units used in /proc/<pid>/schedstat
83 * Returns the number of nanoseconds per time unit,
84 * or -1 if we cannot determine the units.
86 static int64_t determineSchedstatUnits() {
87 struct utsname unameInfo;
88 if (uname(&unameInfo) != 0) {
89 LOG(ERROR) << "unable to determine jiffies/second: uname failed: %s"
94 // In Linux version 2.6.23 and later, time time values are always
95 // reported in nanoseconds.
97 // This change appears to have been made in commit 425e0968a25f, which
98 // moved some of the sched stats code to a new file. Despite the commit
99 // message claiming "no code changes are caused by this patch", it changed
100 // the task.sched_info.cpu_time and task.sched_info.run_delay counters to be
101 // computed using sched_clock() rather than jiffies.
104 linuxVersion = getLinuxVersion(unameInfo.release);
105 } catch (const std::exception&) {
106 LOG(ERROR) << "unable to determine jiffies/second: failed to parse "
107 << "kernel release string \"" << unameInfo.release << "\"";
110 if (linuxVersion >= 2006023) {
111 // The units are nanoseconds
115 // In Linux versions prior to 2.6.23, the time values are reported in
116 // jiffies. This is somewhat unfortunate, as the number of jiffies per
117 // second is configurable. We have to determine the units being used.
119 // It seems like the only real way to figure out the CONFIG_HZ value used by
120 // this kernel is to look it up in the config file.
122 // Look in /boot/config-<kernel_release>
123 char configPath[256];
124 snprintf(configPath, sizeof(configPath), "/boot/config-%s",
127 FILE* f = fopen(configPath, "r");
129 LOG(ERROR) << "unable to determine jiffies/second: "
130 "cannot open kernel config file %s" << configPath;
139 while (fgets(buf, sizeof(buf), f) != nullptr) {
140 if (strcmp(buf, "CONFIG_NO_HZ=y\n") == 0) {
141 LOG(ERROR) << "unable to determine jiffies/second: tickless kernel";
143 } else if (strcmp(buf, "CONFIG_HZ=1000\n") == 0) {
145 } else if (strcmp(buf, "CONFIG_HZ=300\n") == 0) {
147 } else if (strcmp(buf, "CONFIG_HZ=250\n") == 0) {
149 } else if (strcmp(buf, "CONFIG_HZ=100\n") == 0) {
155 LOG(ERROR) << "unable to determine jiffies/second: no CONFIG_HZ setting "
156 "found in %s" << configPath;
165 * Determine how long this process has spent waiting to get scheduled on the
168 * Returns the number of milliseconds spent waiting, or -1 if the amount of
169 * time cannot be determined.
171 static milliseconds getTimeWaitingMS(pid_t tid) {
174 return milliseconds(0);
176 static int64_t timeUnits = determineSchedstatUnits();
178 // We couldn't figure out how many jiffies there are in a second.
179 // Don't bother reading the schedstat info if we can't interpret it.
180 return milliseconds(0);
185 char schedstatFile[256];
186 snprintf(schedstatFile, sizeof(schedstatFile),
187 "/proc/%d/schedstat", tid);
188 fd = open(schedstatFile, O_RDONLY);
190 throw std::runtime_error(
191 folly::to<string>("failed to open process schedstat file", errno));
195 ssize_t bytesReadRet = read(fd, buf, sizeof(buf) - 1);
196 if (bytesReadRet <= 0) {
197 throw std::runtime_error(
198 folly::to<string>("failed to read process schedstat file", errno));
200 size_t bytesRead = size_t(bytesReadRet);
202 if (buf[bytesRead - 1] != '\n') {
203 throw std::runtime_error("expected newline at end of schedstat data");
205 assert(bytesRead < sizeof(buf));
206 buf[bytesRead] = '\0';
208 uint64_t activeJiffies = 0;
209 uint64_t waitingJiffies = 0;
210 uint64_t numTasks = 0;
211 int rc = sscanf(buf, "%" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
212 &activeJiffies, &waitingJiffies, &numTasks);
214 throw std::runtime_error("failed to parse schedstat data");
218 return duration_cast<milliseconds>(nanoseconds(waitingJiffies * timeUnits));
219 } catch (const std::runtime_error& e) {
223 LOG(ERROR) << "error determining process wait time: %s" << e.what();
224 return milliseconds(0);
229 void TimePoint::reset() {
230 // Remember the current time
231 timeStart_ = system_clock::now();
233 // Remember how long this process has spent waiting to be scheduled
235 timeWaiting_ = getTimeWaitingMS(tid_);
237 // In case it took a while to read the schedstat info,
238 // also record the time after the schedstat check
239 timeEnd_ = system_clock::now();
242 std::ostream& operator<<(std::ostream& os, const TimePoint& timePoint) {
243 os << "TimePoint(" << timePoint.getTimeStart().time_since_epoch().count()
244 << ", " << timePoint.getTimeEnd().time_since_epoch().count() << ", "
245 << timePoint.getTimeWaiting().count() << ")";
250 checkTimeout(const TimePoint& start, const TimePoint& end,
251 milliseconds expectedMS, bool allowSmaller,
252 milliseconds tolerance) {
253 auto elapsedTime = end.getTimeStart() - start.getTimeEnd();
256 // Timeouts should never fire before the time was up.
257 // Allow 1ms of wiggle room for rounding errors.
258 if (elapsedTime < (expectedMS - milliseconds(1))) {
263 // Check that the event fired within a reasonable time of the timout.
265 // If the system is under heavy load, our process may have had to wait for a
266 // while to be run. The time spent waiting for the processor shouldn't
267 // count against us, so exclude this time from the check.
268 milliseconds excludedMS;
269 if (end.getTid() != start.getTid()) {
270 // We can only correctly compute the amount of time waiting to be scheduled
271 // if both TimePoints were set in the same thread.
272 excludedMS = milliseconds(0);
274 excludedMS = end.getTimeWaiting() - start.getTimeWaiting();
275 assert(end.getTimeWaiting() >= start.getTimeWaiting());
276 // Add a tolerance here due to precision issues on linux, see below note.
277 assert((elapsedTime + tolerance) >= excludedMS);
280 milliseconds effectiveElapsedMS = milliseconds(0);
281 if (elapsedTime > excludedMS) {
282 effectiveElapsedMS = duration_cast<milliseconds>(elapsedTime) - excludedMS;
285 // On x86 Linux, sleep calls generally have precision only to the nearest
286 // millisecond. The tolerance parameter lets users allow a few ms of slop.
287 milliseconds overrun = effectiveElapsedMS - expectedMS;
288 if (overrun > tolerance) {