Bug 522375 - built-in startup time measurement r=vlad a=Mossop

browser/components/sessionstore/test/browser/Makefile.in

@@ -134,6 +134,7 @@ _BROWSER_TEST_FILES = \
 	browser_607016.js \
 	browser_615394-SSWindowState_events.js \
 	browser_618151.js \
+	browser_522375.js \
 	$(NULL)
 
 ifneq ($(OS_ARCH),Darwin)

browser/components/sessionstore/test/browser/browser_522375.js

@@ -0,0 +1,13 @@
+function test() {
+  waitForExplicitFinish();
+  var startup_info = Components.classes["@mozilla.org/toolkit/app-startup;1"].getService(Components.interfaces.nsIAppStartup_MOZILLA_2_0).getStartupInfo();
+  // No .process info on mac
+  is(startup_info.process <= startup_info.main, true, "process created before main is run " + uneval(startup_info));
+
+  // on linux firstPaint can happen after everything is loaded (especially with remote X)
+  if (startup_info.firstPaint)
+    is(startup_info.main <= startup_info.firstPaint, true, "main ran before first paint " + uneval(startup_info));
+
+  is(startup_info.main < startup_info.sessionRestored, true, "Session restored after main " + uneval(startup_info));
+  finish();
+}

toolkit/components/startup/public/nsIAppStartup.idl

@@ -123,6 +123,16 @@ interface nsIAppStartup2 : nsIAppStartup
     readonly attribute boolean shuttingDown;
 };
 
