Log slow file operations.

install/debug.conf.template

@@ -1788,6 +1788,7 @@ Listen 127.0.0.2:@@APACHE_TERTIARY_PORT@@
 #ALL_DIRECTIVES ModPagespeedRunExperiment true
 #ALL_DIRECTIVES ModPagespeedShardDomain example.com 1.example.com,2.example.com
 #ALL_DIRECTIVES ModPagespeedSharedMemoryLocks true
+#ALL_DIRECTIVES ModPagespeedSlowFileLatencyUs 80000
 #ALL_DIRECTIVES ModPagespeedSlurpDirectory /tmp/slurp/
 #ALL_DIRECTIVES ModPagespeedSlurpFlushLimit 5
 #ALL_DIRECTIVES ModPagespeedSlurpReadOnly true

pagespeed/kernel/base/stdio_file_system.cc

@@ -52,6 +52,11 @@ namespace {
 // for the files. (While POSIX doesn't specify this, it's the proper value on
 // at least Linux, FreeBSD, and OS X).
 const int kBlockSize = 512;
+
+static const char kOutstandingOps[] = "stdio_fs_outstanding_ops";
+static const char kSlowOps[] = "stdio_fs_slow_ops";
+static const char kTotalOps[] = "stdio_fs_total_ops";
+
 }  // namespace
 
 namespace net_instaweb {
@@ -60,9 +65,11 @@ namespace net_instaweb {
 // Output files, in lieu of multiple inheritance.
 class StdioFileHelper {
  public:
-  StdioFileHelper(FILE* f, const StringPiece& filename)
+  StdioFileHelper(FILE* f, const StringPiece& filename, StdioFileSystem* fs)
       : file_(f),
-        line_(1) {
+        line_(1),
+        file_system_(fs),
+        start_us_(0) {
     filename.CopyToString(&filename_);
   }
 
@@ -92,26 +99,39 @@ class StdioFileHelper {
     return ret;
   }
 
+  void StartTimer() {
+    start_us_ = file_system_->StartTimer();
+  }
+
+  void EndTimer(const char* operation) {
+    file_system_->EndTimer(filename_.c_str(), operation, start_us_);
+  }
+
+
   FILE* file_;
   GoogleString filename_;
   int line_;
+  StdioFileSystem* file_system_;
+  int64 start_us_;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(StdioFileHelper);
 };
 
 class StdioInputFile : public FileSystem::InputFile {
  public:
-  StdioInputFile(FILE* f, const StringPiece& filename)
-      : file_helper_(f, filename) {
+  StdioInputFile(FILE* f, const StringPiece& filename, StdioFileSystem* fs)
+      : file_helper_(f, filename, fs) {
   }
 
   virtual int Read(char* buf, int size, MessageHandler* message_handler) {
+    file_helper_.StartTimer();
     int ret = fread(buf, 1, size, file_helper_.file_);
     file_helper_.CountNewlines(buf, ret);
     if ((ret == 0) && (ferror(file_helper_.file_) != 0)) {
       file_helper_.ReportError(message_handler, "reading file: %s");
     }
+    file_helper_.EndTimer("read");
     return ret;
   }
 
@@ -129,18 +149,20 @@ class StdioInputFile : public FileSystem::InputFile {
 
 class StdioOutputFile : public FileSystem::OutputFile {
  public:
-  StdioOutputFile(FILE* f, const StringPiece& filename)
-      : file_helper_(f, filename) {
+  StdioOutputFile(FILE* f, const StringPiece& filename, StdioFileSystem* fs)
+      : file_helper_(f, filename, fs) {
   }
 
   virtual bool Write(const StringPiece& buf, MessageHandler* handler) {
+    file_helper_.StartTimer();
     size_t bytes_written =
         fwrite(buf.data(), 1, buf.size(), file_helper_.file_);
     file_helper_.CountNewlines(buf.data(), bytes_written);
     bool ret = (bytes_written == buf.size());
     if (!ret) {
       file_helper_.ReportError(handler, "writing file: %s");
     }
+    file_helper_.EndTimer("write");
     return ret;
   }
 
@@ -180,9 +202,69 @@ class StdioOutputFile : public FileSystem::OutputFile {
   DISALLOW_COPY_AND_ASSIGN(StdioOutputFile);
 };
 
+StdioFileSystem::StdioFileSystem()
+    : slow_file_latency_threshold_us_(0),
+      timer_(NULL),
+      statistics_(NULL),
+      outstanding_ops_(NULL),
+      slow_ops_(NULL),
+      total_ops_(NULL) {
+}
+
 StdioFileSystem::~StdioFileSystem() {
 }
 
+void StdioFileSystem::InitStats(Statistics* stats) {
+  stats->AddUpDownCounter(kOutstandingOps);
+  stats->AddVariable(kSlowOps);
+  stats->AddVariable(kTotalOps);
+}
+
+void StdioFileSystem::TrackTiming(int64 slow_file_latency_threshold_us,
+                                  Timer* timer, Statistics* stats,
+                                  MessageHandler* handler) {
+  slow_file_latency_threshold_us_ = slow_file_latency_threshold_us;
+  timer_ = timer;
+  statistics_ = stats;
+  outstanding_ops_ = stats->GetUpDownCounter(kOutstandingOps);
+  slow_ops_ = stats->GetVariable(kSlowOps);
+  total_ops_ = stats->GetVariable(kTotalOps);
+  message_handler_ = handler;
+}
+
+int64 StdioFileSystem::StartTimer() {
+  if (timer_ == NULL) {
+    return 0;
+  }
+  if (outstanding_ops_ != NULL) {
+    outstanding_ops_->Add(1);
+  }
+  if (total_ops_ != NULL) {
+    total_ops_->Add(1);
+  }
+  return timer_->NowUs();
+}
+
+void StdioFileSystem::EndTimer(const char* filename, const char* operation,
+                               int64 start_us) {
+  if (outstanding_ops_ != NULL) {
+    outstanding_ops_->Add(-1);
+  }
+  if (timer_ != NULL) {
+    int64 end_us = timer_->NowUs();
+    int64 latency_us = end_us - start_us;
+    if (latency_us > slow_file_latency_threshold_us_) {
+      if (slow_ops_ != NULL) {
+        slow_ops_->Add(1);
+      }
+      message_handler_->Message(
+          kError, "Slow %s operation on file %s: %gms; "
+          "configure SlowFileLatencyUs to change threshold\n",
+          operation, filename, latency_us / 1000.0);
+    }
+  }
+}
+
 int StdioFileSystem::MaxPathLength(const StringPiece& base) const {
 #ifdef WIN32
   return MAX_PATH;
@@ -210,7 +292,7 @@ FileSystem::InputFile* StdioFileSystem::OpenInputFile(
     message_handler->Error(filename, 0, "opening input file: %s",
                            strerror(errno));
   } else {
-    input_file = new StdioInputFile(f, filename);
+    input_file = new StdioInputFile(f, filename, this);
   }
   return input_file;
 }
@@ -220,15 +302,15 @@ FileSystem::OutputFile* StdioFileSystem::OpenOutputFileHelper(
     const char* filename, bool append, MessageHandler* message_handler) {
   FileSystem::OutputFile* output_file = NULL;
   if (strcmp(filename, "-") == 0) {
-    output_file = new StdioOutputFile(stdout, "<stdout>");
+    output_file = new StdioOutputFile(stdout, "<stdout>", this);
   } else {
     const char* mode = append ? "a" : "w";
     FILE* f = fopen(filename, mode);
     if (f == NULL) {
       message_handler->Error(filename, 0,
                              "opening output file: %s", strerror(errno));
     } else {
-      output_file = new StdioOutputFile(f, filename);
+      output_file = new StdioOutputFile(f, filename, this);
     }
   }
   return output_file;
@@ -274,7 +356,7 @@ FileSystem::OutputFile* StdioFileSystem::OpenTempFileHelper(
       NullMessageHandler null_message_handler;
       RemoveFile(template_name, &null_message_handler);
     } else {
-      output_file = new StdioOutputFile(f, template_name);
+      output_file = new StdioOutputFile(f, template_name, this);
     }
   }
 
@@ -561,15 +643,15 @@ bool StdioFileSystem::Unlock(const StringPiece& lock_name,
 }
 
 FileSystem::InputFile* StdioFileSystem::Stdin() {
-  return new StdioInputFile(stdin, "stdin");
+  return new StdioInputFile(stdin, "stdin", this);
 }
 
 FileSystem::OutputFile* StdioFileSystem::Stdout() {
-  return new StdioOutputFile(stdout, "stdout");
+  return new StdioOutputFile(stdout, "stdout", this);
 }
 
 FileSystem::OutputFile* StdioFileSystem::Stderr() {
-  return new StdioOutputFile(stderr, "stderr");
+  return new StdioOutputFile(stderr, "stderr", this);
 }
 
 }  // namespace net_instaweb

pagespeed/kernel/base/stdio_file_system.h

@@ -21,6 +21,7 @@
 
 #include "pagespeed/kernel/base/basictypes.h"
 #include "pagespeed/kernel/base/file_system.h"
+#include "pagespeed/kernel/base/statistics.h"
 #include "pagespeed/kernel/base/string_util.h"
 
 struct stat;
@@ -32,7 +33,7 @@ class Timer;
 
 class StdioFileSystem : public FileSystem {
  public:
-  StdioFileSystem() {}
+  StdioFileSystem();
   virtual ~StdioFileSystem();
 
   virtual int MaxPathLength(const StringPiece& base) const;
@@ -78,11 +79,26 @@ class StdioFileSystem : public FileSystem {
   OutputFile* Stdout();
   OutputFile* Stderr();
 
+  static void InitStats(Statistics* stats);
+  void TrackTiming(int64 slow_file_latency_threshold_us, Timer* timer,
+                   Statistics* stats, MessageHandler* handler);
+
+  int64 StartTimer();
+  void EndTimer(const char* filename, const char* operation, int64 start_us);
+
  private:
   // Used by *time and Size methods to get file info.
   bool Stat(const StringPiece& path, struct stat* statbuf,
             MessageHandler* handler);
 
+  int64 slow_file_latency_threshold_us_;
+  Timer* timer_;
+  Statistics* statistics_;
+  UpDownCounter* outstanding_ops_;
+  Variable* slow_ops_;
+  Variable* total_ops_;
+  MessageHandler* message_handler_;  // Only set by TrackTiming, not by ctor.
+
   DISALLOW_COPY_AND_ASSIGN(StdioFileSystem);
 };
 

pagespeed/system/system_rewrite_driver_factory.cc

@@ -188,6 +188,7 @@ void SystemRewriteDriverFactory::InitStats(Statistics* statistics) {
 
   // Init System-specific stats.
   SerfUrlAsyncFetcher::InitStats(statistics);
+  StdioFileSystem::InitStats(statistics);
   SystemCaches::InitStats(statistics);
   PropertyCache::InitCohortStats(RewriteDriver::kBeaconCohort, statistics);
   PropertyCache::InitCohortStats(RewriteDriver::kDomCohort, statistics);
@@ -254,6 +255,18 @@ void SystemRewriteDriverFactory::RootInit() {
 }
 
 void SystemRewriteDriverFactory::ChildInit() {
+  const SystemRewriteOptions* conf =
+      SystemRewriteOptions::DynamicCast(default_options());
+  CHECK(conf != NULL);
+
+  StdioFileSystem* fs = dynamic_cast<StdioFileSystem*>(file_system());
+  DCHECK(fs != NULL) << "Expected StdioFileSystem so we can call TrackTiming";
+  if (fs != NULL) {
+    fs->TrackTiming(conf->slow_file_latency_threshold_us(),
+                    timer(), statistics(),
+                    message_handler());
+  }
+
   is_root_process_ = false;
   system_thread_system_->PermitThreadStarting();
 
@@ -268,9 +281,6 @@ void SystemRewriteDriverFactory::ChildInit() {
   caches_->ChildInit();
 
   // Static asset config is process-global.
-  const SystemRewriteOptions* conf =
-      SystemRewriteOptions::DynamicCast(default_options());
-  CHECK(conf != NULL);
   if (conf->has_static_assets_to_cdn()) {
     StaticAssetConfig out_conf;
     conf->FillInStaticAssetCDNConf(&out_conf);

pagespeed/system/system_rewrite_options.cc

@@ -92,6 +92,11 @@ void SystemRewriteOptions::AddProperties() {
                     RewriteOptions::kMemcachedTimeoutUs,
                     "Maximum time in microseconds to allow for memcached "
                         "transactions", true);
+  AddSystemProperty(50 * Timer::kMsUs,  // 50 ms
+                    &SystemRewriteOptions::slow_file_latency_threshold_us_,
+                    "asflt", "SlowFileLatencyUs",
+                    "Maximum time in microseconds to allow for file operations "
+                        "before logging and bumping a stat", true);
   AddSystemProperty(true, &SystemRewriteOptions::statistics_enabled_, "ase",
                     RewriteOptions::kStatisticsEnabled,
                     "Whether to collect cross-process statistics.", true);

pagespeed/system/system_rewrite_options.h

@@ -153,6 +153,15 @@ class SystemRewriteOptions : public RewriteOptions {
   void set_memcached_timeout_us(int x) {
     set_option(x, &memcached_timeout_us_);
   }
+  int64 slow_file_latency_threshold_us() const {
+    return slow_file_latency_threshold_us_.value();
+  }
+  bool has_slow_file_latency_threshold_us() const {
+    return slow_file_latency_threshold_us_.was_set();
+  }
+  void set_slow_file_latency_threshold_us(int64 x) {
+    set_option(x, &slow_file_latency_threshold_us_);
+  }
   const GoogleString& fetcher_proxy() const {
     return fetcher_proxy_.value();
   }
@@ -392,6 +401,7 @@ class SystemRewriteOptions : public RewriteOptions {
   Option<int> memcached_threads_;
   Option<int> memcached_timeout_us_;
 
+  Option<int64> slow_file_latency_threshold_us_;
   Option<int64> file_cache_clean_inode_limit_;
   Option<int64> file_cache_clean_interval_ms_;
   Option<int64> file_cache_clean_size_kb_;