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 #ifndef _MSC_VER
  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/portability/SysSyscall.h>
  37 #include <folly/portability/Unistd.h>
  38 #include <folly/portability/Windows.h>
  39
  40 #include <glog/logging.h>
  41
  42 using std::string;
  43 using namespace std::chrono;
  44
  45 namespace folly {
  46
  47 #ifdef _MSC_VER
  48 static pid_t gettid() {
  49   return pid_t(GetCurrentThreadId());
  50 }
  51 #else
  52 /**
  53  * glibc doesn't provide gettid(), so define it ourselves.
  54  */
  55 static pid_t gettid() {
  56   return syscall(FOLLY_SYS_gettid);
  57 }
  58 #endif
  59
  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");
  64   }
  65   auto v1 = folly::to<int>(release.subpiece(0, dot1));
  66
  67   auto dot2 = release.find('.', dot1 + 1);
  68   if (dot2 == StringPiece::npos) {
  69     throw std::invalid_argument("could not find second dot");
  70   }
  71   auto v2 = folly::to<int>(release.subpiece(dot1 + 1, dot2 - (dot1 + 1)));
  72
  73   int dash = release.find('-', dot2 + 1);
  74   auto v3 = folly::to<int>(release.subpiece(dot2 + 1, dash - (dot2 + 1)));
  75
  76   return ((v1 * 1000 + v2) * 1000) + v3;
  77 }
  78
  79 #ifdef __linux__
  80 /**
  81  * Determine the time units used in /proc/<pid>/schedstat
  82  *
  83  * Returns the number of nanoseconds per time unit,
  84  * or -1 if we cannot determine the units.
  85  */
  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"
  90                << strerror(errno);
  91     return -1;
  92   }
  93
  94   // In Linux version 2.6.23 and later, time time values are always
  95   // reported in nanoseconds.
  96   //
  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.
 102   int linuxVersion;
 103   try {
 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 << "\"";
 108     return -1;
 109   }
 110   if (linuxVersion >= 2006023) {
 111     // The units are nanoseconds
 112     return 1;
 113   }
 114
 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.
 118   //
 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.
 121   //
 122   // Look in /boot/config-<kernel_release>
 123   char configPath[256];
 124   snprintf(configPath, sizeof(configPath), "/boot/config-%s",
 125            unameInfo.release);
 126
 127   FILE* f = fopen(configPath, "r");
 128   if (f == nullptr) {
 129     LOG(ERROR) << "unable to determine jiffies/second: "
 130       "cannot open kernel config file %s" << configPath;
 131     return -1;
 132   }
 133   SCOPE_EXIT {
 134     fclose(f);
 135   };
 136
 137   int64_t hz = -1;
 138   char buf[1024];
 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";
 142       return -1;
 143     } else if (strcmp(buf, "CONFIG_HZ=1000\n") == 0) {
 144       hz = 1000;
 145     } else if (strcmp(buf, "CONFIG_HZ=300\n") == 0) {
 146       hz = 300;
 147     } else if (strcmp(buf, "CONFIG_HZ=250\n") == 0) {
 148       hz = 250;
 149     } else if (strcmp(buf, "CONFIG_HZ=100\n") == 0) {
 150       hz = 100;
 151     }
 152   }
 153
 154   if (hz == -1) {
 155     LOG(ERROR) << "unable to determine jiffies/second: no CONFIG_HZ setting "
 156       "found in %s" << configPath;
 157     return -1;
 158   }
 159
 160   return hz;
 161 }
 162 #endif
 163
 164 /**
 165  * Determine how long this process has spent waiting to get scheduled on the
 166  * CPU.
 167  *
 168  * Returns the number of milliseconds spent waiting, or -1 if the amount of
 169  * time cannot be determined.
 170  */
 171 static milliseconds getTimeWaitingMS(pid_t tid) {
 172 #ifndef __linux__
 173   (void)tid;
 174   return milliseconds(0);
 175 #else
 176   static int64_t timeUnits = determineSchedstatUnits();
 177   if (timeUnits < 0) {
 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);
 181   }
 182
 183   int fd = -1;
 184   try {
 185     char schedstatFile[256];
 186     snprintf(schedstatFile, sizeof(schedstatFile),
 187              "/proc/%d/schedstat", tid);
 188     fd = open(schedstatFile, O_RDONLY);
 189     if (fd < 0) {
 190       throw std::runtime_error(
 191         folly::to<string>("failed to open process schedstat file", errno));
 192     }
 193
 194     char buf[512];
 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));
 199     }
 200     size_t bytesRead = size_t(bytesReadRet);
 201
 202     if (buf[bytesRead - 1] != '\n') {
 203       throw std::runtime_error("expected newline at end of schedstat data");
 204     }
 205     assert(bytesRead < sizeof(buf));
 206     buf[bytesRead] = '\0';
 207
 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);
 213     if (rc != 3) {
 214       throw std::runtime_error("failed to parse schedstat data");
 215     }
 216
 217     close(fd);
 218     return duration_cast<milliseconds>(nanoseconds(waitingJiffies * timeUnits));
 219   } catch (const std::runtime_error& e) {
 220     if (fd >= 0) {
 221       close(fd);
 222     }
 223     LOG(ERROR) << "error determining process wait time: %s" << e.what();
 224     return milliseconds(0);
 225   }
 226 #endif
 227 }
 228
 229 void TimePoint::reset() {
 230   // Remember the current time
 231   timeStart_ = system_clock::now();
 232
 233   // Remember how long this process has spent waiting to be scheduled
 234   tid_ = gettid();
 235   timeWaiting_ = getTimeWaitingMS(tid_);
 236
 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();
 240 }
 241
 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() << ")";
 246   return os;
 247 }
 248
 249 bool
 250 checkTimeout(const TimePoint& start, const TimePoint& end,
 251              milliseconds expectedMS, bool allowSmaller,
 252              milliseconds tolerance) {
 253   auto elapsedTime = end.getTimeStart() - start.getTimeEnd();
 254
 255   if (!allowSmaller) {
 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))) {
 259       return false;
 260     }
 261   }
 262
 263   // Check that the event fired within a reasonable time of the timout.
 264   //
 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);
 273   } else {
 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);
 278   }
 279
 280   milliseconds effectiveElapsedMS = milliseconds(0);
 281   if (elapsedTime > excludedMS) {
 282     effectiveElapsedMS = duration_cast<milliseconds>(elapsedTime) - excludedMS;
 283   }
 284
 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) {
 289     return false;
 290   }
 291
 292   return true;
 293 }
 294
 295 }