b=480735; add infrastructure for simple timeline logging; r=bsmedberg

configure.in

@@ -7216,6 +7216,19 @@ if test -n "$MOZ_TIMELINE"; then
     AC_DEFINE(MOZ_TIMELINE)
 fi
 
+dnl ========================================================
+dnl = Enable NS_FUNCTION_TIMER, which provides Function 
+dnl = timing for identifying code bottlenecks 
+dnl = NS_FUNCTION_TIMER is off by default.
+dnl ========================================================
+MOZ_ARG_ENABLE_BOOL(functiontimer,
+[  --enable-functiontimer       Enable NS_FUNCTION_TIMER ],
+    NS_FUNCTION_TIMER=1,
+    NS_FUNCTION_TIMER= )
+if test -n "$NS_FUNCTION_TIMER"; then
+    AC_DEFINE(NS_FUNCTION_TIMER)
+fi
+
 dnl ========================================================
 dnl Turn on reflow counting
 dnl ========================================================

xpcom/base/FunctionTimer.cpp

@@ -0,0 +1,123 @@
+/* -*- Mode: C++; tab-width: 40; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
+/* ***** BEGIN LICENSE BLOCK *****
+ * Version: MPL 1.1/GPL 2.0/LGPL 2.1
+ *
+ * The contents of this file are subject to the Mozilla Public License Version
+ * 1.1 (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ * http://www.mozilla.org/MPL/
+ *
+ * Software distributed under the License is distributed on an "AS IS" basis,
+ * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
+ * for the specific language governing rights and limitations under the
+ * License.
+ *
+ * The Original Code is Mozilla code.
+ *
+ * The Initial Developer of the Original Code is
+ * Mozilla Corporation.
+ * Portions created by the Initial Developer are Copyright (C) 2009
+ * the Initial Developer. All Rights Reserved.
+ *
+ * Contributor(s):
+ *   Vladimir Vukicevic <vladimir@pobox.com>
+ *
+ * Alternatively, the contents of this file may be used under the terms of
+ * either the GNU General Public License Version 2 or later (the "GPL"), or
+ * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
+ * in which case the provisions of the GPL or the LGPL are applicable instead
+ * of those above. If you wish to allow use of your version of this file only
+ * under the terms of either the GPL or the LGPL, and not to allow others to
+ * use your version of this file under the terms of the MPL, indicate your
+ * decision by deleting the provisions above and replace them with the notice
+ * and other provisions required by the GPL or the LGPL. If you do not delete
+ * the provisions above, a recipient may use your version of this file under
+ * the terms of any one of the MPL, the GPL or the LGPL.
+ *
+ * ***** END LICENSE BLOCK ***** */
+
+// needed to get vsnprintf with glibc
+#ifndef _ISOC99_SOURCE
+#define _ISOC99_SOURCE
+#endif
+
+#include <stdarg.h>
+#include <stdio.h>
+#include <string.h>
+
+#include "prenv.h"
+
+#include "mozilla/FunctionTimer.h"
+
+#ifdef _MSC_VER
+#define vsnprintf _vsnprintf
+#endif
+
+using namespace mozilla;
+
+FunctionTimerLog *FunctionTimer::sLog = nsnull;
+char *FunctionTimer::sBuf1 = nsnull;
+char *FunctionTimer::sBuf2 = nsnull;
+int FunctionTimer::sBufSize = FunctionTimer::InitTimers();
+
+int
+FunctionTimer::InitTimers()
+{
+    if (PR_GetEnv("MOZ_FT") == NULL)
+        return 0;
+
+    sLog = new FunctionTimerLog(PR_GetEnv("MOZ_FT"));
+    sBuf1 = (char *) malloc(BUF_LOG_LENGTH);
+    sBuf2 = (char *) malloc(BUF_LOG_LENGTH);
+
+    return BUF_LOG_LENGTH;
+}
+
+FunctionTimerLog::FunctionTimerLog(const char *fname)
+{
+    if (strcmp(fname, "stdout") == 0) {
+        mFile = stdout;
+    } else if (strcmp(fname, "stderr") == 0) {
+        mFile = stderr;
+    } else {
+        FILE *fp = fopen(fname, "wb");
+        if (!fp) {
+            NS_WARNING("FunctionTimerLog: Failed to open file specified, logging disabled!");
+        }
+        mFile = fp;
+    }
+}
+
+FunctionTimerLog::~FunctionTimerLog()
+{
+    if (mFile && mFile != stdout && mFile != stderr)
+        fclose((FILE*)mFile);
+}
+
+void
+FunctionTimerLog::LogString(const char *str)
+{
+    if (mFile) {
+        fputs(str, (FILE*)mFile);
+        putc('\n', (FILE*)mFile);
+    }
+}
+
+int
+FunctionTimer::ft_vsnprintf(char *str, int maxlen, const char *fmt, va_list args)
+{
+    return vsnprintf(str, maxlen, fmt, args);
+}
+
+int
+FunctionTimer::ft_snprintf(char *str, int maxlen, const char *fmt, ...)
+{
+    va_list ap;
+    va_start(ap, fmt);
+
+    int rval = ft_vsnprintf(str, maxlen, fmt, ap);
+
+    va_end(ap);
+
+    return rval;
+}

