xpcom/build/MainThreadIOLogger.cpp

   1 /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
   2 /* vim: set ts=8 sts=2 et sw=2 tw=80: */
   3 /* This Source Code Form is subject to the terms of the Mozilla Public
   4  * License, v. 2.0. If a copy of the MPL was not distributed with this
   5  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
   6
   7 #include "MainThreadIOLogger.h"
   8
   9 #include "GeckoProfiler.h"
  10 #include "IOInterposerPrivate.h"
  11 #include "mozilla/IOInterposer.h"
  12 #include "mozilla/StaticPtr.h"
  13 #include "mozilla/TimeStamp.h"
  14 #include "nsAutoPtr.h"
  15
  16 /**
  17  * This code uses NSPR stuff and STL containers because it must be detached
  18  * from leak checking code; this observer runs until the process terminates.
  19  */
  20
  21 #include <prenv.h>
  22 #include <prprf.h>
  23 #include <prthread.h>
  24 #include <vector>
  25
  26 namespace {
  27
  28 struct ObservationWithStack
  29 {
  30   ObservationWithStack(mozilla::IOInterposeObserver::Observation& aObs,
  31                        ProfilerBacktrace *aStack)
  32     : mObservation(aObs)
  33     , mStack(aStack)
  34   {
  35     const char16_t* filename = aObs.Filename();
  36     if (filename) {
  37       mFilename = filename;
  38     }
  39   }
  40
  41   mozilla::IOInterposeObserver::Observation mObservation;
  42   ProfilerBacktrace*                        mStack;
  43   nsString                                  mFilename;
  44 };
  45
  46 } // anonymous namespace
  47
  48 namespace mozilla {
  49
  50 class MainThreadIOLoggerImpl MOZ_FINAL : public IOInterposeObserver
  51 {
  52 public:
  53   MainThreadIOLoggerImpl();
  54   ~MainThreadIOLoggerImpl();
  55
  56   bool Init();
  57
  58   void Observe(Observation& aObservation);
  59
  60 private:
  61   static void sIOThreadFunc(void* aArg);
  62   void IOThreadFunc();
  63
  64   TimeStamp             mLogStartTime;
  65   const char*           mFileName;
  66   PRThread*             mIOThread;
  67   IOInterposer::Monitor mMonitor;
  68   bool                  mShutdownRequired;
  69   std::vector<ObservationWithStack> mObservations;
  70 };
  71
  72 static StaticAutoPtr<MainThreadIOLoggerImpl> sImpl;
  73
  74 MainThreadIOLoggerImpl::MainThreadIOLoggerImpl()
  75   : mFileName(nullptr)
  76   , mIOThread(nullptr)
  77   , mShutdownRequired(false)
  78 {
  79 }
  80
  81 MainThreadIOLoggerImpl::~MainThreadIOLoggerImpl()
  82 {
  83   if (!mIOThread) {
  84     return;
  85   }
  86   { // Scope for lock
  87     IOInterposer::MonitorAutoLock lock(mMonitor);
  88     mShutdownRequired = true;
  89     lock.Notify();
  90   }
  91   PR_JoinThread(mIOThread);
  92   mIOThread = nullptr;
  93 }
  94
  95 bool
  96 MainThreadIOLoggerImpl::Init()
  97 {
  98   if (mFileName) {
  99     // Already initialized
 100     return true;
 101   }
 102   mFileName = PR_GetEnv("MOZ_MAIN_THREAD_IO_LOG");
 103   if (!mFileName) {
 104     // Can't start
 105     return false;
 106   }
 107   mIOThread = PR_CreateThread(PR_USER_THREAD, &sIOThreadFunc, this,
 108                               PR_PRIORITY_LOW, PR_GLOBAL_THREAD,
 109                               PR_JOINABLE_THREAD, 0);
 110   if (!mIOThread) {
 111     return false;
 112   }
 113   return true;
 114 }
 115
 116 /* static */ void
 117 MainThreadIOLoggerImpl::sIOThreadFunc(void* aArg)
 118 {
 119   PR_SetCurrentThreadName("MainThreadIOLogger");
 120   MainThreadIOLoggerImpl* obj = static_cast<MainThreadIOLoggerImpl*>(aArg);
 121   obj->IOThreadFunc();
 122 }
 123
 124 void
 125 MainThreadIOLoggerImpl::IOThreadFunc()
 126 {
 127   PRFileDesc* fd = PR_Open(mFileName, PR_WRONLY | PR_CREATE_FILE | PR_TRUNCATE,
 128                            PR_IRUSR | PR_IWUSR | PR_IRGRP);
 129   if (!fd) {
 130     IOInterposer::MonitorAutoLock lock(mMonitor);
 131     mShutdownRequired = true;
 132     std::vector<ObservationWithStack>().swap(mObservations);
 133     return;
 134   }
 135   mLogStartTime = TimeStamp::Now();
 136   { // Scope for lock
 137     IOInterposer::MonitorAutoLock lock(mMonitor);
 138     while (true) {
 139       while (!mShutdownRequired && mObservations.empty()) {
 140         lock.Wait();
 141       }
 142       if (mShutdownRequired) {
 143         break;
 144       }
 145       // Pull events off the shared array onto a local one
 146       std::vector<ObservationWithStack> observationsToWrite;
 147       observationsToWrite.swap(mObservations);
 148
 149       // Release the lock so that we're not holding anybody up during I/O
 150       IOInterposer::MonitorAutoUnlock unlock(mMonitor);
 151
 152       // Now write the events.
 153       for (std::vector<ObservationWithStack>::iterator
 154              i = observationsToWrite.begin(), e = observationsToWrite.end();
 155            i != e; ++i) {
 156         if (i->mObservation.ObservedOperation() == OpNextStage) {
 157           PR_fprintf(fd, "%f,NEXT-STAGE\n",
 158                      (TimeStamp::Now() - mLogStartTime).ToMilliseconds());
 159           continue;
 160         }
 161         double durationMs = i->mObservation.Duration().ToMilliseconds();
 162         nsAutoCString nativeFilename;
 163         nativeFilename.AssignLiteral("(not available)");
 164         if (!i->mFilename.IsEmpty()) {
 165           if (NS_FAILED(NS_CopyUnicodeToNative(i->mFilename, nativeFilename))) {
 166             nativeFilename.AssignLiteral("(conversion failed)");
 167           }
 168         }
 169         /**
 170          * Format:
 171          * Start Timestamp (Milliseconds), Operation, Duration (Milliseconds), Event Source, Filename
 172          */
 173         if (PR_fprintf(fd, "%f,%s,%f,%s,%s\n",
 174                        (i->mObservation.Start() - mLogStartTime).ToMilliseconds(),
 175                        i->mObservation.ObservedOperationString(), durationMs,
 176                        i->mObservation.Reference(), nativeFilename.get()) > 0) {
 177           ProfilerBacktrace* stack = i->mStack;
 178           if (stack) {
 179             // TODO: Write out the callstack
 180             //       (This will be added in a later bug)
 181             profiler_free_backtrace(stack);
 182           }
 183         }
 184       }
 185     }
 186   }
 187   PR_Close(fd);
 188 }
 189
 190 void
 191 MainThreadIOLoggerImpl::Observe(Observation& aObservation)
 192 {
 193   if (!mFileName || !IsMainThread()) {
 194     return;
 195   }
 196   IOInterposer::MonitorAutoLock lock(mMonitor);
 197   if (mShutdownRequired) {
 198     // The writer thread isn't running. Don't enqueue any more data.
 199     return;
 200   }
 201   // Passing nullptr as aStack parameter for now
 202   mObservations.push_back(ObservationWithStack(aObservation, nullptr));
 203   lock.Notify();
 204 }
 205
 206 namespace MainThreadIOLogger {
 207
 208 bool
 209 Init()
 210 {
 211   nsAutoPtr<MainThreadIOLoggerImpl> impl(new MainThreadIOLoggerImpl());
 212   if (!impl->Init()) {
 213     return false;
 214   }
 215   sImpl = impl.forget();
 216   IOInterposer::Register(IOInterposeObserver::OpAllWithStaging, sImpl);
 217   return true;
 218 }
 219
 220 } // namespace MainThreadIOLogger
 221
 222 } // namespace mozilla
 223