ENH: Add Logging to GC Marking Phase
authormsaboff@apple.com <msaboff@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 6 Jun 2012 23:11:09 +0000 (23:11 +0000)
committermsaboff@apple.com <msaboff@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Wed, 6 Jun 2012 23:11:09 +0000 (23:11 +0000)
https://bugs.webkit.org/show_bug.cgi?id=88364

Reviewed by Filip Pizlo.

Source/JavaScriptCore:

Log GC marking to stderr or a file.  The logging in controlled
with the define ENABLE_OBJECT_MARK_LOGGING in wtf/Platform.h.
If DATA_LOG_TO_FILE in wtf/DataLog.cpp is set to 1, output is
logged to a file otherwise it is logged to stderr.

When logging is enabled, the GC is built single threaded since the
log output from the various threads isn't buffered and output in a
thread safe manner.

* heap/Heap.cpp:
(JSC::Heap::markRoots):
* heap/MarkStack.cpp:
(JSC::MarkStackThreadSharedData::resetChildren):
(JSC::MarkStackThreadSharedData::childVisitCount):
(JSC::MarkStackThreadSharedData::markingThreadMain):
(JSC::MarkStackThreadSharedData::markingThreadStartFunc):
(JSC::MarkStackThreadSharedData::MarkStackThreadSharedData):
(JSC::MarkStackThreadSharedData::reset):
* heap/MarkStack.h:
(MarkStackThreadSharedData):
(MarkStack):
(JSC::MarkStack::sharedData):
(JSC::MarkStack::resetChildCount):
(JSC::MarkStack::childCount):
(JSC::MarkStack::incrementChildCount):
* runtime/JSArray.cpp:
(JSC::JSArray::visitChildren):
* runtime/JSCell.cpp:
(JSC::JSCell::className):
* runtime/JSCell.h:
(JSCell):
(JSC::JSCell::visitChildren):
* runtime/JSString.cpp:
(JSC::JSString::visitChildren):
* runtime/JSString.h:
(JSString):
* runtime/Structure.h:
(JSC::MarkStack::internalAppend):

Source/WTF:

* wtf/DataLog.cpp:
(WTF::dataLogString): Additional method to support GC Mark logging.
* wtf/DataLog.h:
* wtf/Platform.h: New ENABLE_OBJECT_MARK_LOGGING flag macro.

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@119633 268f45cc-cd09-0410-ab3c-d52691b4dbfc

14 files changed:
Source/JavaScriptCore/ChangeLog
Source/JavaScriptCore/heap/Heap.cpp
Source/JavaScriptCore/heap/MarkStack.cpp
Source/JavaScriptCore/heap/MarkStack.h
Source/JavaScriptCore/runtime/JSArray.cpp
Source/JavaScriptCore/runtime/JSCell.cpp
Source/JavaScriptCore/runtime/JSCell.h
Source/JavaScriptCore/runtime/JSString.cpp
Source/JavaScriptCore/runtime/JSString.h
Source/JavaScriptCore/runtime/Structure.h
Source/WTF/ChangeLog
Source/WTF/wtf/DataLog.cpp
Source/WTF/wtf/DataLog.h
Source/WTF/wtf/Platform.h

index 651076a..d98bf55 100644 (file)
@@ -1,3 +1,49 @@
+2012-06-06  Michael Saboff  <msaboff@apple.com>
+
+        ENH: Add Logging to GC Marking Phase
+        https://bugs.webkit.org/show_bug.cgi?id=88364
+
+        Reviewed by Filip Pizlo.
+
+        Log GC marking to stderr or a file.  The logging in controlled
+        with the define ENABLE_OBJECT_MARK_LOGGING in wtf/Platform.h.
+        If DATA_LOG_TO_FILE in wtf/DataLog.cpp is set to 1, output is
+        logged to a file otherwise it is logged to stderr.
+
+        When logging is enabled, the GC is built single threaded since the
+        log output from the various threads isn't buffered and output in a
+        thread safe manner.
+
+        * heap/Heap.cpp:
+        (JSC::Heap::markRoots):
+        * heap/MarkStack.cpp:
+        (JSC::MarkStackThreadSharedData::resetChildren):
+        (JSC::MarkStackThreadSharedData::childVisitCount):
+        (JSC::MarkStackThreadSharedData::markingThreadMain):
+        (JSC::MarkStackThreadSharedData::markingThreadStartFunc):
+        (JSC::MarkStackThreadSharedData::MarkStackThreadSharedData):
+        (JSC::MarkStackThreadSharedData::reset):
+        * heap/MarkStack.h:
+        (MarkStackThreadSharedData):
+        (MarkStack):
+        (JSC::MarkStack::sharedData):
+        (JSC::MarkStack::resetChildCount):
+        (JSC::MarkStack::childCount):
+        (JSC::MarkStack::incrementChildCount):
+        * runtime/JSArray.cpp:
+        (JSC::JSArray::visitChildren):
+        * runtime/JSCell.cpp:
+        (JSC::JSCell::className):
+        * runtime/JSCell.h:
+        (JSCell):
+        (JSC::JSCell::visitChildren):
+        * runtime/JSString.cpp:
+        (JSC::JSString::visitChildren):
+        * runtime/JSString.h:
+        (JSString):
+        * runtime/Structure.h:
+        (JSC::MarkStack::internalAppend):
+
 2012-06-06  Gavin Barraclough  <barraclough@apple.com>
 
         Assigning to a static property should not change iteration order