xpcom/base/FunctionTimer.h

@@ -0,0 +1,233 @@
+/* -*- Mode: C++; tab-width: 40; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
+/* ***** BEGIN LICENSE BLOCK *****
+ * Version: MPL 1.1/GPL 2.0/LGPL 2.1
+ *
+ * The contents of this file are subject to the Mozilla Public License Version
+ * 1.1 (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ * http://www.mozilla.org/MPL/
+ *
+ * Software distributed under the License is distributed on an "AS IS" basis,
+ * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
+ * for the specific language governing rights and limitations under the
+ * License.
+ *
+ * The Original Code is Mozilla code.
+ *
+ * The Initial Developer of the Original Code is
+ * Mozilla Corporation.
+ * Portions created by the Initial Developer are Copyright (C) 2009
+ * the Initial Developer. All Rights Reserved.
+ *
+ * Contributor(s):
+ *   Vladimir Vukicevic <vladimir@pobox.com>
+ *
+ * Alternatively, the contents of this file may be used under the terms of
+ * either the GNU General Public License Version 2 or later (the "GPL"), or
+ * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
+ * in which case the provisions of the GPL or the LGPL are applicable instead
+ * of those above. If you wish to allow use of your version of this file only
+ * under the terms of either the GPL or the LGPL, and not to allow others to
+ * use your version of this file under the terms of the MPL, indicate your
+ * decision by deleting the provisions above and replace them with the notice
+ * and other provisions required by the GPL or the LGPL. If you do not delete
+ * the provisions above, a recipient may use your version of this file under
+ * the terms of any one of the MPL, the GPL or the LGPL.
+ *
+ * ***** END LICENSE BLOCK ***** */
+
+#ifndef mozilla_FunctionTimer_h
+#define mozilla_FunctionTimer_h
+
+#include <stdarg.h>
+
+#include "mozilla/TimeStamp.h"
+#include "nscore.h"
+
+#if defined(NS_FORCE_FUNCTION_TIMER) && !defined(NS_FUNCTION_TIMER)
+#define NS_FUNCTION_TIMER
+#endif
+
+/*
+ * Shortcut macros
+ */
+
+#ifdef NS_FUNCTION_TIMER
+
+// Add a timer for this function, from this declaration until the
+// function returns.  The function name will be used as the
+// log string, and both function entry and exit will be printed.
+#define NS_TIME_FUNCTION                                                \
+    mozilla::FunctionTimer ft__autogen("%s (line %d)", __FUNCTION__, __LINE__)
+
+// Add a timer for this block, but print only a) if the exit time is
+// greater than the given number of milliseconds; or b) if the
+// mark-to-mark time is greater than the given number of milliseconds.
+// No function entry will be printed.  If the value given is negative,
+// no function entry or exit will ever be printed, but all marks will.
+#define NS_TIME_FUNCTION_MIN(_ms)                                       \
+    mozilla::FunctionTimer ft__autogen((_ms), "%s (line %d)", __FUNCTION__, __LINE__)
+
+// Add a timer for this block, but print only marks, not function
+// entry and exit.  The same as calling the above macro with a negative value.
+#define NS_TIME_FUNCTION_MARK_ONLY                                    \
+    mozilla::FunctionTimer ft__autogen((-1), "%s (line %d)", __FUNCTION__, __LINE__)
+
+// Add a timer for this block, using the printf-style format.
+// Both function entry and exit will be printed.
+#define NS_TIME_FUNCTION_FMT(...)                                       \
+    mozilla::FunctionTimer ft__autogen(__VA_ARGS__)
+
+// Add a timer for this block, using the given minimum number of
+// milliseconds and the given printf-style format.  No function entry
+// will be printed.
+#define NS_TIME_FUNCTION_MIN_FMT(_ms, ...)                              \
+    mozilla::FunctionTimer ft__autogen((_ms), __VA_ARGS__)
+
+// Add a midway mark for the current timer; an existing timer must
+// have already been created using one of the above macros.  The
+// string given by the printf-style format will be logged, as well as
+// the total elapsed time since the creation of the timer, and the
+// time since the last mark.
+#define NS_TIME_FUNCTION_MARK(...)              \
+    ft__autogen.Mark(__VA_ARGS__)
+
+// A double value representing the time elapsed since NS_TIME_FUNCTION
+// initialization, in ms.
+#define NS_TIME_FUNCTION_ELAPSED              \
+    ft__autogen.Elapsed()
+
+// A double value representing the time elapsed since the last
+// NS_TIME_FUNCTION_MARK, in ms.
+#define NS_TIME_FUNCTION_ELAPSED_SINCE_MARK                             \
+    ft__autogen.ElapsedSinceMark
+
+#else
+
+#define NS_TIME_FUNCTION do { } while (0)
+#define NS_TIME_FUNCTION_MIN(_ms) do { } while (0)
+#define NS_TIME_FUNCTION_MARK_ONLY do { } while (0)
+#define NS_TIME_FUNCTION_FMT(...) do { } while (0)
+#define NS_TIME_FUNCTION_MIN_FMT(_ms, ...) do { } while (0)
+#define NS_TIME_FUNCTION_MARK(...) do { } while (0)
+#define NS_TIME_FUNCTION_ELAPSED (0)
+#define NS_TIME_FUNCTION_ELAPSED_SINCE_MARK (0)
+
+#endif
+
+namespace mozilla {
+
+class NS_COM FunctionTimerLog
+{
+public:
+    FunctionTimerLog(const char *fname);
+    ~FunctionTimerLog();
+
+    void LogString(const char *str);
+
+private:
+    void *mFile;
+};
+
+class NS_COM FunctionTimer
+{
+    static FunctionTimerLog* sLog;
+    static char *sBuf1, *sBuf2;
+    static int sBufSize;
+
+    enum { BUF_LOG_LENGTH = 256 };
+
+public:
+    static int InitTimers();
+
+    static int ft_vsnprintf(char *str, int maxlen, const char *fmt, va_list args);
+    static int ft_snprintf(char *str, int maxlen, const char *fmt, ...);
+
+public:
+    inline void TimeInit() {
+        mStart = TimeStamp::Now();
+        mLastMark = mStart;
+    }
+
+    inline double Elapsed() {
+        return (TimeStamp::Now() - mStart).ToSeconds() * 1000.0;
+    }
+
+    inline double ElapsedSinceMark() {
+        return (TimeStamp::Now() - mLastMark).ToSeconds() * 1000.0;
+    }
+
+    FunctionTimer(double minms, const char *s, ...)
+        : mMinMs(minms)
+    {
+        va_list ap;
+        va_start(ap, s);
+
+        if (sLog) {
+            TimeInit();
+
+            ft_vsnprintf(mString, BUF_LOG_LENGTH, s, ap);
+        }
+
+        va_end(ap);
+    }
+
+    FunctionTimer(const char *s, ...)
+        : mMinMs(0.0)
+    {
+        va_list ap;
+        va_start(ap, s);
+
+        if (sLog) {
+            TimeInit();
+
+            ft_vsnprintf(mString, BUF_LOG_LENGTH, s, ap);
+
+            ft_snprintf(sBuf1, sBufSize, "> %s", mString);
+            sLog->LogString(sBuf1);
+        }
+
+        va_end(ap);
+    }
+
+    void Mark(const char *s, ...)
+    {
+        va_list ap;
+        va_start(ap, s);
+
+        ft_vsnprintf(sBuf1, sBufSize, s, ap);
+
+        TimeStamp now(TimeStamp::Now());
+        double ms = (now - mStart).ToSeconds() * 1000.0;
+        double msl = (now - mLastMark).ToSeconds() * 1000.0;
+        mLastMark = now;
+
+        if (msl > mMinMs) {
+            ft_snprintf(sBuf2, sBufSize, "%s- %5.2f ms (%5.2f ms total) - %s [%s]", mMinMs < 0.0 ? "" : "*", msl, ms, mString, sBuf1);
+            sLog->LogString(sBuf2);
+        }
+
+        va_end(ap);
+    }
+
+    ~FunctionTimer() {
+        TimeStamp now(TimeStamp::Now());
+        double ms = (now - mStart).ToSeconds() * 1000.0;
+        double msl = (now - mLastMark).ToSeconds() * 1000.0;
+
+        if (mMinMs < 0.0 || (mMinMs >= 0.0 && msl > mMinMs)) {
+            ft_snprintf(sBuf1, sBufSize, "%s %5.2f ms (%5.2f ms total) - %s", mMinMs < 0.0 ? "<" : "*", msl, ms, mString);
+            sLog->LogString(sBuf1);
+        }
+    }
+
+    TimeStamp mStart, mLastMark;
+    char mString[BUF_LOG_LENGTH+1];
+    double mMinMs;
+};
+
+} // namespace mozilla
+
+#endif // mozilla_FunctionTimer_h
+
+