+[scriptable, uuid(2e8c45b0-1ac1-11e0-ac64-0800200c9a66)]
+interface nsIAppStartup_MOZILLA_2_0 : nsIAppStartup2
+{
+    /** 
+     * Returns an object with main, process, firstPaint, sessionRestored properties.
+     * Properties may not be available depending on platform or application
+     */
+    void getStartupInfo();
+};
+
 %{C++
 /**
  * This success code may be returned by nsIAppStartup::Run to indicate that the

toolkit/components/startup/src/nsAppStartup.cpp

@@ -24,6 +24,8 @@
  *   Pierre Phaneuf <pp@ludusdesign.com>
  *   Robert O'Callahan <roc+moz@cs.cmu.edu>
  *   Benjamin Smedberg <bsmedberg@covad.net>
+ *   Daniel Brooks <db48x@db48x.net>
+ *   Taras Glek <tglek@mozilla.com>
  *
  * Alternatively, the contents of this file may be used under the terms of
  * either of the GNU General Public License Version 2 or later (the "GPL"),
@@ -69,10 +71,30 @@
 #include "nsWidgetsCID.h"
 #include "nsAppShellCID.h"
 #include "mozilla/Services.h"
-
 #include "mozilla/FunctionTimer.h"
+#include "nsIXPConnect.h"
+#include "jsapi.h"
+#include "jsdate.h"
+
+#if defined(XP_WIN)
+#include <windows.h>
+// windows.h can go to hell 
+#undef GetStartupInfo
+#elif defined(XP_UNIX)
+#include <unistd.h>
+#include <sys/syscall.h>
+#endif
+
+#ifdef XP_MACOSX
+#include <sys/sysctl.h>
+#endif
 
 static NS_DEFINE_CID(kAppShellCID, NS_APPSHELL_CID);
+extern PRTime gXRE_mainTimestamp;
+extern PRTime gFirstPaintTimestamp;
+// mfinklesessionstore-browser-state-restored might be a better choice than the one below
+static PRTime gRestoredTimestamp = 0;       // Timestamp of sessionstore-windows-restored
+static PRTime gProcessCreationTimestamp = 0;// Timestamp of sessionstore-windows-restored
 
 class nsAppExitEvent : public nsRunnable {
 private:
@@ -125,6 +147,7 @@ nsAppStartup::Init()
   NS_TIME_FUNCTION_MARK("Got Observer service");
 
   os->AddObserver(this, "quit-application-forced", PR_TRUE);
+  os->AddObserver(this, "sessionstore-windows-restored", PR_TRUE);
   os->AddObserver(this, "profile-change-teardown", PR_TRUE);
   os->AddObserver(this, "xul-window-registered", PR_TRUE);
   os->AddObserver(this, "xul-window-destroyed", PR_TRUE);
@@ -137,9 +160,10 @@ nsAppStartup::Init()
 // nsAppStartup->nsISupports
 //
 
-NS_IMPL_THREADSAFE_ISUPPORTS6(nsAppStartup,
+NS_IMPL_THREADSAFE_ISUPPORTS7(nsAppStartup,
                               nsIAppStartup,
                               nsIAppStartup2,
+                              nsIAppStartup_MOZILLA_2_0,
                               nsIWindowCreator,
                               nsIWindowCreator2,
                               nsIObserver,
@@ -508,9 +532,161 @@ nsAppStartup::Observe(nsISupports *aSubject,
     EnterLastWindowClosingSurvivalArea();
   } else if (!strcmp(aTopic, "xul-window-destroyed")) {
     ExitLastWindowClosingSurvivalArea();
+  } else if (!strcmp(aTopic, "sessionstore-windows-restored")) {
+    gRestoredTimestamp = PR_Now();
   } else {
     NS_ERROR("Unexpected observer topic.");
   }
 
   return NS_OK;
 }
+
+#if defined(LINUX) || defined(ANDROID)
+static PRUint64 
+JiffiesSinceBoot(const char *file)
+{
+  char stat[512];
+  FILE *f = fopen(file, "r");
+  if (!f)
+    return 0;
+  int n = fread(&stat, 1, sizeof(stat) - 1, f);
+  fclose(f);
+  if (n <= 0)
+    return 0;
+  stat[n] = 0;
+  
+  long long unsigned starttime = 0; // instead of PRUint64 to keep GCC quiet
+  
+  char *s = strrchr(stat, ')');
+  if (!s)
+    return 0;
+  sscanf(s + 2,
+         "%*c %*d %*d %*d %*d %*d %*u %*u %*u %*u "
+         "%*u %*u %*u %*u %*u %*d %*d %*d %*d %llu",
+         &starttime);
+  if (!starttime)
+    return 0;
+  return starttime;
+}
+
+static void
+ThreadedCalculateProcessCreationTimestamp(void *aClosure)
+{
+  PRTime now = PR_Now();
+  gProcessCreationTimestamp = 0;
+  long hz = sysconf(_SC_CLK_TCK);
+  if (!hz)
+    return;
+
+  char thread_stat[40];
+  sprintf(thread_stat, "/proc/self/task/%d/stat", (pid_t) syscall(__NR_gettid));
+  
+  PRTime interval = (JiffiesSinceBoot(thread_stat) - JiffiesSinceBoot("/proc/self/stat")) * PR_USEC_PER_SEC / hz;;
+  gProcessCreationTimestamp = now - interval;
+}
+
+static PRTime
+CalculateProcessCreationTimestamp()
+{
+ PRThread *thread = PR_CreateThread(PR_USER_THREAD,
+                                    ThreadedCalculateProcessCreationTimestamp,
+                                    NULL,
+                                    PR_PRIORITY_NORMAL,
+                                    PR_LOCAL_THREAD,
+                                    PR_JOINABLE_THREAD,
+                                    0);
+
+  PR_JoinThread(thread);
+  return gProcessCreationTimestamp;
+}
+#elif defined(XP_WIN)
+static PRTime
+CalculateProcessCreationTimestamp()
+{
+  FILETIME start, foo, bar, baz;
+  bool success = GetProcessTimes(GetCurrentProcess(), &start, &foo, &bar, &baz);
+  if (!success)
+    return 0;
+  // copied from NSPR _PR_FileTimeToPRTime
+  PRUint64 timestamp = 0;
+  CopyMemory(&timestamp, &start, sizeof(PRTime));
+#ifdef __GNUC__
+  timestamp = (timestamp - 116444736000000000LL) / 10LL;
+#else
+  timestamp = (timestamp - 116444736000000000i64) / 10i64;
+#endif    
+  return timestamp;
+}
+#elif defined(XP_MACOSX)
+static PRTime
+CalculateProcessCreationTimestamp()
+{
+  int mib[4] = { CTL_KERN, KERN_PROC, KERN_PROC_PID, getpid() };
+  size_t buffer_size;
+  if (sysctl(mib, 4, NULL, &buffer_size, NULL, 0))
+    return 0;
+
+  struct kinfo_proc *proc = (kinfo_proc*) malloc(buffer_size);  
+  if (sysctl(mib, 4, proc, &buffer_size, NULL, 0)) {
+    free(proc);
+    return 0;
+  }
+  PRTime starttime = proc->kp_proc.p_un.__p_starttime.tv_sec * PR_USEC_PER_SEC;
+  starttime += proc->kp_proc.p_un.__p_starttime.tv_usec;
+  free(proc);
+  return starttime;
+}
+#else
+static PRTime
+CalculateProcessCreationTimestamp()
+{
+  return 0;
+}
+#endif
+ 
+static void
+MaybeDefineProperty(JSContext *cx, JSObject *obj, const char *name, PRTime timestamp)
+{
+  if (!timestamp)
+    return;
+  JSObject *date = js_NewDateObjectMsec(cx, timestamp/PR_USEC_PER_MSEC);
+  JS_DefineProperty(cx, obj, name, OBJECT_TO_JSVAL(date), NULL, NULL, JSPROP_ENUMERATE);     
+}
+
+NS_IMETHODIMP
+nsAppStartup::GetStartupInfo()
+{
+  nsAXPCNativeCallContext *ncc = nsnull;
+  nsresult rv;
+  nsCOMPtr<nsIXPConnect> xpConnect = do_GetService(nsIXPConnect::GetCID(), &rv);
+  NS_ENSURE_SUCCESS(rv, rv);
+
+  rv = xpConnect->GetCurrentNativeCallContext(&ncc);
+  NS_ENSURE_SUCCESS(rv, rv);
+
+  if (!ncc)
+    return NS_ERROR_FAILURE;
+
+  jsval *retvalPtr;
+  ncc->GetRetValPtr(&retvalPtr);
+
+  *retvalPtr = JSVAL_NULL;
+  ncc->SetReturnValueWasSet(PR_TRUE);
+
+  JSContext *cx = nsnull;
+  rv = ncc->GetJSContext(&cx);
+  NS_ENSURE_SUCCESS(rv, rv);
+
+  JSObject *obj = JS_NewObject(cx, NULL, NULL, NULL);
+  *retvalPtr = OBJECT_TO_JSVAL(obj);
+  ncc->SetReturnValueWasSet(PR_TRUE);
+
+  if (!gProcessCreationTimestamp)
+    gProcessCreationTimestamp = CalculateProcessCreationTimestamp();
+
+  MaybeDefineProperty(cx, obj, "process", gProcessCreationTimestamp);
+  MaybeDefineProperty(cx, obj, "main", gXRE_mainTimestamp);
+  MaybeDefineProperty(cx, obj, "firstPaint", gFirstPaintTimestamp);
+  MaybeDefineProperty(cx, obj, "sessionRestored", gRestoredTimestamp);
+  return NS_OK;
+}

toolkit/components/startup/src/nsAppStartup.h

@@ -55,7 +55,7 @@ struct PLEvent;
 { 0x7dd4d320, 0xc84b, 0x4624, { 0x8d, 0x45, 0x7b, 0xb9, 0xb2, 0x35, 0x69, 0x77 } }
 
 
-class nsAppStartup : public nsIAppStartup2,
+class nsAppStartup : public nsIAppStartup_MOZILLA_2_0,
                      public nsIWindowCreator2,
                      public nsIObserver,
                      public nsSupportsWeakReference
@@ -64,6 +64,7 @@ public:
   NS_DECL_ISUPPORTS
   NS_DECL_NSIAPPSTARTUP
   NS_DECL_NSIAPPSTARTUP2
+  NS_DECL_NSIAPPSTARTUP_MOZILLA_2_0
   NS_DECL_NSIWINDOWCREATOR
   NS_DECL_NSIWINDOWCREATOR2
   NS_DECL_NSIOBSERVER

toolkit/xre/nsAppRunner.cpp

@@ -2724,11 +2724,15 @@ NS_VISIBILITY_DEFAULT PRBool nspr_use_zone_allocator = PR_FALSE;
 typedef BOOL (WINAPI* SetProcessDEPPolicyFunc)(DWORD dwFlags);
 #endif
 
+PRTime gXRE_mainTimestamp = 0;
+
 int
 XRE_main(int argc, char* argv[], const nsXREAppData* aAppData)
 {
   NS_TIME_FUNCTION;
 
+  gXRE_mainTimestamp = PR_Now();
+
 #ifdef MOZ_SPLASHSCREEN
   nsSplashScreen *splashScreen = nsnull;
 #endif

view/src/nsViewManager.cpp

@@ -65,6 +65,7 @@
 
 static NS_DEFINE_IID(kRegionCID, NS_REGION_CID);
 
+PRTime gFirstPaintTimestamp = 0; // Timestamp of the first paint event
 /**
    XXX TODO XXX
 
@@ -951,6 +952,8 @@ NS_IMETHODIMP nsViewManager::DispatchEvent(nsGUIEvent *aEvent,
       }
 
     case NS_DID_PAINT: {
+      if (!gFirstPaintTimestamp)
+        gFirstPaintTimestamp = PR_Now();
       nsRefPtr<nsViewManager> rootVM = RootViewManager();
       rootVM->CallDidPaintOnObservers();
       break;