index 27bacae..790e3aa 100644 (file)
@@ -421,6 +421,10 @@ void Heap::markRoots(bool fullGC)
     UNUSED_PARAM(fullGC);
     ASSERT(isValidThreadState(m_globalData));
 
+#if ENABLE(OBJECT_MARK_LOGGING)
+    double gcStartTime = WTF::currentTime();
+#endif
+
     void* dummy;
     
     // We gather conservative roots before clearing mark bits because conservative
@@ -484,28 +488,33 @@ void Heap::markRoots(bool fullGC)
     
         {
             GCPHASE(VisitMachineRoots);
+            MARK_LOG_ROOT(visitor, "C++ Stack");
             visitor.append(machineThreadRoots);
             visitor.donateAndDrain();
         }
         {
             GCPHASE(VisitRegisterFileRoots);
+            MARK_LOG_ROOT(visitor, "Register File");
             visitor.append(registerFileRoots);
             visitor.donateAndDrain();
         }
 #if ENABLE(DFG_JIT)
         {
             GCPHASE(VisitScratchBufferRoots);
+            MARK_LOG_ROOT(visitor, "Scratch Buffers");
             visitor.append(scratchBufferRoots);
             visitor.donateAndDrain();
         }
 #endif
         {
             GCPHASE(VisitProtectedObjects);
+            MARK_LOG_ROOT(visitor, "Protected Objects");
             markProtectedObjects(heapRootVisitor);
             visitor.donateAndDrain();
         }
         {
             GCPHASE(VisitTempSortVectors);
+            MARK_LOG_ROOT(visitor, "Temp Sort Vectors");
             markTempSortVectors(heapRootVisitor);
             visitor.donateAndDrain();
         }
@@ -513,30 +522,35 @@ void Heap::markRoots(bool fullGC)
         {
             GCPHASE(MarkingArgumentBuffers);
             if (m_markListSet && m_markListSet->size()) {
+                MARK_LOG_ROOT(visitor, "Argument Buffers");
                 MarkedArgumentBuffer::markLists(heapRootVisitor, *m_markListSet);
                 visitor.donateAndDrain();
             }
         }
         if (m_globalData->exception) {
             GCPHASE(MarkingException);
+            MARK_LOG_ROOT(visitor, "Exceptions");
             heapRootVisitor.visit(&m_globalData->exception);
             visitor.donateAndDrain();
         }
     
         {
             GCPHASE(VisitStrongHandles);
+            MARK_LOG_ROOT(visitor, "Strong Handles");
             m_handleSet.visitStrongHandles(heapRootVisitor);
             visitor.donateAndDrain();
         }
     
         {
             GCPHASE(HandleStack);
+            MARK_LOG_ROOT(visitor, "Handle Stack");
             m_handleStack.visit(heapRootVisitor);
             visitor.donateAndDrain();
         }
     
         {
             GCPHASE(TraceCodeBlocks);
+            MARK_LOG_ROOT(visitor, "Trace Code Blocks");
             m_dfgCodeBlocks.traceMarkedCodeBlocks(visitor);
             visitor.donateAndDrain();
         }
