Last Comment Bug 672207 - Add image decoding telemetry
: Add image decoding telemetry
Status: RESOLVED FIXED
:
Product: Core
Classification: Components
Component: ImageLib (show other bugs)
: unspecified
: x86 Mac OS X
: -- normal (vote)
: mozilla8
Assigned To: Nobody; OK to take it and work on it
:
: Milan Sreckovic [:milan]
Mentors:
Depends on:
Blocks: 666352 673176
  Show dependency treegraph
 
Reported: 2011-07-18 08:09 PDT by Jeff Muizelaar [:jrmuizel]
Modified: 2011-08-05 13:21 PDT (History)
5 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Switch away from nsTime in favour of TimeStamp/TimeDuration. (2.09 KB, patch)
2011-07-18 08:12 PDT, Jeff Muizelaar [:jrmuizel]
joe: review+
Details | Diff | Splinter Review
Time how long we spend in the decode loop. (1.78 KB, patch)
2011-07-18 08:15 PDT, Jeff Muizelaar [:jrmuizel]
joe: review-
Details | Diff | Splinter Review
Time how long we spend in the decode loop. v2 (3.81 KB, patch)
2011-07-18 08:56 PDT, Jeff Muizelaar [:jrmuizel]
justin.lebar+bug: review+
joe: review+
Details | Diff | Splinter Review
Add toMicroseconds() (1013 bytes, patch)
2011-07-18 08:58 PDT, Jeff Muizelaar [:jrmuizel]
cjones.bugs: review+
Details | Diff | Splinter Review
Remove some PRBools that were hurting my eyes. (6.84 KB, patch)
2011-07-18 08:59 PDT, Jeff Muizelaar [:jrmuizel]
joe: review-
Details | Diff | Splinter Review
Accumulate metrics on the total time spent decoding images (4.34 KB, patch)
2011-07-20 15:06 PDT, Jeff Muizelaar [:jrmuizel]
justin.lebar+bug: review+
joe: review+
Details | Diff | Splinter Review

Description Jeff Muizelaar [:jrmuizel] 2011-07-18 08:09:45 PDT
This is needed for tuning some of the behavior here.
Comment 1 Jeff Muizelaar [:jrmuizel] 2011-07-18 08:12:01 PDT
Created attachment 546536 [details] [diff] [review]
Switch away from nsTime in favour of TimeStamp/TimeDuration.
Comment 2 Justin Lebar (not reading bugmail) 2011-07-18 08:13:54 PDT
From bug 666352 comment 25, the two metrics we're interested in are:

> 1) Start the clock just before we decode a block, and stop the clock just
> after we finish decoding it.  Here we'd want to check how closely we're
> meeting our 5ms (or however-long) goal.

> 2) Time how long it takes to decode a block, and then report the number of
> bytes in that block divided by the time.
Comment 3 Jeff Muizelaar [:jrmuizel] 2011-07-18 08:15:19 PDT
Created attachment 546538 [details] [diff] [review]
Time how long we spend in the decode loop.

For now this is a global counter, the eventual plan is to make this per image format. This will be our proxy for how long we block the event loop.
Comment 4 Joe Drew (not getting mail) 2011-07-18 08:40:55 PDT
Comment on attachment 546536 [details] [diff] [review]
Switch away from nsTime in favour of TimeStamp/TimeDuration.

Review of attachment 546536 [details] [diff] [review]:
-----------------------------------------------------------------
Comment 5 Joe Drew (not getting mail) 2011-07-18 08:41:21 PDT
Comment on attachment 546538 [details] [diff] [review]
Time how long we spend in the decode loop.

Review of attachment 546538 [details] [diff] [review]:
-----------------------------------------------------------------
Comment 6 Jeff Muizelaar [:jrmuizel] 2011-07-18 08:56:12 PDT
Created attachment 546548 [details] [diff] [review]
Time how long we spend in the decode loop. v2

