Skip to content

V
V8
Commit 44dfaa2a authored by yurys@chromium.org's avatar yurys@chromium.org
Browse files
Options

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=jkummerow@chromium.org, loislo@chromium.org

Review URL: https://codereview.chromium.org/18068012

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@15471 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
parent 41c9adff
Hide whitespace changes
Inline Side-by-side
Showing with 7 additions and 2 deletions
test/cctest/test-cpu-profiler.cc
View file @ 44dfaa2a
......@@ -1087,8 +1087,13 @@ 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 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");
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment