New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 671635 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Dec 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

overflow error for total_time in cpu.py

Project Member Reported by mikec...@chromium.org, Dec 6 2016

Issue description

@qyearsley, any idea of who would be best to look at this?

This failure might be related to some media.android.tough_video_cases failures.

It seems in the metrics/cpu.py script there can be an int overflow with the total_time variable. There seems to be a comment in the script to fix this. 

    # Fix overflow for 32-bit jiffie counter, 64-bit counter will not overflow.
    # Linux kernel starts with a value close to an overflow, so correction is
    # necessary.

The relevant code is here....

https://cs.chromium.org/chromium/src/tools/perf/metrics/cpu.py?type=cs&q=perf/metrics/cpu.py&sq=package:chromium&l=91
This code seems a big buggy. For instance, I think if the int overflows multiple times it just works incorrectly.

Below is the error we are hitting...

https://uberchromegw.corp.google.com/i/chromium.perf/builders/Android%20Nexus7v2%20Perf%20%282%29/builds/3445/steps/media.android.tough_video_cases/logs/stdio

Traceback (most recent call last):
  RunBenchmark at /b/rr/tmpqJGypr/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:343
    benchmark.ShouldTearDownStateAfterEachStorySetRun())
  Run at /b/rr/tmpqJGypr/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:229
    _RunStoryAndProcessErrorIfNeeded(story, results, state, test)
  _RunStoryAndProcessErrorIfNeeded at /b/rr/tmpqJGypr/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:87
    state.RunStory(results)
  traced_function at /b/rr/tmpqJGypr/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:52
    return func(*args, **kwargs)
  RunStory at /b/rr/tmpqJGypr/w/src/third_party/catapult/telemetry/telemetry/page/shared_page_state.py:301
    self._current_page, self._current_tab, results)
  traced_function at /b/rr/tmpqJGypr/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:52
    return func(*args, **kwargs)
  ValidateAndMeasurePage at /b/rr/tmpqJGypr/w/src/tools/perf/measurements/media.py:64
    self._cpu_metric.AddResults(tab, results, trace_name=trace_name)
  AddResults at /b/rr/tmpqJGypr/w/src/tools/perf/metrics/cpu.py:46
    cpu_stats = _SubtractCpuStats(self._stop_cpu, self._start_cpu)
  _SubtractCpuStats at /b/rr/tmpqJGypr/w/src/tools/perf/metrics/cpu.py:95
    'Expected total_time > 0, was: %d' % total_time)
AssertionError: Expected total_time > 0, was: 4252017631
 
Cc: skyos...@chromium.org qyears...@chromium.org
Owner: ----
I think skyostil@ might be best to look at this (or might know who else might be best :-D)

Note, the change that added that assertion was: https://codereview.chromium.org/362533003 (from 2014).

Comment 3 by dtu@chromium.org, Dec 6 2016

BTW the locals after the stack trace were useful in debugging here. Note the TotalTime numbers are before and after the overflow, and are accurate to the hundredths, and 2^32 (4294967296) is very close to start_cpu_stats['Gpu']['TotalTime']


Locals:
  cpu_process_time : 0.23000000000000004
  cpu_stats        : {'Gpu': {'TotalTime': 5.46, 'CpuProcessTime': 0.68}, 'Other': {}, 'Renderer': {'TotalTime': 5.46, 'CpuProcessTime': 0.91}, 'Browser': {'TotalTime': 5.46, 'CpuProcessTime': 2.51}}
  cpu_usage        : {}
  process_type     : 'Gpu'
  start_cpu_stats  : {'Gpu': {'TotalTime': 42949670.36, 'CpuProcessTime': 0.45}, 'Other': {}, 'Renderer': {'TotalTime': 42949670.36, 'CpuProcessTime': 0.63}, 'Browser': {'TotalTime': 42949670.36, 'CpuProcessTime': 2.24}}
  total_time       : 4252017631.1
Owner: dtu@chromium.org
Status: Fixed (was: Untriaged)
Excellent, thanks Dave :-D
Project Member

Comment 5 by bugdroid1@chromium.org, Dec 13 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8617703b123bda515544f1a68803e4911bf947d3

commit 8617703b123bda515544f1a68803e4911bf947d3
Author: dtu <dtu@chromium.org>
Date: Tue Dec 13 19:23:21 2016

[telemetry] Fix CPU metric jiffie overflow correction.

The jiffie counter is at 100 Hz, so the correction should be divided by 100.

BUG= 671635 

Review-Url: https://codereview.chromium.org/2560543002
Cr-Commit-Position: refs/heads/master@{#438248}

[modify] https://crrev.com/8617703b123bda515544f1a68803e4911bf947d3/tools/perf/metrics/cpu.py
[modify] https://crrev.com/8617703b123bda515544f1a68803e4911bf947d3/tools/perf/metrics/cpu_unittest.py

Sign in to add a comment