972847 - Characterize the time offset between profile slices and ammeter samples

Status: RESOLVED FIXED

(Powertool Graveyard :: Software, defect, P2)

Description

[Jon Hylands [:jhylands]]

When using Benoit's patch in bug 928475, there is an approximate 40-50 ms offset in the millisecond counter between the ammeter timestamps and the profiler timestamps. Account for this time, and if possible, eliminate it in a way that is reasonable (i.e., not hacked or hard-coded).

Comment 1

[Jon Hylands [:jhylands]]

After doing some analysis, I have determined that almost none of that offset is coming from the ammeter side of things. I added some pin-toggles to the ammeter code, and hooked up my logic analyzer while retrieving a sample, which allows me to measure the timings of the pin changes with sub-microsecond accuracy.

It takes about 7.75 ms to request and retrieve a sample from the ammeter. The timestamp for the sample is set between 0.2 and 0.45 ms from the end of this period.

Here's a timeline that illustrates what is happening:

Time 0 ms - (q)
  - send packet from PC
Time 0 ms
  - receive packet on AVR
  - average 10 samples from A/D converter
  - create sample from average
Time 7.3 ms
  - set ms counter
  - create response packet & send back
Time 7.5 ms

  - receive data on PC
Time 7.5 ms + (r)

On my machine, (q) and (r) combined are ~0.25 ms.

Comment 2

[Jon Hylands [:jhylands]]

I have to update the timeline, I mistakenly hit "Enter" which saved the changes before I was done:

Time 0 ms - (q)
  - send packet from PC
Time 0 ms
  - receive packet on AVR (ammeter)
  - retrieve 10 readings from A/D converter
  - create sample from average
Time 7.3 ms
  - set ms counter
  - create response packet & send back
Time 7.5 ms
  - done on AVR (ammeter)
Time 7.5 ms + (r)
  - received data on PC

On my machine, (q) and (r) combined are ~0.25 ms.

So this implies that the ammeter is only responsible for at most 3-4 ms of the time difference.

Comment 3

[Jon Hylands [:jhylands]]

So, it turns out the time difference was 50ms because the clocks for the phone and the desktop were more or less in sync (part of the normal flash process syncs the clocks). Today my phone clock is about 5 hours off, and the timestamps do not line up at all.

I talked to Benoit, and it looks like it was more or less depending on the two clocks being in sync. I'm going to add a piece to the profiler script that gets the timestamp from the phone, and calculates the offset properly to make sure the profiler timestamps are in sync with the ammeter timestamps.

Comment 4

[Jon Hylands [:jhylands]]

The code for this has been attached to bug 928475