Fix test-cpu-profiler/FunctionCallSample flakiness under GC stress testing
authoryurys@chromium.org <yurys@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Wed, 3 Jul 2013 14:26:38 +0000 (14:26 +0000)
committeryurys@chromium.org <yurys@chromium.org@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Wed, 3 Jul 2013 14:26:38 +0000 (14:26 +0000)
commit44dfaa2a1e40d607f5390b4c35c8e4d0d50e3bd7
treecaad4de09f75205eb65796a2e60cd5398a468d01
parent41c9adffc6fa30eca059d2dd90e28b3951d6f6cf
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
test/cctest/test-cpu-profiler.cc