Changeset 166544 in webkit

Timestamp:

Mar 31, 2014 4:27:29 PM (10 years ago)

Author:

mhahnenberg@apple.com

Message:

Improve GC_LOGGING
​https://bugs.webkit.org/show_bug.cgi?id=130988

Reviewed by Geoffrey Garen.

GC_LOGGING can be useful for diagnosing where we're spending our time during collection,
but it doesn't distinguish between Eden and Full collections in the data it gathers. This
patch updates it so that it can. It also adds the process ID to the beginning of each line
of input to be able to distinguish between the output of multiple processes exiting at the
same time.

• heap/Heap.cpp:

(JSC::Heap::collect):

Location:

trunk/Source/JavaScriptCore

Files:

• ChangeLog (modified) (1 diff)
• heap/Heap.cpp (modified) (8 diffs)

trunk/Source/JavaScriptCore/ChangeLog

@@ +1 @@
+2014-03-31  Mark Hahnenberg  <mhahnenberg@apple.com>
+
+        Improve GC_LOGGING
+        https://bugs.webkit.org/show_bug.cgi?id=130988
+
+        Reviewed by Geoffrey Garen.
+
+        GC_LOGGING can be useful for diagnosing where we're spending our time during collection, 
+        but it doesn't distinguish between Eden and Full collections in the data it gathers. This
+        patch updates it so that it can. It also adds the process ID to the beginning of each line 
+        of input to be able to distinguish between the output of multiple processes exiting at the 
+        same time.
+
+        * heap/Heap.cpp:
+        (JSC::Heap::collect):
+
 2014-03-31  Dean Jackson  <dino@apple.com>
 

trunk/Source/JavaScriptCore/heap/Heap.cpp

@@ -50 +50 @@
 #include <wtf/RAMSize.h>
 #include <wtf/CurrentTime.h>
+#include <wtf/ProcessID.h>
 
 using namespace std;
@@ -78 +79 @@
 struct GCTimer {
     GCTimer(const char* name)
-        : m_time(0)
-        , m_min(100000000)
-        , m_max(0)
-        , m_count(0)
-        , m_name(name)
+        : m_name(name)
     {
     }
     ~GCTimer()
     {
-        dataLogF("%s: %.2lfms (avg. %.2lf, min. %.2lf, max. %.2lf)\n", m_name, m_time * 1000, m_time * 1000 / m_count, m_min*1000, m_max*1000);
-    }
-    double m_time;
-    double m_min;
-    double m_max;
-    size_t m_count;
+        logData(m_allCollectionData, "(All)");
+        logData(m_edenCollectionData, "(Eden)");
+        logData(m_fullCollectionData, "(Full)");
+    }
+
+    struct TimeRecord {
+        TimeRecord()
+            : m_time(0)
+            , m_min(std::numeric_limits<double>::infinity())
+            , m_max(0)
+            , m_count(0)
+        {
+        }
+
+        double m_time;
+        double m_min;
+        double m_max;
+        size_t m_count;
+    };
+
+    void logData(const TimeRecord& data, const char* extra)
+    {
+        dataLogF("[%d] %s %s: %.2lfms (avg. %.2lf, min. %.2lf, max. %.2lf, count %lu)\n", 
+            getCurrentProcessID(),
+            m_name, extra, 
+            data.m_time * 1000, 
+            data.m_time * 1000 / data.m_count, 
+            data.m_min * 1000, 
+            data.m_max * 1000,
+            data.m_count);
+    }
+
+    void updateData(TimeRecord& data, double duration)
+    {
+        if (duration < data.m_min)
+            data.m_min = duration;
+        if (duration > data.m_max)
+            data.m_max = duration;
+        data.m_count++;
+        data.m_time += duration;
+    }
+
+    void didFinishPhase(HeapOperation collectionType, double duration)
+    {
+        TimeRecord& data = collectionType == EdenCollection ? m_edenCollectionData : m_fullCollectionData;
+        updateData(data, duration);
+        updateData(m_allCollectionData, duration);
+    }
+
+    TimeRecord m_allCollectionData;
+    TimeRecord m_fullCollectionData;
+    TimeRecord m_edenCollectionData;
     const char* m_name;
 };
 
 struct GCTimerScope {
-    GCTimerScope(GCTimer* timer)
+    GCTimerScope(GCTimer* timer, HeapOperation collectionType)
         : m_timer(timer)
         , m_start(WTF::monotonicallyIncreasingTime())
+        , m_collectionType(collectionType)
     {
     }
@@ -105 +149 @@
     {
         double delta = WTF::monotonicallyIncreasingTime() - m_start;
-        if (delta < m_timer->m_min)
-            m_timer->m_min = delta;
-        if (delta > m_timer->m_max)
-            m_timer->m_max = delta;
-        m_timer->m_count++;
-        m_timer->m_time += delta;
+        m_timer->didFinishPhase(m_collectionType, delta);
     }
     GCTimer* m_timer;
     double m_start;
+    HeapOperation m_collectionType;
 };
 
@@ -137 +177 @@
     ~GCCounter()
     {
-        dataLogF("%s: %zu values (avg. %zu, min. %zu, max. %zu)\n", m_name, m_total, m_total / m_count, m_min, m_max);
+        dataLogF("[%d] %s: %zu values (avg. %zu, min. %zu, max. %zu)\n", getCurrentProcessID(), m_name, m_total, m_total / m_count, m_min, m_max);
     }
     const char* m_name;
@@ -146 +186 @@
 };
 
-#define GCPHASE(name) DEFINE_GC_LOGGING_GLOBAL(GCTimer, name##Timer, (#name)); GCTimerScope name##TimerScope(&name##Timer)
-#define COND_GCPHASE(cond, name1, name2) DEFINE_GC_LOGGING_GLOBAL(GCTimer, name1##Timer, (#name1)); DEFINE_GC_LOGGING_GLOBAL(GCTimer, name2##Timer, (#name2)); GCTimerScope name1##CondTimerScope(cond ? &name1##Timer : &name2##Timer)
+#define GCPHASE(name) DEFINE_GC_LOGGING_GLOBAL(GCTimer, name##Timer, (#name)); GCTimerScope name##TimerScope(&name##Timer, m_operationInProgress)
 #define GCCOUNTER(name, value) do { DEFINE_GC_LOGGING_GLOBAL(GCCounter, name##Counter, (#name)); name##Counter.count(value); } while (false)
     
@@ -153 +192 @@
 
 #define GCPHASE(name) do { } while (false)
-#define COND_GCPHASE(cond, name1, name2) do { } while (false)
 #define GCCOUNTER(name, value) do { } while (false)
 #endif
@@ -888 +926 @@
     
     RELEASE_ASSERT(!m_deferralDepth);
-    GCPHASE(Collect);
     ASSERT(vm()->currentThreadIsHoldingAPILock());
     RELEASE_ASSERT(vm()->atomicStringTable() == wtfThreadData().atomicStringTable());
@@ -897 +934 @@
     suspendCompilerThreads();
     willStartCollection(collectionType);
+    GCPHASE(Collect);
 
     double gcStartTime = WTF::monotonicallyIncreasingTime();