Bug 1411391: Ensure mscom::InterceptorLog covers time spent wrapping outparams in mscom::MainThreadHandoff; r=jimm
authorAaron Klotz <aklotz@mozilla.com>
Mon, 23 Oct 2017 16:55:26 -0600
changeset 442756 4f4b24520f839dffc690af703b8c2cb56194b82a
parent 442755 0341d179a4baf5dab1d47c603bf4d5150b59c949
child 442757 2aaa2d20e7aa91fc941973dbd6a1850c2ec0e5c7
push id1618
push userCallek@gmail.com
push dateThu, 11 Jan 2018 17:45:48 +0000
treeherdermozilla-release@882ca853e05a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjimm
bugs1411391
milestone58.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1411391: Ensure mscom::InterceptorLog covers time spent wrapping outparams in mscom::MainThreadHandoff; r=jimm MozReview-Commit-ID: 8529IjAXZcb
ipc/mscom/InterceptorLog.cpp
ipc/mscom/InterceptorLog.h
ipc/mscom/MainThreadHandoff.cpp
--- a/ipc/mscom/InterceptorLog.cpp
+++ b/ipc/mscom/InterceptorLog.cpp
@@ -4,16 +4,17 @@
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "mozilla/mscom/InterceptorLog.h"
 
 #include "MainThreadUtils.h"
 #include "mozilla/ClearOnShutdown.h"
 #include "mozilla/DebugOnly.h"
+#include "mozilla/Move.h"
 #include "mozilla/mscom/Registration.h"
 #include "mozilla/mscom/Utils.h"
 #include "mozilla/Mutex.h"
 #include "mozilla/Services.h"
 #include "mozilla/StaticPtr.h"
 #include "mozilla/TimeStamp.h"
 #include "mozilla/Unused.h"
 #include "nsAppDirectoryServiceDefs.h"
@@ -31,16 +32,17 @@
 #include "prenv.h"
 
 #include <callobj.h>
 
 using mozilla::DebugOnly;
 using mozilla::mscom::ArrayData;
 using mozilla::mscom::FindArrayData;
 using mozilla::mscom::IsValidGUID;
+using mozilla::Move;
 using mozilla::Mutex;
 using mozilla::MutexAutoLock;
 using mozilla::NewNonOwningRunnableMethod;
 using mozilla::services::GetObserverService;
 using mozilla::StaticAutoPtr;
 using mozilla::TimeDuration;
 using mozilla::TimeStamp;
 using mozilla::Unused;
@@ -54,29 +56,31 @@ public:
   NS_DECL_NSIOBSERVER
 
 private:
   ~ShutdownEvent() {}
 };
 
 NS_IMPL_ISUPPORTS(ShutdownEvent, nsIObserver)
 
-class Logger
+class Logger final
 {
 public:
   explicit Logger(const nsACString& aLeafBaseName);
   bool IsValid()
   {
     MutexAutoLock lock(mMutex);
     return !!mThread;
   }
   void LogQI(HRESULT aResult, IUnknown* aTarget, REFIID aIid,
              IUnknown* aInterface, const TimeDuration* aOverheadDuration,
              const TimeDuration* aGeckoDuration);
-  void LogEvent(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
+  void CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
+                    nsACString& aCapturedFrame);
+  void LogEvent(const nsACString& aCapturedFrame,
                 const TimeDuration& aOverheadDuration,
                 const TimeDuration& aGeckoDuration);
   nsresult Shutdown();
 
 private:
   void OpenFile();
   void Flush();
   void CloseFile();
@@ -300,17 +304,17 @@ Logger::LogQI(HRESULT aResult, IUnknown*
   if (StringFromGUID2(aIid, buf, mozilla::ArrayLength(buf))) {
     line.AppendPrintf("%S", buf);
   } else {
     line.AppendLiteral("(IID Conversion Failed)");
   }
   line.AppendPrintf(", [out] 0x%p)\t0x%08X\n", aInterface, aResult);
 
   MutexAutoLock lock(mMutex);
-  mEntries.AppendElement(line);
+  mEntries.AppendElement(Move(line));
   mThread->Dispatch(NewNonOwningRunnableMethod("Logger::Flush",
                                                this, &Logger::Flush),
                     NS_DISPATCH_NORMAL);
 }
 
 bool
 Logger::TryParamAsGuid(REFIID aIid, ICallFrame* aCallFrame,
                        const CALLFRAMEPARAMINFO& aParamInfo, nsACString& aLine)
@@ -332,41 +336,38 @@ Logger::TryParamAsGuid(REFIID aIid, ICal
     return false;
   }
 
   aLine.AppendPrintf("%S", buf);
   return true;
 }
 
 void
