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 nanoseconds spent waiting, or -1 if the amount of
 155  * time cannot be determined.
 156  */
 157 static nanoseconds getSchedTimeWaiting(pid_t tid) {
 158 #ifndef __linux__
 159   (void)tid;
 160   return nanoseconds(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 nanoseconds(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 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 nanoseconds(0);
 211   }
 212 #endif
 213 }
 214
 215 void TimePoint::reset() {
 216   // Remember the current time
 217   timeStart_ = steady_clock::now();
 218
 219   // Remember how long this process has spent waiting to be scheduled
 220   tid_ = getOSThreadID();
 221   timeWaiting_ = getSchedTimeWaiting(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_ = steady_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 checkTimeout(
 236     const TimePoint& start,
 237     const TimePoint& end,
 238     nanoseconds expected,
 239     bool allowSmaller,
 240     nanoseconds tolerance) {
 241   auto elapsedTime = end.getTimeStart() - start.getTimeEnd();
 242
 243   if (!allowSmaller) {
 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))) {
 247       return false;
 248     }
 249   }
 250
 251   // Check that the event fired within a reasonable time of the timout.
 252   //
 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);
 261   } else {
 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);
 266   }
 267
 268   nanoseconds effectiveElapsedTime(0);
 269   if (elapsedTime > timeExcluded) {
 270     effectiveElapsedTime = elapsedTime - timeExcluded;
 271   }
 272
 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) {
 277     return false;
 278   }
 279
 280   return true;
 281 }
 282
 283 }