Upload the correct patch this time.
Comment 7 Jeff Muizelaar [:jrmuizel] 2011-07-18 08:58:33 PDT
Created attachment 546549 [details] [diff] [review]
Add toMicroseconds()

The times we're measuring here are going to be on the order of 5 milliseconds so the extra precision would be nice.
Comment 8 Jeff Muizelaar [:jrmuizel] 2011-07-18 08:59:44 PDT
Created attachment 546550 [details] [diff] [review]
Remove some PRBools that were hurting my eyes.
Comment 9 Joe Drew (not getting mail) 2011-07-18 09:01:16 PDT
Comment on attachment 546550 [details] [diff] [review]
Remove some PRBools that were hurting my eyes.

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

different bug plz
Comment 10 Joe Drew (not getting mail) 2011-07-18 09:11:06 PDT
Comment on attachment 546548 [details] [diff] [review]
Time how long we spend in the decode loop. v2

Review of attachment 546548 [details] [diff] [review]:
-----------------------------------------------------------------
Comment 11 Boris Zbarsky [:bz] (still a bit busy) 2011-07-18 09:17:54 PDT
Comment on attachment 546549 [details] [diff] [review]
Add toMicroseconds()

This is totally Chris' bailiwick.
Comment 12 Justin Lebar (not reading bugmail) 2011-07-18 09:30:18 PDT
Comment on attachment 546548 [details] [diff] [review]
Time how long we spend in the decode loop. v2

>+HISTOGRAM(IMAGE_DECODE_LATENCY, 1, 10000, 50, EXPONENTIAL, "Time spent on a single event loop of image decoding")

 * Please indicate units (us).

 * I don't think (1, 10000) is right, because then the largest value we can see is 10ms.  How about (100, 50000000), which would let us see between .1ms and 5s?  (I don't expect anyone to actually take 5s to decode a block, but if we don't set the max bucket that high, we'll never know!)

 * I don't like "time spent on a single event loop", since an "event loop" isn't the same as a "trip through the event loop".  How about "Time spent decoding one image chunk"?

r=me with fixes to this line.
Comment 13 Justin Lebar (not reading bugmail) 2011-07-18 09:32:25 PDT
>  * I don't think (1, 10000) is right, because then the largest value we can see is 10ms.

Unless you wrote this patch with the assumption that we'd turn the time-before-yield knob down to 5ms at the same time as we landed this?  In that case, I'd still think 10ms is too low, but 5s would probably be overkill.
Comment 14 Chris Jones [:cjones] inactive; ni?/f?/r? if you need me 2011-07-18 09:32:46 PDT
Comment on attachment 546549 [details] [diff] [review]
Add toMicroseconds()

You're only going to get this resolution on linux-desktop, but OK.  Bug 539093 might be relevant to your interests.