-Logger::LogEvent(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
-                 const TimeDuration& aOverheadDuration,
-                 const TimeDuration& aGeckoDuration)
+Logger::CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
+                     nsACString& aCapturedFrame)
 {
+  aCapturedFrame.Truncate();
+
   // (1) Gather info about the call
-  double elapsed = GetElapsedTime();
-
   CALLFRAMEINFO callInfo;
   HRESULT hr = aCallFrame->GetInfo(&callInfo);
   if (FAILED(hr)) {
     return;
   }
 
   PWSTR interfaceName = nullptr;
   PWSTR methodName = nullptr;
   hr = aCallFrame->GetNames(&interfaceName, &methodName);
   if (FAILED(hr)) {
     return;
   }
 
   // (2) Serialize the call
-  nsPrintfCString line("%.3f\t%.3f\t%.3f\t0x%p\t%S::%S\t(", elapsed,
-                       aOverheadDuration.ToMicroseconds(),
-                       aGeckoDuration.ToMicroseconds(),
-                       aTargetInterface, interfaceName, methodName);
+  nsPrintfCString line("0x%p\t%S::%S\t(", aTargetInterface, interfaceName,
+                       methodName);
 
   CoTaskMemFree(interfaceName);
   interfaceName = nullptr;
   CoTaskMemFree(methodName);
   methodName = nullptr;
 
   // Check for supplemental array data
   const ArrayData* arrayData = FindArrayData(callInfo.iid, callInfo.iMethod);
@@ -413,17 +414,31 @@ Logger::LogEvent(ICallFrame* aCallFrame,
       line.AppendLiteral(", ");
     }
   }
   line.AppendLiteral(")\t");
 
   HRESULT callResult = aCallFrame->GetReturnValue();
   line.AppendPrintf("0x%08X\n", callResult);
 
-  // (3) Enqueue event for logging
+  aCapturedFrame = Move(line);
+}
+
+void
+Logger::LogEvent(const nsACString& aCapturedFrame,
+                 const TimeDuration& aOverheadDuration,
+                 const TimeDuration& aGeckoDuration)
+{
+  double elapsed = GetElapsedTime();
+
+  nsPrintfCString line("%.3f\t%.3f\t%.3f\t%s", elapsed,
+                       aOverheadDuration.ToMicroseconds(),
+                       aGeckoDuration.ToMicroseconds(),
+                       PromiseFlatCString(aCapturedFrame).get());
+
   MutexAutoLock lock(mMutex);
   mEntries.AppendElement(line);
   mThread->Dispatch(NewNonOwningRunnableMethod("Logger::Flush",
                                                this, &Logger::Flush),
                     NS_DISPATCH_NORMAL);
 }
 
 void
@@ -509,22 +524,31 @@ InterceptorLog::QI(HRESULT aResult, IUnk
   if (!sLogger) {
     return;
   }
   sLogger->LogQI(aResult, aTarget, aIid, aInterface, aOverheadDuration,
                  aGeckoDuration);
 }
 
 /* static */ void
-InterceptorLog::Event(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
+InterceptorLog::CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
+                             nsACString& aCapturedFrame)
+{
+  if (!sLogger) {
+    return;
+  }
+  sLogger->CaptureFrame(aCallFrame, aTargetInterface, aCapturedFrame);
+}
+
+/* static */ void
+InterceptorLog::Event(const nsACString& aCapturedFrame,
                       const TimeDuration& aOverheadDuration,
                       const TimeDuration& aGeckoDuration)
 {
   if (!sLogger) {
     return;
   }
-  sLogger->LogEvent(aCallFrame, aTargetInterface, aOverheadDuration,
-                    aGeckoDuration);
+  sLogger->LogEvent(aCapturedFrame, aOverheadDuration, aGeckoDuration);
 }
 
 } // namespace mscom
 } // namespace mozilla
 
--- a/ipc/mscom/InterceptorLog.h
+++ b/ipc/mscom/InterceptorLog.h
@@ -3,32 +3,35 @@
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #ifndef mozilla_mscom_InterceptorLog_h
 #define mozilla_mscom_InterceptorLog_h
 
 #include "mozilla/TimeStamp.h"
+#include "nsString.h"
 
 struct ICallFrame;
 struct IUnknown;
 
 namespace mozilla {
 namespace mscom {
 
 class InterceptorLog
 {
 public:
   static bool Init();
   static void QI(HRESULT aResult, IUnknown* aTarget, REFIID aIid,
                  IUnknown* aInterface,
                  const TimeDuration* aOverheadDuration = nullptr,
                  const TimeDuration* aGeckoDuration = nullptr);
-  static void Event(ICallFrame* aCallFrame, IUnknown* aTarget,
+  static void CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTarget,
+                           nsACString& aCapturedFrame);
+  static void Event(const nsACString& aCapturedFrame,
                     const TimeDuration& aOverheadDuration,
                     const TimeDuration& aGeckoDuration);
 };
 
 } // namespace mscom
 } // namespace mozilla
 
 #endif // mozilla_mscom_InterceptorLog_h
