Changeset 166544 in webkit
- Timestamp:
- Mar 31, 2014 4:27:29 PM (10 years ago)
- Location:
- trunk/Source/JavaScriptCore
- Files:
-
- 2 edited
Legend:
- Unmodified
- Added
- Removed
-
trunk/Source/JavaScriptCore/ChangeLog
r166535 r166544 1 2014-03-31 Mark Hahnenberg <mhahnenberg@apple.com> 2 3 Improve GC_LOGGING 4 https://bugs.webkit.org/show_bug.cgi?id=130988 5 6 Reviewed by Geoffrey Garen. 7 8 GC_LOGGING can be useful for diagnosing where we're spending our time during collection, 9 but it doesn't distinguish between Eden and Full collections in the data it gathers. This 10 patch updates it so that it can. It also adds the process ID to the beginning of each line 11 of input to be able to distinguish between the output of multiple processes exiting at the 12 same time. 13 14 * heap/Heap.cpp: 15 (JSC::Heap::collect): 16 1 17 2014-03-31 Dean Jackson <dino@apple.com> 2 18 -
trunk/Source/JavaScriptCore/heap/Heap.cpp
r166375 r166544 50 50 #include <wtf/RAMSize.h> 51 51 #include <wtf/CurrentTime.h> 52 #include <wtf/ProcessID.h> 52 53 53 54 using namespace std; … … 78 79 struct GCTimer { 79 80 GCTimer(const char* name) 80 : m_time(0) 81 , m_min(100000000) 82 , m_max(0) 83 , m_count(0) 84 , m_name(name) 81 : m_name(name) 85 82 { 86 83 } 87 84 ~GCTimer() 88 85 { 89 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); 90 } 91 double m_time; 92 double m_min; 93 double m_max; 94 size_t m_count; 86 logData(m_allCollectionData, "(All)"); 87 logData(m_edenCollectionData, "(Eden)"); 88 logData(m_fullCollectionData, "(Full)"); 89 } 90 91 struct TimeRecord { 92 TimeRecord() 93 : m_time(0) 94 , m_min(std::numeric_limits<double>::infinity()) 95 , m_max(0) 96 , m_count(0) 97 { 98 } 99 100 double m_time; 101 double m_min; 102 double m_max; 103 size_t m_count; 104 }; 105 106 void logData(const TimeRecord& data, const char* extra) 107 { 108 dataLogF("[%d] %s %s: %.2lfms (avg. %.2lf, min. %.2lf, max. %.2lf, count %lu)\n", 109 getCurrentProcessID(), 110 m_name, extra, 111 data.m_time * 1000, 112 data.m_time * 1000 / data.m_count, 113 data.m_min * 1000, 114 data.m_max * 1000, 115 data.m_count); 116 } 117 118 void updateData(TimeRecord& data, double duration) 119 { 120 if (duration < data.m_min) 121 data.m_min = duration; 122 if (duration > data.m_max) 123 data.m_max = duration; 124 data.m_count++; 125 data.m_time += duration; 126 } 127 128 void didFinishPhase(HeapOperation collectionType, double duration) 129 { 130 TimeRecord& data = collectionType == EdenCollection ? m_edenCollectionData : m_fullCollectionData; 131 updateData(data, duration); 132 updateData(m_allCollectionData, duration); 133 } 134 135 TimeRecord m_allCollectionData; 136 TimeRecord m_fullCollectionData; 137 TimeRecord m_edenCollectionData; 95 138 const char* m_name; 96 139 }; 97 140 98 141 struct GCTimerScope { 99 GCTimerScope(GCTimer* timer )142 GCTimerScope(GCTimer* timer, HeapOperation collectionType) 100 143 : m_timer(timer) 101 144 , m_start(WTF::monotonicallyIncreasingTime()) 145 , m_collectionType(collectionType) 102 146 { 103 147 } … … 105 149 { 106 150 double delta = WTF::monotonicallyIncreasingTime() - m_start; 107 if (delta < m_timer->m_min) 108 m_timer->m_min = delta; 109 if (delta > m_timer->m_max) 110 m_timer->m_max = delta; 111 m_timer->m_count++; 112 m_timer->m_time += delta; 151 m_timer->didFinishPhase(m_collectionType, delta); 113 152 } 114 153 GCTimer* m_timer; 115 154 double m_start; 155 HeapOperation m_collectionType; 116 156 }; 117 157 … … 137 177 ~GCCounter() 138 178 { 139 dataLogF(" %s: %zu values (avg. %zu, min. %zu, max. %zu)\n", m_name, m_total, m_total / m_count, m_min, m_max);179 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); 140 180 } 141 181 const char* m_name; … … 146 186 }; 147 187 148 #define GCPHASE(name) DEFINE_GC_LOGGING_GLOBAL(GCTimer, name##Timer, (#name)); GCTimerScope name##TimerScope(&name##Timer) 149 #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) 188 #define GCPHASE(name) DEFINE_GC_LOGGING_GLOBAL(GCTimer, name##Timer, (#name)); GCTimerScope name##TimerScope(&name##Timer, m_operationInProgress) 150 189 #define GCCOUNTER(name, value) do { DEFINE_GC_LOGGING_GLOBAL(GCCounter, name##Counter, (#name)); name##Counter.count(value); } while (false) 151 190 … … 153 192 154 193 #define GCPHASE(name) do { } while (false) 155 #define COND_GCPHASE(cond, name1, name2) do { } while (false)156 194 #define GCCOUNTER(name, value) do { } while (false) 157 195 #endif … … 888 926 889 927 RELEASE_ASSERT(!m_deferralDepth); 890 GCPHASE(Collect);891 928 ASSERT(vm()->currentThreadIsHoldingAPILock()); 892 929 RELEASE_ASSERT(vm()->atomicStringTable() == wtfThreadData().atomicStringTable()); … … 897 934 suspendCompilerThreads(); 898 935 willStartCollection(collectionType); 936 GCPHASE(Collect); 899 937 900 938 double gcStartTime = WTF::monotonicallyIncreasingTime();
Note: See TracChangeset
for help on using the changeset viewer.