@@ -553,6 +567,7 @@ void Heap::markRoots(bool fullGC)
     // the liveness of the rest of the object graph.
     {
         GCPHASE(VisitingLiveWeakHandles);
+        MARK_LOG_ROOT(visitor, "Live Weak Handles");
         while (true) {
             m_objectSpace.visitWeakSets(heapRootVisitor);
             harvestWeakReferences();
@@ -571,8 +586,19 @@ void Heap::markRoots(bool fullGC)
     GCCOUNTER(VisitedValueCount, visitor.visitCount());
 
     visitor.doneCopying();
+#if ENABLE(OBJECT_MARK_LOGGING)
+    size_t visitCount = visitor.visitCount();
+#if ENABLE(PARALLEL_GC)
+    visitCount += m_sharedData.childVisitCount();
+#endif
+    MARK_LOG_MESSAGE2("\nNumber of live Objects after full GC %lu, took %.6f secs\n", visitCount, WTF::currentTime() - gcStartTime);
+#endif
+
     visitor.reset();
     m_sharedData.reset();
+#if ENABLE(PARALLEL_GC)
+    m_sharedData.resetChildren();
+#endif
     m_storageSpace.doneCopying();
 
 }
index 678f1cb..c026581 100644 (file)
@@ -36,6 +36,7 @@
 #include "JSObject.h"
 #include "ScopeChain.h"
 #include "Structure.h"
+#include "UString.h"
 #include "WriteBarrier.h"
 #include <wtf/DataLog.h>
 #include <wtf/MainThread.h>
@@ -219,19 +220,35 @@ void MarkStackArray::stealSomeCellsFrom(MarkStackArray& other)
 }
 
 #if ENABLE(PARALLEL_GC)
-void MarkStackThreadSharedData::markingThreadMain()
+void MarkStackThreadSharedData::resetChildren()
+{
+    for (unsigned i = 0; i < m_markingThreadsMarkStack.size(); ++i)
+       m_markingThreadsMarkStack[i]->reset();
+}   
+
+size_t MarkStackThreadSharedData::childVisitCount()
+{       
+    unsigned long result = 0;
+    for (unsigned i = 0; i < m_markingThreadsMarkStack.size(); ++i)
+        result += m_markingThreadsMarkStack[i]->visitCount();
+    return result;
+}
+
+void MarkStackThreadSharedData::markingThreadMain(SlotVisitor* slotVisitor)
 {
     WTF::registerGCThread();
     {
-        SlotVisitor slotVisitor(*this);
-        ParallelModeEnabler enabler(slotVisitor);
-        slotVisitor.drainFromShared(SlotVisitor::SlaveDrain);
+        ParallelModeEnabler enabler(*slotVisitor);
+        slotVisitor->drainFromShared(SlotVisitor::SlaveDrain);
     }
+    delete slotVisitor;
 }
 
