Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(139)

Issues Search
    My Issues | Starred     Open | Closed | All

Issue 18068012: Fix test-cpu-profiler/FunctionCallSample flakiness under GC stress testing (Closed)

Created:
7 years, 5 months ago by yurys
Modified:
7 years, 5 months ago
Reviewers:
Jakob Kummerow, Yang, loislo
CC:
v8-dev, alph
Visibility:
Public.

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 R=jkummerow@chromium.org, loislo@chromium.org Committed: https://code.google.com/p/v8/source/detail?r=15471

Patch Set 1 #

Unified diffs Side-by-side diffs Delta from patch set Stats (+8 lines, -2 lines) Patch
M test/cctest/test-cpu-profiler.cc View 1 chunk +8 lines, -2 lines 0 comments Download

Messages

Total messages: 4 (0 generated)
yurys
7 years, 5 months ago (2013-07-03 12:32:08 UTC) #1
loislo
lgtm
7 years, 5 months ago (2013-07-03 12:33:30 UTC) #2
Jakob Kummerow
lgtm
7 years, 5 months ago (2013-07-03 14:23:06 UTC) #3
yurys
7 years, 5 months ago (2013-07-03 14:26:44 UTC) #4
Message was sent while issue was closed. 
Committed patchset #1 manually as r15471 (presubmit successful).

Powered by Google App Engine
This is Rietveld 408576698