>+  double ToMicroseconds() const {
>+    return ToSeconds() * 1000.0 * 1000.0;

|ToMilliseconds() * 1000.0| plz,
Comment 15 Marco Bonardo [::mak] 2011-07-20 06:48:26 PDT
http://hg.mozilla.org/mozilla-central/rev/0798b3817dc9
Comment 16 Justin Lebar (not reading bugmail) 2011-07-20 06:51:47 PDT
This isn't fixed; the patch which was checked in is just "switch away from nsTime in favour of TimeStamp/TimeDuration."
Comment 17 Jeff Muizelaar [:jrmuizel] 2011-07-20 15:06:46 PDT
Created attachment 547268 [details] [diff] [review]
Accumulate metrics on the total time spent decoding images

Do this by accumulating decode latency in mDecodeTime which is added to imgDecodeWorker.
Comment 18 Justin Lebar (not reading bugmail) 2011-07-21 06:07:39 PDT
Comment on attachment 547268 [details] [diff] [review]
Accumulate metrics on the total time spent decoding images

>+  // accumulate the total decode time
>+  mDecodeTime += decodeLatency;
>+
>   // Flush invalidations _after_ we've written everything we're going to.
>   // Furthermore, if this is a redecode, we don't want to do progressive
>   // display at all. In that case, let Decoder::PostFrameStop() do the
>   // flush once the whole frame is ready.
>   if (!image->mHasBeenDecoded) {
>     image->mInDecoder = PR_TRUE;
>     image->mDecoder->FlushInvalidations();
>     image->mInDecoder = PR_FALSE;
>   }

Do you know if FlushInvalidations() synchronously draws to the screen?  If so, we might want to either include this in one of the telemetry metrics or time it separately.
Comment 19 Marco Bonardo [::mak] 2011-07-21 06:10:42 PDT
http://hg.mozilla.org/mozilla-central/rev/d17926720805

Should this be fixed or not? why are no these patches being pushed together, and if they should not, why are no them in separate bugs? Unfortunately this just confuses things.
Comment 20 Marco Bonardo [::mak] 2011-07-21 06:17:11 PDT
http://hg.mozilla.org/mozilla-central/rev/b93040df9e2a

looks like this was the last one... please correct if I'm still wrong.
Comment 21 Jeff Muizelaar [:jrmuizel] 2011-07-21 07:10:52 PDT
(In reply to comment #19)
> http://hg.mozilla.org/mozilla-central/rev/d17926720805
> 
> Should this be fixed or not? why are no these patches being pushed together,
> and if they should not, why are no them in separate bugs? Unfortunately this
> just confuses things.

I'll close this when it's fixed. The patches aren't being pushed together because they don't have any real dependencies and aren't all done yet. Separate bugs aren't being used so that the discussion can be kept in one place.
Comment 22 Marco Bonardo [::mak] 2011-07-21 07:32:04 PDT
Well, a tracking bug for the discussion, with dependent bugs for each piece of work, would be easier to track, also for drivers.  Regarding merges, there is no time to read each single bug to figure out its status, so I guess in these cases you may have to reopen the bug each time someone merges, sorry for that.
Comment 23 Brian R. Bondy [:bbondy] 2011-07-23 11:39:08 PDT
I'm getting a build error with all of my patch queues popped on mozilla-central which seems to be from this task.  Please advise.

/mozilla-central/modules/libpr0n/src/RasterImage.cpp(2716) : error C2039: 'IMAGE_DECODE_LATENCY' : is not a member of 'mozilla::Telemetry'
/mozilla-central/modules/libpr0n/src/RasterImage.cpp(2716) : error C2065: 'IMAGE_DECODE_LATENCY' : undeclared identifier
/mozilla-central/modules/libpr0n/src/RasterImage.cpp(2716) : error C2039: 'ToMicroseconds' : is not a member of 'mozilla::TimeDuration'
Comment 24 Justin Lebar (not reading bugmail) 2011-07-23 11:46:27 PDT
The tree is not burning, and I can compile on my Linux box.  Could you please give us more details about your setup?  You might want to try deleting your objdir -- it looks like it may be out of date and not updating for some reason.
Comment 25 Brian R. Bondy [:bbondy] 2011-07-23 11:53:58 PDT
ok thanks, I will do a clean and build again.  I was only building the libpr0n directory. If you don't hear back from me (which will probably be the case), then everything is fine.
Comment 26 Joe Drew (not getting mail) 2011-07-25 13:52:43 PDT
Comment on attachment 547268 [details] [diff] [review]
Accumulate metrics on the total time spent decoding images

Review of attachment 547268 [details] [diff] [review]:
-----------------------------------------------------------------
Comment 27 Marco Bonardo [::mak] 2011-08-05 08:56:48 PDT
http://hg.mozilla.org/mozilla-central/rev/cd6c34e9b28f
Comment 28 Marco Bonardo [::mak] 2011-08-05 09:01:08 PDT
http://hg.mozilla.org/mozilla-central/rev/5be600d6e85c

Note You need to log in before you can comment on or make changes to this bug.