xpcom/base/Makefile.in

@@ -64,6 +64,7 @@ CPPSRCS		= \
 		nsCycleCollector.cpp \
 		nsStackWalk.cpp \
 		nsMemoryReporterManager.cpp \
+		FunctionTimer.cpp \
 		$(NULL)
 
 ifeq (cocoa,$(MOZ_WIDGET_TOOLKIT))
@@ -84,6 +85,12 @@ EXPORTS		= \
 		nsInterfaceRequestorAgg.h \
 		$(NULL)
 
+EXPORTS_NAMESPACES = mozilla
+
+EXPORTS_mozilla = \
+	FunctionTimer.h \
+	$(NULL)
+
 ifeq ($(OS_ARCH),WINNT)
 ifdef MOZ_DEBUG
 CSRCS		+= pure_api.c

xpcom/build/nsXPComInit.cpp

@@ -164,8 +164,6 @@ static BrowserProcessSubThread* sIOThread;
 } /* anonymous namespace */
 #endif
 
-using mozilla::TimeStamp;
-
 // Registry Factory creation function defined in nsRegistry.cpp
 // We hook into this function locally to create and register the registry
 // Since noone outside xpcom needs to know about this and nsRegistry.cpp
@@ -519,10 +517,6 @@ NS_InitXPCOM3(nsIServiceManager* *result,
     }
 #endif
 