-void MarkStackThreadSharedData::markingThreadStartFunc(void* shared)
-{
-    static_cast<MarkStackThreadSharedData*>(shared)->markingThreadMain();
+void MarkStackThreadSharedData::markingThreadStartFunc(void* myVisitor)
+{               
+    SlotVisitor* slotVisitor = static_cast<SlotVisitor*>(myVisitor);
+
+    slotVisitor->sharedData().markingThreadMain(slotVisitor);
 }
 #endif
 
@@ -244,7 +261,9 @@ MarkStackThreadSharedData::MarkStackThreadSharedData(JSGlobalData* globalData)
 {
 #if ENABLE(PARALLEL_GC)
     for (unsigned i = 1; i < Options::numberOfGCMarkers; ++i) {
-        m_markingThreads.append(createThread(markingThreadStartFunc, this, "JavaScriptCore::Marking"));
+        SlotVisitor* slotVisitor = new SlotVisitor(*this);
+        m_markingThreadsMarkStack.append(slotVisitor);
+        m_markingThreads.append(createThread(markingThreadStartFunc, slotVisitor, "JavaScriptCore::Marking"));
         ASSERT(m_markingThreads.last());
     }
 #endif
@@ -276,7 +295,6 @@ void MarkStackThreadSharedData::reset()
 #else
     ASSERT(m_opaqueRoots.isEmpty());
 #endif
-    
     m_weakReferenceHarvesters.removeAll();
 }
 
index 0695b1b..2779fc9 100644 (file)
 #include "UnconditionalFinalizer.h"
 #include "VTableSpectrum.h"
 #include "WeakReferenceHarvester.h"
+#include <wtf/DataLog.h>
+#include <wtf/Forward.h>
 #include <wtf/HashMap.h>
 #include <wtf/HashSet.h>
 #include <wtf/Vector.h>
 #include <wtf/Noncopyable.h>
 #include <wtf/OSAllocator.h>
 #include <wtf/PageBlock.h>
+#include <wtf/text/StringHash.h>
+
+#if ENABLE(OBJECT_MARK_LOGGING)
+#define MARK_LOG_MESSAGE0(message) dataLog(message)
+#define MARK_LOG_MESSAGE1(message, arg1) dataLog(message, arg1)
+#define MARK_LOG_MESSAGE2(message, arg1, arg2) dataLog(message, arg1, arg2)
+#define MARK_LOG_ROOT(visitor, rootName) \
+    dataLog("\n%s: ", rootName); \
+    (visitor).resetChildCount()
+#define MARK_LOG_PARENT(visitor, parent) \
+    dataLog("\n%p (%s): ", parent, parent->className() ? parent->className() : "unknown"); \
+    (visitor).resetChildCount()
+#define MARK_LOG_CHILD(visitor, child) \
+    if ((visitor).childCount()) \
+    dataLogString(", "); \
+    dataLog("%p", child); \
+    (visitor).incrementChildCount()
+#else
+#define MARK_LOG_MESSAGE0(message) do { } while (false)
+#define MARK_LOG_MESSAGE1(message, arg1) do { } while (false)
+#define MARK_LOG_MESSAGE2(message, arg1, arg2) do { } while (false)
+#define MARK_LOG_ROOT(visitor, rootName) do { } while (false)
+#define MARK_LOG_PARENT(visitor, parent) do { } while (false)
+#define MARK_LOG_CHILD(visitor, child) do { } while (false)
+#endif
 
 namespace JSC {
 
@@ -171,13 +198,19 @@ namespace JSC {
         ~MarkStackThreadSharedData();
         
         void reset();
+
+#if ENABLE(PARALLEL_GC)
+        void resetChildren();
+        size_t childVisitCount();
+        size_t childDupStrings();
+#endif
     
     private:
         friend class MarkStack;
         friend class SlotVisitor;
 
 #if ENABLE(PARALLEL_GC)
-        void markingThreadMain();
+        void markingThreadMain(SlotVisitor*);
         static void markingThreadStartFunc(void* heap);
 #endif
 
@@ -187,6 +220,7 @@ namespace JSC {
         MarkStackSegmentAllocator m_segmentAllocator;
         
         Vector<ThreadIdentifier> m_markingThreads;
+        Vector<MarkStack*> m_markingThreadsMarkStack;
         
         Mutex m_markingLock;
         ThreadCondition m_markingCondition;
@@ -221,7 +255,8 @@ namespace JSC {
         void addOpaqueRoot(void*);
         bool containsOpaqueRoot(void*);
         int opaqueRootCount();
-        
+
+        MarkStackThreadSharedData& sharedData() { return m_shared; }
         bool isEmpty() { return m_stack.isEmpty(); }
 
         void reset();
@@ -242,6 +277,12 @@ namespace JSC {
             m_shared.m_unconditionalFinalizers.addThreadSafe(unconditionalFinalizer);
         }
 
+#if ENABLE(OBJECT_MARK_LOGGING)
+        inline void resetChildCount() { m_logChildCount = 0; }
+        inline unsigned childCount() { return m_logChildCount; }
+        inline void incrementChildCount() { m_logChildCount++; }
+#endif
+
     protected:
         JS_EXPORT_PRIVATE static void validate(JSCell*);
 
@@ -283,6 +324,10 @@ namespace JSC {
         bool m_isInParallelMode;
         
         MarkStackThreadSharedData& m_shared;
+
+#if ENABLE(OBJECT_MARK_LOGGING)
+        unsigned m_logChildCount;
+#endif
     };
 
     inline MarkStack::MarkStack(MarkStackThreadSharedData& shared)
index 9e7aaba..96cc447 100644 (file)
@@ -1371,6 +1371,8 @@ void JSArray::visitChildren(JSCell* cell, SlotVisitor& visitor)
     JSNonFinalObject::visitChildren(thisObject, visitor);
 
     if (thisObject->m_storage) {
+        MARK_LOG_MESSAGE1("[%u]: ", thisObject->length());
+
         ArrayStorage* storage = thisObject->m_storage;
         void* baseStorage = storage->m_allocBase;
 
index 06c1f7c..61e8549 100644 (file)
@@ -184,6 +184,11 @@ UString JSCell::className(const JSObject*)
     return UString();
 }
 
+const char* JSCell::className()
+{
+    return classInfo()->className;
+}
+
 void JSCell::getPropertyNames(JSObject*, ExecState*, PropertyNameArray&, EnumerationMode)
 {
     ASSERT_NOT_REACHED();
index 0233f0f..cdd4097 100644 (file)
@@ -84,6 +84,8 @@ namespace JSC {
         void setStructure(JSGlobalData&, Structure*);
         void clearStructure() { m_structure.clear(); }
 
+        const char* className();
+
         // Extracting the value.
         JS_EXPORT_PRIVATE bool getString(ExecState* exec, UString&) const;
         JS_EXPORT_PRIVATE UString getString(ExecState* exec) const; // null string if not a string
@@ -197,6 +199,8 @@ namespace JSC {
 
     inline void JSCell::visitChildren(JSCell* cell, SlotVisitor& visitor)
     {
+        MARK_LOG_PARENT(visitor, cell);
+
         visitor.append(&cell->m_structure);
     }
 
index 180c64b..4eb2a52 100644 (file)
@@ -56,6 +56,19 @@ void JSString::visitChildren(JSCell* cell, SlotVisitor& visitor)
     JSString* thisObject = jsCast<JSString*>(cell);
     Base::visitChildren(thisObject, visitor);
     
+    MARK_LOG_MESSAGE1("[%u]: ", thisObject->length());
+
+#if ENABLE(OBJECT_MARK_LOGGING)
+    if (!thisObject->isRope()) {
+        WTF::StringImpl* ourImpl = thisObject->m_value.impl();
+        if (ourImpl->is8Bit())
+            MARK_LOG_MESSAGE1("[8 %p]", ourImpl->characters8());
+        else
+            MARK_LOG_MESSAGE1("[16 %p]", ourImpl->characters16());
+    } else
+        MARK_LOG_MESSAGE0("[rope]: ");
+#endif
+
     if (thisObject->isRope())
         static_cast<JSRopeString*>(thisObject)->visitFibers(visitor);
 }
index 111853c..4fb157c 100644 (file)
@@ -67,6 +67,7 @@ namespace JSC {
         friend class JSGlobalData;
         friend class SpecializedThunkJIT;
         friend class JSRopeString;
+        friend class SlotVisitor;
         friend struct ThunkHelpers;
 
         typedef JSCell Base;
index f67c4e7..d9f4d1f 100644 (file)
@@ -382,10 +382,13 @@ namespace JSC {
 #if ENABLE(GC_VALIDATION)
         validate(cell);
 #endif
-        m_visitCount++;
         if (Heap::testAndSetMarked(cell) || !cell->structure())
             return;
+
+        m_visitCount++;
         
+        MARK_LOG_CHILD(*this, cell);
+
         // Should never attempt to mark something that is zapped.
         ASSERT(!cell->isZapped());
         
index 2fb2da0..d183d9b 100644 (file)
@@ -1,3 +1,15 @@
+2012-06-06  Michael Saboff  <msaboff@apple.com>
+
+        ENH: Add Logging to GC Marking Phase
+        https://bugs.webkit.org/show_bug.cgi?id=88364
+
+        Reviewed by Filip Pizlo.
+
+        * wtf/DataLog.cpp:
+        (WTF::dataLogString): Additional method to support GC Mark logging.
+        * wtf/DataLog.h:
+        * wtf/Platform.h: New ENABLE_OBJECT_MARK_LOGGING flag macro.
+
 2012-06-06  Andy Wingo  <wingo@igalia.com>
 
         [GTK] Enable the LLInt
index 7cdeaff..74b678d 100644 (file)
@@ -95,5 +95,10 @@ void dataLog(const char* format, ...)
     va_end(argList);
 }
 
+void dataLogString(const char* str)
+{
+    fputs(str, dataFile());
+}
+
 } // namespace WTF
 
index cca04a3..11e1d3e 100644 (file)
@@ -37,10 +37,12 @@ WTF_EXPORT_PRIVATE FILE* dataFile();
 
 WTF_EXPORT_PRIVATE void dataLogV(const char* format, va_list) WTF_ATTRIBUTE_PRINTF(1, 0);
 WTF_EXPORT_PRIVATE void dataLog(const char* format, ...) WTF_ATTRIBUTE_PRINTF(1, 2);
+WTF_EXPORT_PRIVATE void dataLogString(const char*);
 
 } // namespace WTF
 
 using WTF::dataLog;
+using WTF::dataLogString;
 
 #endif // DataLog_h
 
index f94dfe2..a38b309 100644 (file)
 #define ENABLE_COMPARE_AND_SWAP 1
 #endif
 
-#if !defined(ENABLE_PARALLEL_GC) && (PLATFORM(MAC) || PLATFORM(IOS) || PLATFORM(QT) || PLATFORM(BLACKBERRY)) && ENABLE(COMPARE_AND_SWAP)
+#define ENABLE_OBJECT_MARK_LOGGING 0
+
+#if !defined(ENABLE_PARALLEL_GC) && !ENABLE(OBJECT_MARK_LOGGING) && (PLATFORM(MAC) || PLATFORM(IOS) || PLATFORM(QT) || PLATFORM(BLACKBERRY)) && ENABLE(COMPARE_AND_SWAP)
 #define ENABLE_PARALLEL_GC 1
 #endif