928475 - Add external power profiling for b2g to platform profiler

Status: RESOLVED WONTFIX

(Core :: Gecko Profiler, defect, P2)

Description

[Benoit Girard (:BenWa)]

The profiler backend and UI now supports showing power usage when profiling on modern Intel CPU by querying the PMU (see bug 769431). For b2g I can't find anything similar but it looks like we may be able to collect this information externally and sync up. Here's what the profiler would need to get this working:

A JSON array of [time, power usage] pair. Time needs to be *exactly* sync up to the system clock on the device. The larger the drift the harder it will be to use this data. Ideally we can sync to within fraction of a millisecond. If we can collect that data then we can insert that into the profile and the UI can trivial display the power data.

Comment 1

[Benoit Girard (:BenWa)]

Attachment: Modify profile.sh to use power harness

Asking dhylands since it's a toss up between him and jld for profile.sh reviews and Jon for the harness.

Comment 2

[Benoit Girard (:BenWa)]

Attachment: merge.patch

Comment 3

[Benoit Girard (:BenWa)]

This depends on bug 964096 since we will use the visualization from there.

Comment 4

[Benoit Girard (:BenWa)]

Attachment: add a jsonSampler to moz-amp harness

Comment 5

[Jon Hylands [:jhylands]]

Comment on attachment 8368779 [details] [review]
Modify profile.sh to use power harness

r+ on making simple change commented in PR

Comment 6

[Dave Hylands [:dhylands]]

Comment on attachment 8368783 [details] [diff] [review]
merge.patch

Review of attachment 8368783 [details] [diff] [review]:
-----------------------------------------------------------------

Giving r+ since my comments are all minor.

::: tools/profiler/merge-profiles.py
@@ +18,4 @@
>      minStartTime = None
>  
>      for fname in files:
> +        if fname.startswith("--power="):

You might want to look into use argparse to parse command line arguments (I'm not saying you have to do this as part of this review - mostly just something to consider).

Here's some code I've written that uses argparse.
https://github.com/dhylands/usb-ser-mon/blob/master/usb-ser-mon.py#L133

Then you get nicely formatted --help.

@@ +72,5 @@
>  
> +    for fname in files:
> +        # Empty --power param means we have no power profile
> +        if fname != "--power=" and fname.startswith("--power="):
> +            fp = open(fname[8:], "r")

If you use:

with open(fname[8:], "r") as fp:

Then fp will automatically be closed when the with goes out of scope (so similar idea to ScopedFd in C++)

@@ +81,5 @@
> +            timeOffset = powerProfile['sampleTimeEpochOffset'] - minStartTime
> +            for sample in powerProfile['samples']:
> +               sample['time'] = sample['time'] + timeOffset
> +            fp.close()
> +            

nit: trailing space

Comment 7

[Dave Hylands [:dhylands]]

Comment on attachment 8368779 [details] [review]
Modify profile.sh to use power harness

I'd like to at least see the wait_for connect/disconnect stuff cleaned up.

Comment 8

[Jon Hylands [:jhylands]]

I have the two data streams sharing the same time-base now.

I have changes to profile.sh, and merge-profiles.py

Currently, both the power samples and the profiler samples get their "timestamp" fields put in terms of the phone's RTC, in milliseconds. The numbers look like 1370048159529, which is a millisecond epoch from Jan 1, 1970

The profiler currently uses a millisecond counter that starts at zero when the profiler is first started on the phone. I could change my code to use that, or to zero-offset everything based on the specific capture.

Do you have a preference?

Comment 9

[Benoit Girard (:BenWa)]

Profile should be relative to when the profiler was started, which you can use the field startTime to normalize absolute epoch timestamps with the profiler' relative start time stamps. I'd suggest that all timestamps in the profile be relative to that. If you have measurement that occurred before the profiler was started then those value should be negative (we have that case with JS profiling).

Relative timestamp give us better floating point behavior.

Comment 10

[Jon Hylands [:jhylands]]

Attachment: merge2.patch

An extension of the original patch, does timeline sync between the phone and the pc to get the ammeter samples on the same timeline as the profile samples.

Comment 11

[Jon Hylands [:jhylands]]

Attachment: profile.patch

Added support for timeline syncing needed for the merge patch. Does not include the changes in attachment 8368779 [details] [review] (the original PR for profile.sh)

Comment 12

[Jon Hylands [:jhylands]]

Benoit, for the user interface changes to the profiler to support this, are you planning on doing them as a part of this bug, or in a separate bug?

Comment 13

[Benoit Girard (:BenWa)]

Comment on attachment 8397205 [details] [diff] [review]
profile.patch

Review of attachment 8397205 [details] [diff] [review]:
-----------------------------------------------------------------

::: profile.sh
@@ +332,5 @@
>        fi
>      done
>      if [ $profiles_count -gt 1 -o -n "$MOZ_AMP_PROFILE" ]; then
> +      PC_MILLISECONDS=$(python -c 'import time; print time.time()')
> +      adb shell log "profilerClockSync ${PC_MILLISECONDS}"

${ADB}

@@ +335,5 @@
> +      PC_MILLISECONDS=$(python -c 'import time; print time.time()')
> +      adb shell log "profilerClockSync ${PC_MILLISECONDS}"
> +      # we seem to get an offset of about ~190 ms, so compensate for it here...
> +      PC_MILLISECONDS_AFTER=$(python -c 'import time; print time.time() - 190')
> +      LINE_TEXT=$(adb logcat -v threadtime -d *:S log:I | tail -1)

adb should be ${ADB} (not sure why).

Shouldn't this also grep for profilerClockSync before tail -1 in case another log:I occurs?

Comment 14

[Benoit Girard (:BenWa)]

(In reply to Jon Hylands [:jhylands] from comment #12)
> Benoit, for the user interface changes to the profiler to support this, are
> you planning on doing them as a part of this bug, or in a separate bug?

Another bug I'd say.

Comment 15

[Jon Hylands [:jhylands]]

Attachment: profile.patch

Slight changes from previous review

Comment 16

[Jon Hylands [:jhylands]]

Comment on attachment 8368796 [details] [review]
add a jsonSampler to moz-amp harness

This is no longer needed - it has been replaced with a corresponding file in fxos-powertool (https://github.com/JonHylands/fxos-powertool/blob/master/powertool/jsonSampler.py)

Comment 17

[Benoit Girard (:BenWa)]

Comment on attachment 8403394 [details] [diff] [review]
profile.patch

Review of attachment 8403394 [details] [diff] [review]:
-----------------------------------------------------------------

This needs to be a github PR :(

Comment 18

[Jon Hylands [:jhylands]]

Attachment: Modify profile.sh for power harness

Comment 19

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

Comment on attachment 8404329 [details] [review]
Modify profile.sh for power harness

r+ with comments, over at GitHub.

Comment 20

[Ben Kelly [:bkelly, not reviewing]]

Benoit, do you still want to block on the memory usage in bug 964096?  I think the power effort is moving faster at the moment and it seems whichever one implements the visualization first could be used in the other bug.

Comment 21

[Benoit Girard (:BenWa)]

(In reply to Ben Kelly [:bkelly] from comment #20)
> Benoit, do you still want to block on the memory usage in bug 964096?  I
> think the power effort is moving faster at the moment and it seems whichever
> one implements the visualization first could be used in the other bug.

Yes I agree. We can build it out part of this effort instead.

Comment 22

[Benoit Girard (:BenWa)]

The primary goal was to correlate the power usage with the execution but it might be more work than benefit here. I think this is WONTFIX unless we start running into enough problems to justify supporting this feature.