<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.1//EN"
"http://www.w3.org/TR/xhtml11/DTD/xhtml11.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
<head><meta http-equiv="content-type" content="text/html; charset=utf-8" />
<title>[181821] trunk</title>
</head>
<body>
<style type="text/css"><!--
#msg dl.meta { border: 1px #006 solid; background: #369; padding: 6px; color: #fff; }
#msg dl.meta dt { float: left; width: 6em; font-weight: bold; }
#msg dt:after { content:':';}
#msg dl, #msg dt, #msg ul, #msg li, #header, #footer, #logmsg { font-family: verdana,arial,helvetica,sans-serif; font-size: 10pt; }
#msg dl a { font-weight: bold}
#msg dl a:link { color:#fc3; }
#msg dl a:active { color:#ff0; }
#msg dl a:visited { color:#cc6; }
h3 { font-family: verdana,arial,helvetica,sans-serif; font-size: 10pt; font-weight: bold; }
#msg pre { overflow: auto; background: #ffc; border: 1px #fa0 solid; padding: 6px; }
#logmsg { background: #ffc; border: 1px #fa0 solid; padding: 1em 1em 0 1em; }
#logmsg p, #logmsg pre, #logmsg blockquote { margin: 0 0 1em 0; }
#logmsg p, #logmsg li, #logmsg dt, #logmsg dd { line-height: 14pt; }
#logmsg h1, #logmsg h2, #logmsg h3, #logmsg h4, #logmsg h5, #logmsg h6 { margin: .5em 0; }
#logmsg h1:first-child, #logmsg h2:first-child, #logmsg h3:first-child, #logmsg h4:first-child, #logmsg h5:first-child, #logmsg h6:first-child { margin-top: 0; }
#logmsg ul, #logmsg ol { padding: 0; list-style-position: inside; margin: 0 0 0 1em; }
#logmsg ul { text-indent: -1em; padding-left: 1em; }#logmsg ol { text-indent: -1.5em; padding-left: 1.5em; }
#logmsg > ul, #logmsg > ol { margin: 0 0 1em 0; }
#logmsg pre { background: #eee; padding: 1em; }
#logmsg blockquote { border: 1px solid #fa0; border-left-width: 10px; padding: 1em 1em 0 1em; background: white;}
#logmsg dl { margin: 0; }
#logmsg dt { font-weight: bold; }
#logmsg dd { margin: 0; padding: 0 0 0.5em 0; }
#logmsg dd:before { content:'\00bb';}
#logmsg table { border-spacing: 0px; border-collapse: collapse; border-top: 4px solid #fa0; border-bottom: 1px solid #fa0; background: #fff; }
#logmsg table th { text-align: left; font-weight: normal; padding: 0.2em 0.5em; border-top: 1px dotted #fa0; }
#logmsg table td { text-align: right; border-top: 1px dotted #fa0; padding: 0.2em 0.5em; }
#logmsg table thead th { text-align: center; border-bottom: 1px solid #fa0; }
#logmsg table th.Corner { text-align: left; }
#logmsg hr { border: none 0; border-top: 2px dashed #fa0; height: 1px; }
#header, #footer { color: #fff; background: #636; border: 1px #300 solid; padding: 6px; }
#patch { width: 100%; }
#patch h4 {font-family: verdana,arial,helvetica,sans-serif;font-size:10pt;padding:8px;background:#369;color:#fff;margin:0;}
#patch .propset h4, #patch .binary h4 {margin:0;}
#patch pre {padding:0;line-height:1.2em;margin:0;}
#patch .diff {width:100%;background:#eee;padding: 0 0 10px 0;overflow:auto;}
#patch .propset .diff, #patch .binary .diff {padding:10px 0;}
#patch span {display:block;padding:0 10px;}
#patch .modfile, #patch .addfile, #patch .delfile, #patch .propset, #patch .binary, #patch .copfile {border:1px solid #ccc;margin:10px 0;}
#patch ins {background:#dfd;text-decoration:none;display:block;padding:0 10px;}
#patch del {background:#fdd;text-decoration:none;display:block;padding:0 10px;}
#patch .lines, .info {color:#888;background:#fff;}
--></style>
<div id="msg">
<dl class="meta">
<dt>Revision</dt> <dd><a href="http://trac.webkit.org/projects/webkit/changeset/181821">181821</a></dd>
<dt>Author</dt> <dd>mhahnenb@gmail.com</dd>
<dt>Date</dt> <dd>2015-03-20 19:02:44 -0700 (Fri, 20 Mar 2015)</dd>
</dl>
<h3>Log Message</h3>
<pre>GCTimer should know keep track of nested GC phases
https://bugs.webkit.org/show_bug.cgi?id=142675
Reviewed by Darin Adler.
Source/JavaScriptCore:
This improves the GC phase timing output in Heap.cpp by linking
phases nested inside other phases together, allowing tools
to compute how much time we're spending in various nested phases.
* heap/Heap.cpp:
Tools:
Adds a tool to aid in parsing the GC phase timing output into a
tree-like structure based on the parent-child relationships
of nested GC phases.
* Scripts/parse-gc-phase-timings: Added.
(Timing):
(Timing.__init__):
(Timing.__unicode__):
(Timing.__str__):
(Timing.__repr__):
(parse_input):
(print_timing_node):
(print_timing_tree):
(link_parents):
(main):</pre>
<h3>Modified Paths</h3>
<ul>
<li><a href="#trunkSourceJavaScriptCoreChangeLog">trunk/Source/JavaScriptCore/ChangeLog</a></li>
<li><a href="#trunkSourceJavaScriptCoreheapHeapcpp">trunk/Source/JavaScriptCore/heap/Heap.cpp</a></li>
<li><a href="#trunkToolsChangeLog">trunk/Tools/ChangeLog</a></li>
</ul>
<h3>Added Paths</h3>
<ul>
<li><a href="#trunkToolsScriptsparsegcphasetimings">trunk/Tools/Scripts/parse-gc-phase-timings</a></li>
</ul>
</div>
<div id="patch">
<h3>Diff</h3>
<a id="trunkSourceJavaScriptCoreChangeLog"></a>
<div class="modfile"><h4>Modified: trunk/Source/JavaScriptCore/ChangeLog (181820 => 181821)</h4>
<pre class="diff"><span>
<span class="info">--- trunk/Source/JavaScriptCore/ChangeLog 2015-03-21 00:07:17 UTC (rev 181820)
+++ trunk/Source/JavaScriptCore/ChangeLog 2015-03-21 02:02:44 UTC (rev 181821)
</span><span class="lines">@@ -1,3 +1,16 @@
</span><ins>+2015-03-20 Mark Hahnenberg <mhahnenb@gmail.com>
+
+ GCTimer should know keep track of nested GC phases
+ https://bugs.webkit.org/show_bug.cgi?id=142675
+
+ Reviewed by Darin Adler.
+
+ This improves the GC phase timing output in Heap.cpp by linking
+ phases nested inside other phases together, allowing tools
+ to compute how much time we're spending in various nested phases.
+
+ * heap/Heap.cpp:
+
</ins><span class="cx"> 2015-03-20 Geoffrey Garen <ggaren@apple.com>
</span><span class="cx">
</span><span class="cx"> FunctionBodyNode should known where its parameters started
</span></span></pre></div>
<a id="trunkSourceJavaScriptCoreheapHeapcpp"></a>
<div class="modfile"><h4>Modified: trunk/Source/JavaScriptCore/heap/Heap.cpp (181820 => 181821)</h4>
<pre class="diff"><span>
<span class="info">--- trunk/Source/JavaScriptCore/heap/Heap.cpp 2015-03-21 00:07:17 UTC (rev 181820)
+++ trunk/Source/JavaScriptCore/heap/Heap.cpp 2015-03-21 02:02:44 UTC (rev 181821)
</span><span class="lines">@@ -80,115 +80,125 @@
</span><span class="cx">
</span><span class="cx"> struct GCTimer {
</span><span class="cx"> GCTimer(const char* name)
</span><del>- : m_name(name)
</del><ins>+ : name(name)
</ins><span class="cx"> {
</span><span class="cx"> }
</span><span class="cx"> ~GCTimer()
</span><span class="cx"> {
</span><del>- logData(m_allCollectionData, "(All)");
- logData(m_edenCollectionData, "(Eden)");
- logData(m_fullCollectionData, "(Full)");
</del><ins>+ logData(allCollectionData, "(All)");
+ logData(edenCollectionData, "(Eden)");
+ logData(fullCollectionData, "(Full)");
</ins><span class="cx"> }
</span><span class="cx">
</span><span class="cx"> struct TimeRecord {
</span><span class="cx"> TimeRecord()
</span><del>- : m_time(0)
- , m_min(std::numeric_limits<double>::infinity())
- , m_max(0)
- , m_count(0)
</del><ins>+ : time(0)
+ , min(std::numeric_limits<double>::infinity())
+ , max(0)
+ , count(0)
</ins><span class="cx"> {
</span><span class="cx"> }
</span><span class="cx">
</span><del>- double m_time;
- double m_min;
- double m_max;
- size_t m_count;
</del><ins>+ double time;
+ double min;
+ double max;
+ size_t count;
</ins><span class="cx"> };
</span><span class="cx">
</span><span class="cx"> void logData(const TimeRecord& data, const char* extra)
</span><span class="cx"> {
</span><del>- dataLogF("[%d] %s %s: %.2lfms (avg. %.2lf, min. %.2lf, max. %.2lf, count %lu)\n",
</del><ins>+ dataLogF("[%d] %s (Parent: %s) %s: %.2lfms (avg. %.2lf, min. %.2lf, max. %.2lf, count %lu)\n",
</ins><span class="cx"> getCurrentProcessID(),
</span><del>- 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);
</del><ins>+ name,
+ parent ? parent->name : "nullptr",
+ extra,
+ data.time * 1000,
+ data.time * 1000 / data.count,
+ data.min * 1000,
+ data.max * 1000,
+ data.count);
</ins><span class="cx"> }
</span><span class="cx">
</span><span class="cx"> void updateData(TimeRecord& data, double duration)
</span><span class="cx"> {
</span><del>- 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;
</del><ins>+ if (duration < data.min)
+ data.min = duration;
+ if (duration > data.max)
+ data.max = duration;
+ data.count++;
+ data.time += duration;
</ins><span class="cx"> }
</span><span class="cx">
</span><span class="cx"> void didFinishPhase(HeapOperation collectionType, double duration)
</span><span class="cx"> {
</span><del>- TimeRecord& data = collectionType == EdenCollection ? m_edenCollectionData : m_fullCollectionData;
</del><ins>+ TimeRecord& data = collectionType == EdenCollection ? edenCollectionData : fullCollectionData;
</ins><span class="cx"> updateData(data, duration);
</span><del>- updateData(m_allCollectionData, duration);
</del><ins>+ updateData(allCollectionData, duration);
</ins><span class="cx"> }
</span><span class="cx">
</span><del>- TimeRecord m_allCollectionData;
- TimeRecord m_fullCollectionData;
- TimeRecord m_edenCollectionData;
- const char* m_name;
</del><ins>+ static GCTimer* s_currentGlobalTimer;
+
+ TimeRecord allCollectionData;
+ TimeRecord fullCollectionData;
+ TimeRecord edenCollectionData;
+ const char* name;
+ GCTimer* parent { nullptr };
</ins><span class="cx"> };
</span><span class="cx">
</span><ins>+GCTimer* GCTimer::s_currentGlobalTimer = nullptr;
+
</ins><span class="cx"> struct GCTimerScope {
</span><del>- GCTimerScope(GCTimer* timer, HeapOperation collectionType)
- : m_timer(timer)
- , m_start(WTF::monotonicallyIncreasingTime())
- , m_collectionType(collectionType)
</del><ins>+ GCTimerScope(GCTimer& timer, HeapOperation collectionType)
+ : timer(timer)
+ , start(WTF::monotonicallyIncreasingTime())
+ , collectionType(collectionType)
</ins><span class="cx"> {
</span><ins>+ timer.parent = GCTimer::s_currentGlobalTimer;
+ GCTimer::s_currentGlobalTimer = &timer;
</ins><span class="cx"> }
</span><span class="cx"> ~GCTimerScope()
</span><span class="cx"> {
</span><del>- double delta = WTF::monotonicallyIncreasingTime() - m_start;
- m_timer->didFinishPhase(m_collectionType, delta);
</del><ins>+ double delta = WTF::monotonicallyIncreasingTime() - start;
+ timer.didFinishPhase(collectionType, delta);
+ GCTimer::s_currentGlobalTimer = timer.parent;
</ins><span class="cx"> }
</span><del>- GCTimer* m_timer;
- double m_start;
- HeapOperation m_collectionType;
</del><ins>+ GCTimer& timer;
+ double start;
+ HeapOperation collectionType;
</ins><span class="cx"> };
</span><span class="cx">
</span><span class="cx"> struct GCCounter {
</span><span class="cx"> GCCounter(const char* name)
</span><del>- : m_name(name)
- , m_count(0)
- , m_total(0)
- , m_min(10000000)
- , m_max(0)
</del><ins>+ : name(name)
+ , count(0)
+ , total(0)
+ , min(10000000)
+ , max(0)
</ins><span class="cx"> {
</span><span class="cx"> }
</span><span class="cx">
</span><del>- void count(size_t amount)
</del><ins>+ void add(size_t amount)
</ins><span class="cx"> {
</span><del>- m_count++;
- m_total += amount;
- if (amount < m_min)
- m_min = amount;
- if (amount > m_max)
- m_max = amount;
</del><ins>+ count++;
+ total += amount;
+ if (amount < min)
+ min = amount;
+ if (amount > max)
+ max = amount;
</ins><span class="cx"> }
</span><span class="cx"> ~GCCounter()
</span><span class="cx"> {
</span><del>- 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);
</del><ins>+ dataLogF("[%d] %s: %zu values (avg. %zu, min. %zu, max. %zu)\n", getCurrentProcessID(), name, total, total / count, min, max);
</ins><span class="cx"> }
</span><del>- const char* m_name;
- size_t m_count;
- size_t m_total;
- size_t m_min;
- size_t m_max;
</del><ins>+ const char* name;
+ size_t count;
+ size_t total;
+ size_t min;
+ size_t max;
</ins><span class="cx"> };
</span><span class="cx">
</span><del>-#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)
</del><ins>+#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.add(value); } while (false)
</ins><span class="cx">
</span><span class="cx"> #else
</span><span class="cx">
</span></span></pre></div>
<a id="trunkToolsChangeLog"></a>
<div class="modfile"><h4>Modified: trunk/Tools/ChangeLog (181820 => 181821)</h4>
<pre class="diff"><span>
<span class="info">--- trunk/Tools/ChangeLog 2015-03-21 00:07:17 UTC (rev 181820)
+++ trunk/Tools/ChangeLog 2015-03-21 02:02:44 UTC (rev 181821)
</span><span class="lines">@@ -1,3 +1,26 @@
</span><ins>+2015-03-20 Mark Hahnenberg <mhahnenb@gmail.com>
+
+ GCTimer should know keep track of nested GC phases
+ https://bugs.webkit.org/show_bug.cgi?id=142675
+
+ Reviewed by Darin Adler.
+
+ Adds a tool to aid in parsing the GC phase timing output into a
+ tree-like structure based on the parent-child relationships
+ of nested GC phases.
+
+ * Scripts/parse-gc-phase-timings: Added.
+ (Timing):
+ (Timing.__init__):
+ (Timing.__unicode__):
+ (Timing.__str__):
+ (Timing.__repr__):
+ (parse_input):
+ (print_timing_node):
+ (print_timing_tree):
+ (link_parents):
+ (main):
+
</ins><span class="cx"> 2015-03-20 Brent Fulgham <bfulgham@apple.com>
</span><span class="cx">
</span><span class="cx"> [Win] Temporarily turn of EWS Windows tests while I debug the test failure.
</span></span></pre></div>
<a id="trunkToolsScriptsparsegcphasetimings"></a>
<div class="addfile"><h4>Added: trunk/Tools/Scripts/parse-gc-phase-timings (0 => 181821)</h4>
<pre class="diff"><span>
<span class="info">--- trunk/Tools/Scripts/parse-gc-phase-timings (rev 0)
+++ trunk/Tools/Scripts/parse-gc-phase-timings 2015-03-21 02:02:44 UTC (rev 181821)
</span><span class="lines">@@ -0,0 +1,131 @@
</span><ins>+#!/usr/bin/env python
+
+# Copyright (C) 2015 Mark Hahnenberg. All rights reserved.
+#
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions
+# are met:
+# 1. Redistributions of source code must retain the above copyright
+# notice, this list of conditions and the following disclaimer.
+# 2. Redistributions in binary form must reproduce the above copyright
+# notice, this list of conditions and the following disclaimer in the
+# documentation and/or other materials provided with the distribution.
+#
+# THIS SOFTWARE IS PROVIDED BY APPLE INC. AND ITS CONTRIBUTORS ``AS IS''
+# AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
+# THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
+# PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL APPLE INC. OR ITS CONTRIBUTORS
+# BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
+# CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
+# SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
+# INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
+# CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
+# ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF
+# THE POSSIBILITY OF SUCH DAMAGE.
+
+import fileinput
+import re
+
+TIMING_REGEX = re.compile(
+ r'^\[(?P<pid>[0-9]+)\] '
+ '(?P<name>[^ ]+) '
+ '\(Parent: (?P<parent>[^\)]+)\) '
+ '\((?P<collect_type>[^\)]+)\): '
+ '(?P<total_time>[0-9]+\.[0-9]+)ms '
+ '\(avg. (?P<avg_time>[^,]+), '
+ 'min. (?P<min_time>[^,]+), '
+ 'max. (?P<max_time>[^,]+), '
+ 'count (?P<count>[^\)]+)\)')
+
+class Timing(object):
+ def __init__(self, pid, name, parent, collect_type, total_time, avg_time, min_time, max_time, count):
+ self.pid = int(pid)
+ self.name = str(name)
+ self.parent = str(parent)
+ self.collect_type = str(collect_type)
+ self.total_time = float(total_time)
+ self.avg_time = float(avg_time)
+ self.min_time = float(min_time)
+ self.max_time = float(max_time)
+ self.count = int(count)
+ self.children = []
+
+ def __unicode__(self):
+ return u"%s - %s total: %.2f, avg: %.2f" % (self.name, self.collect_type, self.total_time, self.avg_time)
+
+ def __str__(self):
+ return "%s - %s total: %.2f, avg: %.2f" % (self.name, self.collect_type, self.total_time, self.avg_time)
+
+ def __repr__(self):
+ return "%s - %s total: %.2f, avg: %.2f" % (self.name, self.collect_type, self.total_time, self.avg_time)
+
+
+def parse_input():
+ timings = []
+ for line in fileinput.input():
+ result = TIMING_REGEX.match(line)
+ if result is None:
+ continue
+ timings.append(Timing(
+ result.group('pid'),
+ result.group('name'),
+ result.group('parent'),
+ result.group('collect_type'),
+ result.group('total_time'),
+ result.group('avg_time'),
+ result.group('min_time'),
+ result.group('max_time'),
+ result.group('count'),
+ ))
+ return timings
+
+
+def print_timing_node(root, timings, tabs):
+ for _ in range(tabs):
+ print " ",
+ percent_time = 1.0
+ if root.parent is not None:
+ percent_time = float(root.total_time) / float(root.parent.total_time)
+ print "%s - %.2f%%" % (str(root), percent_time * 100.0)
+ for child in reversed(sorted(root.children, key=lambda t: t.total_time)):
+ if child.parent != root:
+ continue
+ if child.collect_type != root.collect_type:
+ continue
+ print_timing_node(child, timings, tabs + 1)
+
+
+def print_timing_tree(timings):
+ timings.sort(key=lambda t: t.total_time)
+ timings.reverse()
+ collection_types = ["All", "Eden", "Full"]
+ for collect_type in collection_types:
+ for timing in timings:
+ if timing.collect_type != collect_type:
+ continue
+ if timing.parent is not None:
+ continue
+ print_timing_node(timing, timings, 0)
+ print ""
+
+
+def link_parents(timings):
+ for timing in timings:
+ if timing.parent == "nullptr":
+ timing.parent = None
+ continue
+ for parent in timings:
+ if timing.parent != parent.name:
+ continue
+ if timing.collect_type != parent.collect_type:
+ continue
+ timing.parent = parent
+ parent.children.append(timing)
+
+def main():
+ timings = parse_input()
+ link_parents(timings)
+ print_timing_tree(timings)
+
+if __name__ == "__main__":
+ main()
</ins><span class="cx">Property changes on: trunk/Tools/Scripts/parse-gc-phase-timings
</span><span class="cx">___________________________________________________________________
</span></span></pre></div>
<a id="svnexecutable"></a>
<div class="addfile"><h4>Added: svn:executable</h4></div>
</div>
</body>
</html>