-    // Set up TimeStamp
-    rv = TimeStamp::Startup();
-    NS_ENSURE_SUCCESS(rv, rv);
-
     // Establish the main thread here.
     rv = nsThreadManager::get()->Init();
     if (NS_FAILED(rv)) return rv;
@@ -885,8 +879,6 @@ ShutdownXPCOM(nsIServiceManager* servMgr)
 
     NS_IF_RELEASE(gDebug);
 
-    TimeStamp::Shutdown();
-
 #ifdef MOZ_IPC
     if (sIOThread) {
         delete sIOThread;

xpcom/ds/TimeStamp.cpp

@@ -41,6 +41,18 @@
 
 namespace mozilla {
 
+struct TimeStampInitialization
+{
+  TimeStampInitialization() {
+    TimeStamp::Startup();
+  }
+  ~TimeStampInitialization() {
+    TimeStamp::Shutdown();
+  }
+};
+
+static TimeStampInitialization initOnce;
+
 static PRLock* gTimeStampLock;
 static PRUint32 gRolloverCount;
 static PRIntervalTime gLastNow;

xpcom/ds/TimeStamp.h

@@ -56,7 +56,8 @@ class TimeStamp;
  * system-dependent unit must be constant, otherwise the semantics of
  * this class would be broken.
  */
-class NS_COM TimeDuration {
+class NS_COM TimeDuration
+{
 public:
   // The default duration is 0.
   TimeDuration() : mValue(0) {}
@@ -155,7 +156,8 @@ private:
  *   - PRIntervalTime otherwise.  We detect wraparounds of
  *     PRIntervalTime and work around them.
  */
-class NS_COM TimeStamp {
+class NS_COM TimeStamp
+{
 public:
   /**
    * Initialize to the "null" moment