Revision: 15471
Author: yu...@chromium.org
Date: Wed Jul 3 07:26:38 2013
Log: 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
R=jkumme...@chromium.org, loi...@chromium.org
Review URL: https://codereview.chromium.org/18068012
http://code.google.com/p/v8/source/detail?r=15471
Modified:
/branches/bleeding_edge/test/cctest/test-cpu-profiler.cc
=======================================
--- /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Wed Jul 3
07:23:34 2013
+++ /branches/bleeding_edge/test/cctest/test-cpu-profiler.cc Wed Jul 3
07:26:38 2013
@@ -1087,8 +1087,13 @@
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 is_gc_stress_testing =
+ (i::FLAG_gc_interval != -1) || i::FLAG_stress_compaction;
+ const v8::CpuProfileNode* startNode = FindChild(root, "start");
+ CHECK(is_gc_stress_testing || startNode);
+ if (startNode) {
ScopedVector<v8::Handle<v8::String> > names(2);
names[0] = v8::String::New("bar");
names[1] = v8::String::New("call");
--
--
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.
