Reviewers: Jakob, Yang, loislo,
Description:
Fix test-cpu-profiler/FunctionCallSample flakiness under GC stress testing
The test flakes on "V8 GC Stress" bots and the sample looks like this:
[Top down]:
90 0 (root) [-1] #0 1
1 1 (program) [-1] #0 2
89 89 (garbage collector) [-1] #0 3
which means that almost all samples are inside GC and we have no |start|
node in
the collected profile.
Running the test with different combinations of --gc-interval=500 and
--stress-compaction flags gives the results quoted below. They don't give a
ground to require |start| node presense in the profile when doing GC stress
testing. So this change makes the |start| node optional in the collected
profile
if GC stress testing is on.
$ ./out/ia32.debug/cctest --gc-interval=500 --stress-compaction --trace-gc
test-cpu-profiler/FunctionCallSample
[10291] 76 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 49.5 ms (+ 0.2
ms
in 1 steps since start of marking, biggest step 0.2 ms) [StackGuard GC
request]
[GC in old space requested].
[10291] 110 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 25.3 ms
[Logger::LogCompiledFunctions] [GC in old space requested].
[10291] 135 ms: Mark-sweep 0.4 (17.8) -> 0.4 (17.8) MB, 22.8 ms
[Logger::LogAccessorCallbacks] [GC in old space requested].
[10291] 179 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 39.9 ms (+ 0.1
ms
in 1 steps since start of marking, biggest step 0.1 ms)
[Runtime::PerformGC] [GC
in old space forced by flags].
[10291] 209 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 29.1 ms (+ 0.1
ms
in 1 steps since start of marking, biggest step 0.1 ms)
[Runtime::PerformGC] [GC
in old space forced by flags].
[10291] 240 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 29.1 ms (+ 0.1
ms
in 1 steps since start of marking, biggest step 0.1 ms)
[Runtime::PerformGC] [GC
in old space forced by flags].
[Top down]:
99 0 (root) [-1] #0 1
4 4 start [-1] #16 3
93 93 (garbage collector) [-1] #0 4
2 2 (program) [-1] #0 2
$ ./out/ia32.debug/cctest --gc-interval=500 --trace-gc
test-cpu-profiler/FunctionCallSample
[10328] 46 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 14.9 ms
[Logger::LogCompiledFunctions] [GC in old space requested].
[10328] 61 ms: Mark-sweep 0.4 (17.8) -> 0.4 (17.8) MB, 12.9 ms
[Logger::LogAccessorCallbacks] [GC in old space requested].
[10328] 65 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.3 ms
[Runtime::PerformGC].
[10328] 67 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.3 ms
[Runtime::PerformGC].
[10328] 69 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 70 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 72 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 73 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 75 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 77 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 78 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 80 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 81 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 83 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 85 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 86 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 88 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 89 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 91 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 93 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 94 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.3 ms
[Runtime::PerformGC].
[10328] 96 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 97 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 99 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 101 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 102 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 104 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 105 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 107 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 109 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 110 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 112 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 113 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.3 ms
[Runtime::PerformGC].
[10328] 115 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 117 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 118 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 120 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 121 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 123 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 125 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 126 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 128 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 129 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 131 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 133 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 134 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 136 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 137 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 139 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 141 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 142 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 144 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.3 ms
[Runtime::PerformGC].
[10328] 145 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 147 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 149 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 150 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 152 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 153 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.3 ms
[Runtime::PerformGC].
[10328] 155 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 157 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 158 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 160 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 162 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[10328] 163 ms: Scavenge 0.5 (17.8) -> 0.4 (17.8) MB, 1.2 ms
[Runtime::PerformGC].
[Top down]:
95 0 (root) [-1] #0 1
12 11 start [-1] #16 3
1 1 bar [-1] #16 4
81 81 (garbage collector) [-1] #0 5
2 2 (program) [-1] #0 2
$ ./out/ia32.debug/cctest --stress-compaction --trace-gc
test-cpu-profiler/FunctionCallSample
[10355] 76 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 49.9 ms (+ 0.1
ms
in 1 steps since start of marking, biggest step 0.1 ms) [StackGuard GC
request]
[GC in old space requested].
[10355] 110 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 25.5 ms
[Logger::LogCompiledFunctions] [GC in old space requested].
[10355] 135 ms: Mark-sweep 0.4 (17.8) -> 0.4 (17.8) MB, 22.9 ms
[Logger::LogAccessorCallbacks] [GC in old space requested].
[10355] 189 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 49.8 ms (+ 0.2
ms
in 1 steps since start of marking, biggest step 0.2 ms) [StackGuard GC
request]
[GC in old space requested].
[10355] 234 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 42.5 ms (+ 0.1
ms
in 1 steps since start of marking, biggest step 0.1 ms) [StackGuard GC
request]
[GC in old space requested].
[10355] 278 ms: Mark-sweep 0.5 (17.8) -> 0.4 (17.8) MB, 42.5 ms (+ 0.1
ms
in 1 steps since start of marking, biggest step 0.1 ms) [StackGuard GC
request]
[GC in old space requested].
[Top down]:
135 0 (root) [-1] #0 1
6 6 start [-1] #16 3
127 127 (garbage collector) [-1] #0 4
2 2 (program) [-1] #0 2
BUG=None
Please review this at https://codereview.chromium.org/18068012/
SVN Base: https://v8.googlecode.com/svn/branches/bleeding_edge
Affected files:
M test/cctest/test-cpu-profiler.cc
Index: test/cctest/test-cpu-profiler.cc
diff --git a/test/cctest/test-cpu-profiler.cc
b/test/cctest/test-cpu-profiler.cc
index
223f5fc3925057dc70e228c8a39520c45972260b..36961a9709875933b4a0aec7237f3fcbba625f3f
100644
--- a/test/cctest/test-cpu-profiler.cc
+++ b/test/cctest/test-cpu-profiler.cc
@@ -1087,8 +1087,14 @@ TEST(FunctionCallSample) {
CheckChildrenNames(root, names);
}
- const v8::CpuProfileNode* startNode = GetChild(root, "start");
- {
+ // In case of GC stress tests all samples may be in GC phase and there
+ // won't be |start| node in the profiles.
+ bool start_node_must_exist =
+ (i::FLAG_gc_interval == -1) && !i::FLAG_stress_compaction;
+ const v8::CpuProfileNode* startNode = start_node_must_exist
+ ? GetChild(root, "start")
+ : FindChild(root, "start");
+ if (startNode) {
ScopedVector<v8::Handle<v8::String> > names(1);
names[0] = v8::String::New("bar");
CheckChildrenNames(startNode, names);
--
--
v8-dev mailing list
v8-dev@googlegroups.com
http://groups.google.com/group/v8-dev
---
You received this message because you are subscribed to the Google Groups "v8-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to v8-dev+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