--- a/ipc/mscom/MainThreadHandoff.cpp
+++ b/ipc/mscom/MainThreadHandoff.cpp
@@ -197,16 +197,65 @@ private:
   ICallFrame* mCallFrame;
 
 private:
   static MOZ_THREAD_LOCAL(SavedCallFrame*) tlsFrame;
 };
 
 MOZ_THREAD_LOCAL(SavedCallFrame*) SavedCallFrame::tlsFrame;
 
+class MOZ_RAII LogEvent final
+{
+public:
+  LogEvent()
+    : mCallStart(mozilla::TimeStamp::Now())
+  {
+  }
+
+  ~LogEvent()
+  {
+    if (mCapturedFrame.IsEmpty()) {
+      return;
+    }
+
+    mozilla::TimeStamp callEnd(TimeStamp::Now());
+    mozilla::TimeDuration totalTime(callEnd - mCallStart);
+    mozilla::TimeDuration overhead(totalTime - mGeckoDuration - mCaptureDuration);
+
+    mozilla::mscom::InterceptorLog::Event(mCapturedFrame, overhead,
+                                          mGeckoDuration);
+  }
+
+  void CaptureFrame(ICallFrame* aFrame, IUnknown* aTarget,
+                    const mozilla::TimeDuration& aGeckoDuration)
+  {
+    mozilla::TimeStamp captureStart(TimeStamp::Now());
+
+    mozilla::mscom::InterceptorLog::CaptureFrame(aFrame, aTarget, mCapturedFrame);
+    mGeckoDuration = aGeckoDuration;
+
+    mozilla::TimeStamp captureEnd(TimeStamp::Now());
+
+    // Make sure that the time we spent in CaptureFrame isn't charged against
+    // overall overhead
+    mCaptureDuration = captureEnd - captureStart;
+  }
+
+  LogEvent(const LogEvent&) = delete;
+  LogEvent(LogEvent&&) = delete;
+  LogEvent& operator=(const LogEvent&) = delete;
+  LogEvent& operator=(LogEvent&&) = delete;
+
+private:
+  mozilla::TimeStamp    mCallStart;
+  mozilla::TimeDuration mGeckoDuration;
+  mozilla::TimeDuration mCaptureDuration;
+  nsAutoCString         mCapturedFrame;
+};
+
 } // anonymous namespace
 
 namespace mozilla {
 namespace mscom {
 
 /* static */ HRESULT
 MainThreadHandoff::Create(IHandlerProvider* aHandlerProvider,
                           IInterceptorSink** aOutput)
@@ -306,17 +355,17 @@ MainThreadHandoff::FixIServiceProvider(I
   return OnWalkInterface(**iidOutParam,
                          reinterpret_cast<void**>(varIfaceOut.ppunkVal), FALSE,
                          TRUE);
 }
 
 HRESULT
 MainThreadHandoff::OnCall(ICallFrame* aFrame)
 {
-  TimeStamp callStart(TimeStamp::Now());
+  LogEvent logEvent;
 
   // (1) Get info about the method call
   HRESULT hr;
   IID iid;
   ULONG method;
   hr = aFrame->GetIIDAndMethod(&iid, &method);
   if (FAILED(hr)) {
     return hr;
@@ -344,24 +393,19 @@ MainThreadHandoff::OnCall(ICallFrame* aF
     return E_UNEXPECTED;
   }
   hr = handoffInfo->GetResult();
   MOZ_ASSERT(SUCCEEDED(hr));
   if (FAILED(hr)) {
     return hr;
   }
 
-  TimeStamp callEnd(TimeStamp::Now());
-  TimeDuration totalTime(callEnd - callStart);
-  TimeDuration overhead(totalTime - invoker.GetDuration());
-
-  // (3) Log *before* wrapping outputs so that the log will contain pointers to
-  // the true target interface, not the wrapped ones.
-  InterceptorLog::Event(aFrame, targetInterface.get(), overhead,
-                        invoker.GetDuration());
+  // (3) Capture *before* wrapping outputs so that the log will contain pointers
+  // to the true target interface, not the wrapped ones.
+  logEvent.CaptureFrame(aFrame, targetInterface.get(), invoker.GetDuration());
 
   // (4) Scan the function call for outparams that contain interface pointers.
   // Those will need to be wrapped with MainThreadHandoff so that they too will
   // be exeuted on the main thread.
 
   hr = aFrame->GetReturnValue();
   if (FAILED(hr)) {
     // If the call resulted in an error then there's not going to be anything