update TimeUtil to use getOSThreadID()
[folly.git] / folly / io / async / test / TimeUtil.cpp
1 /*
2  * Copyright 2017 Facebook, Inc.
3  *
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
7  *
8  *   http://www.apache.org/licenses/LICENSE-2.0
9  *
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.
15  */
16 #ifndef __STDC_FORMAT_MACROS
17 #define __STDC_FORMAT_MACROS
18 #endif
19
20 #include <folly/io/async/test/TimeUtil.h>
21
22 #include <errno.h>
23 #include <fcntl.h>
24 #include <sys/stat.h>
25 #include <sys/types.h>
26 #ifdef __linux__
27 #include <sys/utsname.h>
28 #endif
29
30 #include <chrono>
31 #include <ostream>
32 #include <stdexcept>
33
34 #include <folly/Conv.h>
35 #include <folly/ScopeGuard.h>
36 #include <folly/ThreadId.h>
37 #include <folly/portability/Unistd.h>
38
39 #include <glog/logging.h>
40
41 using std::string;
42 using namespace std::chrono;
43
44 namespace folly {
45
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");
50   }
51   auto v1 = folly::to<int>(release.subpiece(0, dot1));
52
53   auto dot2 = release.find('.', dot1 + 1);
54   if (dot2 == StringPiece::npos) {
55     throw std::invalid_argument("could not find second dot");
56   }
57   auto v2 = folly::to<int>(release.subpiece(dot1 + 1, dot2 - (dot1 + 1)));
58
59   int dash = release.find('-', dot2 + 1);
60   auto v3 = folly::to<int>(release.subpiece(dot2 + 1, dash - (dot2 + 1)));
61
62   return ((v1 * 1000 + v2) * 1000) + v3;
63 }
64
65 #ifdef __linux__
66 /**
67  * Determine the time units used in /proc/<pid>/schedstat
68  *
69  * Returns the number of nanoseconds per time unit,
70  * or -1 if we cannot determine the units.
71  */
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"
76                << strerror(errno);
77     return -1;
78   }
79
80   // In Linux version 2.6.23 and later, time time values are always
81   // reported in nanoseconds.
82   //
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.
88   int linuxVersion;
89   try {
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 << "\"";
94     return -1;
95   }
96   if (linuxVersion >= 2006023) {
97     // The units are nanoseconds
98     return 1;
99   }
100
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.
104   //
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.
107   //
108   // Look in /boot/config-<kernel_release>
109   char configPath[256];
110   snprintf(configPath, sizeof(configPath), "/boot/config-%s",
111            unameInfo.release);
112
113   FILE* f = fopen(configPath, "r");
114   if (f == nullptr) {
115     LOG(ERROR) << "unable to determine jiffies/second: "
116       "cannot open kernel config file %s" << configPath;
117     return -1;
118   }
119   SCOPE_EXIT {
120     fclose(f);
121   };
122
123   int64_t hz = -1;
124   char buf[1024];
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";
128       return -1;
129     } else if (strcmp(buf, "CONFIG_HZ=1000\n") == 0) {
130       hz = 1000;
131     } else if (strcmp(buf, "CONFIG_HZ=300\n") == 0) {
132       hz = 300;
133     } else if (strcmp(buf, "CONFIG_HZ=250\n") == 0) {
134       hz = 250;
135     } else if (strcmp(buf, "CONFIG_HZ=100\n") == 0) {
136       hz = 100;
137     }
138   }
139
140   if (hz == -1) {
141     LOG(ERROR) << "unable to determine jiffies/second: no CONFIG_HZ setting "
142       "found in %s" << configPath;
143     return -1;
144   }
145
146   return hz;
147 }
148 #endif
149
150 /**
151  * Determine how long this process has spent waiting to get scheduled on the
152  * CPU.
153  *
154  * Returns the number of milliseconds spent waiting, or -1 if the amount of
155  * time cannot be determined.
156  */
157 static milliseconds getTimeWaitingMS(pid_t tid) {
158 #ifndef __linux__
159   (void)tid;
160   return milliseconds(0);
161 #else
162   static int64_t timeUnits = determineSchedstatUnits();
163   if (timeUnits < 0) {
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 milliseconds(0);
167   }
168
169   int fd = -1;
170   try {
171     char schedstatFile[256];
172     snprintf(schedstatFile, sizeof(schedstatFile),
173              "/proc/%d/schedstat", tid);
174     fd = open(schedstatFile, O_RDONLY);
175     if (fd < 0) {
176       throw std::runtime_error(
177         folly::to<string>("failed to open process schedstat file", errno));
178     }
179
180     char buf[512];
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));
185     }
186     size_t bytesRead = size_t(bytesReadRet);
187
188     if (buf[bytesRead - 1] != '\n') {
189       throw std::runtime_error("expected newline at end of schedstat data");
190     }
191     assert(bytesRead < sizeof(buf));
192     buf[bytesRead] = '\0';
193
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);
199     if (rc != 3) {
200       throw std::runtime_error("failed to parse schedstat data");
201     }
202
203     close(fd);
204     return duration_cast<milliseconds>(nanoseconds(waitingJiffies * timeUnits));
205   } catch (const std::runtime_error& e) {
206     if (fd >= 0) {
207       close(fd);
208     }
209     LOG(ERROR) << "error determining process wait time: %s" << e.what();
210     return milliseconds(0);
211   }
212 #endif
213 }
214
215 void TimePoint::reset() {
216   // Remember the current time
217   timeStart_ = system_clock::now();
218
219   // Remember how long this process has spent waiting to be scheduled
220   tid_ = getOSThreadID();
221   timeWaiting_ = getTimeWaitingMS(tid_);
222
223   // In case it took a while to read the schedstat info,
224   // also record the time after the schedstat check
225   timeEnd_ = system_clock::now();
226 }
227
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() << ")";
232   return os;
233 }
234
235 bool
236 checkTimeout(const TimePoint& start, const TimePoint& end,
237              milliseconds expectedMS, bool allowSmaller,
238              milliseconds tolerance) {
239   auto elapsedTime = end.getTimeStart() - start.getTimeEnd();
240
241   if (!allowSmaller) {
242     // Timeouts should never fire before the time was up.
243     // Allow 1ms of wiggle room for rounding errors.
244     if (elapsedTime < (expectedMS - milliseconds(1))) {
245       return false;
246     }
247   }
248
249   // Check that the event fired within a reasonable time of the timout.
250   //
251   // If the system is under heavy load, our process may have had to wait for a
252   // while to be run.  The time spent waiting for the processor shouldn't
253   // count against us, so exclude this time from the check.
254   milliseconds excludedMS;
255   if (end.getTid() != start.getTid()) {
256     // We can only correctly compute the amount of time waiting to be scheduled
257     // if both TimePoints were set in the same thread.
258     excludedMS = milliseconds(0);
259   } else {
260     excludedMS = end.getTimeWaiting() - start.getTimeWaiting();
261     assert(end.getTimeWaiting() >= start.getTimeWaiting());
262     // Add a tolerance here due to precision issues on linux, see below note.
263     assert((elapsedTime + tolerance) >= excludedMS);
264   }
265
266   milliseconds effectiveElapsedMS = milliseconds(0);
267   if (elapsedTime > excludedMS) {
268     effectiveElapsedMS = duration_cast<milliseconds>(elapsedTime) - excludedMS;
269   }
270
271   // On x86 Linux, sleep calls generally have precision only to the nearest
272   // millisecond.  The tolerance parameter lets users allow a few ms of slop.
273   milliseconds overrun = effectiveElapsedMS - expectedMS;
274   if (overrun > tolerance) {
275     return false;
276   }
277
278   return true;
279 }
280
281 }