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/Unistd.h>
37 #include <folly/system/ThreadId.h>
39 #include <glog/logging.h>
42 using namespace std::chrono;
46 static int getLinuxVersion(StringPiece release) {
47 auto dot1 = release.find('.');
48 if (dot1 == StringPiece::npos) {
49 throw std::invalid_argument("could not find first dot");
51 auto v1 = folly::to<int>(release.subpiece(0, dot1));
53 auto dot2 = release.find('.', dot1 + 1);
54 if (dot2 == StringPiece::npos) {
55 throw std::invalid_argument("could not find second dot");
57 auto v2 = folly::to<int>(release.subpiece(dot1 + 1, dot2 - (dot1 + 1)));
59 int dash = release.find('-', dot2 + 1);
60 auto v3 = folly::to<int>(release.subpiece(dot2 + 1, dash - (dot2 + 1)));
62 return ((v1 * 1000 + v2) * 1000) + v3;
67 * Determine the time units used in /proc/<pid>/schedstat
69 * Returns the number of nanoseconds per time unit,
70 * or -1 if we cannot determine the units.
72 static int64_t determineSchedstatUnits() {
73 struct utsname unameInfo;
74 if (uname(&unameInfo) != 0) {
75 LOG(ERROR) << "unable to determine jiffies/second: uname failed: %s"
80 // In Linux version 2.6.23 and later, time time values are always
81 // reported in nanoseconds.
83 // This change appears to have been made in commit 425e0968a25f, which
84 // moved some of the sched stats code to a new file. Despite the commit
85 // message claiming "no code changes are caused by this patch", it changed
86 // the task.sched_info.cpu_time and task.sched_info.run_delay counters to be
87 // computed using sched_clock() rather than jiffies.
90 linuxVersion = getLinuxVersion(unameInfo.release);
91 } catch (const std::exception&) {
92 LOG(ERROR) << "unable to determine jiffies/second: failed to parse "
93 << "kernel release string \"" << unameInfo.release << "\"";
96 if (linuxVersion >= 2006023) {
97 // The units are nanoseconds
101 // In Linux versions prior to 2.6.23, the time values are reported in
102 // jiffies. This is somewhat unfortunate, as the number of jiffies per
103 // second is configurable. We have to determine the units being used.
105 // It seems like the only real way to figure out the CONFIG_HZ value used by
106 // this kernel is to look it up in the config file.
108 // Look in /boot/config-<kernel_release>
109 char configPath[256];
110 snprintf(configPath, sizeof(configPath), "/boot/config-%s",
113 FILE* f = fopen(configPath, "r");
115 LOG(ERROR) << "unable to determine jiffies/second: "
116 "cannot open kernel config file %s" << configPath;
125 while (fgets(buf, sizeof(buf), f) != nullptr) {
126 if (strcmp(buf, "CONFIG_NO_HZ=y\n") == 0) {
127 LOG(ERROR) << "unable to determine jiffies/second: tickless kernel";
129 } else if (strcmp(buf, "CONFIG_HZ=1000\n") == 0) {
131 } else if (strcmp(buf, "CONFIG_HZ=300\n") == 0) {
133 } else if (strcmp(buf, "CONFIG_HZ=250\n") == 0) {
135 } else if (strcmp(buf, "CONFIG_HZ=100\n") == 0) {
141 LOG(ERROR) << "unable to determine jiffies/second: no CONFIG_HZ setting "
142 "found in %s" << configPath;
151 * Determine how long this process has spent waiting to get scheduled on the
154 * Returns the number of nanoseconds spent waiting, or -1 if the amount of
155 * time cannot be determined.
157 static nanoseconds getSchedTimeWaiting(pid_t tid) {
160 return nanoseconds(0);
162 static int64_t timeUnits = determineSchedstatUnits();
164 // We couldn't figure out how many jiffies there are in a second.
165 // Don't bother reading the schedstat info if we can't interpret it.
166 return nanoseconds(0);
171 char schedstatFile[256];
172 snprintf(schedstatFile, sizeof(schedstatFile),
173 "/proc/%d/schedstat", tid);
174 fd = open(schedstatFile, O_RDONLY);
176 throw std::runtime_error(
177 folly::to<string>("failed to open process schedstat file", errno));
181 ssize_t bytesReadRet = read(fd, buf, sizeof(buf) - 1);
182 if (bytesReadRet <= 0) {
183 throw std::runtime_error(
184 folly::to<string>("failed to read process schedstat file", errno));
186 size_t bytesRead = size_t(bytesReadRet);
188 if (buf[bytesRead - 1] != '\n') {
189 throw std::runtime_error("expected newline at end of schedstat data");
191 assert(bytesRead < sizeof(buf));
192 buf[bytesRead] = '\0';
194 uint64_t activeJiffies = 0;
195 uint64_t waitingJiffies = 0;
196 uint64_t numTasks = 0;
197 int rc = sscanf(buf, "%" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
198 &activeJiffies, &waitingJiffies, &numTasks);
200 throw std::runtime_error("failed to parse schedstat data");
204 return nanoseconds(waitingJiffies * timeUnits);
205 } catch (const std::runtime_error& e) {
209 LOG(ERROR) << "error determining process wait time: %s" << e.what();
210 return nanoseconds(0);
215 void TimePoint::reset() {
216 // Remember the current time
217 timeStart_ = steady_clock::now();
219 // Remember how long this process has spent waiting to be scheduled
220 tid_ = getOSThreadID();
221 timeWaiting_ = getSchedTimeWaiting(tid_);
223 // In case it took a while to read the schedstat info,
224 // also record the time after the schedstat check
225 timeEnd_ = steady_clock::now();
228 std::ostream& operator<<(std::ostream& os, const TimePoint& timePoint) {
229 os << "TimePoint(" << timePoint.getTimeStart().time_since_epoch().count()
230 << ", " << timePoint.getTimeEnd().time_since_epoch().count() << ", "
231 << timePoint.getTimeWaiting().count() << ")";
236 const TimePoint& start,
237 const TimePoint& end,
238 nanoseconds expected,
240 nanoseconds tolerance) {
241 auto elapsedTime = end.getTimeStart() - start.getTimeEnd();
244 // Timeouts should never fire before the time was up.
245 // Allow 1ms of wiggle room for rounding errors.
246 if (elapsedTime < (expected - milliseconds(1))) {
251 // Check that the event fired within a reasonable time of the timout.
253 // If the system is under heavy load, our process may have had to wait for a
254 // while to be run. The time spent waiting for the processor shouldn't
255 // count against us, so exclude this time from the check.
256 nanoseconds timeExcluded;
257 if (end.getTid() != start.getTid()) {
258 // We can only correctly compute the amount of time waiting to be scheduled
259 // if both TimePoints were set in the same thread.
260 timeExcluded = nanoseconds(0);
262 timeExcluded = end.getTimeWaiting() - start.getTimeWaiting();
263 assert(end.getTimeWaiting() >= start.getTimeWaiting());
264 // Add a tolerance here due to precision issues on linux, see below note.
265 assert((elapsedTime + tolerance) >= timeExcluded);
268 nanoseconds effectiveElapsedTime(0);
269 if (elapsedTime > timeExcluded) {
270 effectiveElapsedTime = elapsedTime - timeExcluded;
273 // On x86 Linux, sleep calls generally have precision only to the nearest
274 // millisecond. The tolerance parameter lets users allow a few ms of slop.
275 auto overrun = effectiveElapsedTime - expected;
276 if (overrun > tolerance) {