Closed Bug 1071056 Opened 5 years ago Closed 5 years ago

[timeline] popTimelineProfileMarkers clear un-matched markers

Categories

(DevTools :: Performance Tools (Profiler/Timeline), defect)

x86_64
All
defect
Not set

Tracking

(firefox36 verified)

VERIFIED FIXED
Firefox 36
Tracking Status
firefox36 --- verified

People

(Reporter: paul, Assigned: tromey)

References

Details

Attachments

(2 files, 12 obsolete files)

4.42 KB, patch
Details | Diff | Splinter Review
4.89 KB, patch
Details | Diff | Splinter Review
Attached patch failing test (obsolete) — Splinter Review
Today, popTimelineProfileMarkers clears all the markers, even if it didn't find a corresponding END marker to a START marker. That means if we add a START marker and popTimelineProfileMarkers is called before the END is added, we loose the marker.

This didn't occur yet with the set of markers we have because adding START and END always happen in the same tick, but I'm trying to fix bug 1050502, and it's impossible as calling console.timeEnd() happens too late.

We should only clear the markers that have an END marker.

I wrote a test to highlight this behavior.
Blocks: 1050502
To run this test:

> /mach mochitest-browser ./docshell/test/browser/browser_timelineMarkers_consoleTime.js
FWIW this will be a little simpler when bug 1071105 is fixed,
as it will make dealing with the array's memory easier.
This patch preserves the START markers and makes the attached test
case pass.  You will need the patch from
https://bugzilla.mozilla.org/show_bug.cgi?id=1071105 first in order
for this to build.
Here's a version that doesn't depend on the earlier incorrect patch.
Attachment #8493542 - Flags: feedback?(pbrosset)
Comment on attachment 8493542 [details] [diff] [review]
preserve unpaired START markers until next pop

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

Looks ok to me. This way, unpaired start markers will remain in the array until we see a corresponding end marker.
I can see 2 potential problems with the approach though:

- the UI won't be able to display anything until we get both start and end together. If the goal is to use this mechanism to allow console.timeline to work, we have to ask ourselves if we want the UI block to start appearing before the end marker has been generated.

- Secondly, do we want to support nesting? Like:

|------------------|
start1             end1
     |--------|
     start2   end2
  *              *
  pop            pop

At the first pop, start1 isn't paired, so we keep it. At the second pop, we look at start1, then iterate until we find a end marker, and we pair it incorrectly with end2 as we have no way to differentiate end1 from end2 right now.
Maybe this second problem isn't exactly related to this bug though, but if the goal is to make console.time work, then it's definitely something we need to take into consideration.
Attachment #8493542 - Flags: feedback?(pbrosset)
(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #5)
> Comment on attachment 8493542 [details] [diff] [review]
> preserve unpaired START markers until next pop
> 
> Review of attachment 8493542 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks ok to me. This way, unpaired start markers will remain in the array
> until we see a corresponding end marker.
> I can see 2 potential problems with the approach though:
> 
> - the UI won't be able to display anything until we get both start and end
> together. If the goal is to use this mechanism to allow console.timeline to
> work, we have to ask ourselves if we want the UI block to start appearing
> before the end marker has been generated.

I think it's ok to not show markers in the overview until we get END.

> 
> - Secondly, do we want to support nesting? Like:
> 
> |------------------|
> start1             end1
>      |--------|
>      start2   end2
>   *              *
>   pop            pop
> 
> At the first pop, start1 isn't paired, so we keep it. At the second pop, we
> look at start1, then iterate until we find a end marker, and we pair it
> incorrectly with end2 as we have no way to differentiate end1 from end2
> right now.
> Maybe this second problem isn't exactly related to this bug though,

It's not.

> but if
> the goal is to make console.time work, then it's definitely something we
> need to take into consideration.

console.time doesn't support nesting.
This patch makes Firefox segfault here.
Attached patch WIP (obsolete) — Splinter Review
Apparently, the console methods are executed in asynchronously :(

> console.time("X")
> create sync reflow
> consle.timeEnd("X")

We see the X marker happen after the reflow :/

I can move the code in the sync part of the call.
Assignee: ttromey → paul
Status: NEW → ASSIGNED
Comment on attachment 8493753 [details] [diff] [review]
WIP

Wrong bug, sorry!
Attachment #8493753 - Attachment is obsolete: true
Assignee: paul → ttromey
Attachment #8493244 - Attachment is obsolete: true
Fixes my various thinkos.
Attachment #8493542 - Attachment is obsolete: true
The same patch but rebased onto the patch from bug 1065954
Bug 1065954 is ready to land. Is this patch ready for review?
Depends on: 1065954
I think those try failures are all intermittent ones.  Two of them are marked
as such and the remaining one (Windows 7 Debug) looks very similar to the
Windows 8 Debug failure.
Still, not sure what to do here.
Attachment #8493150 - Attachment is obsolete: true
Attachment #8493776 - Attachment is obsolete: true
Attachment #8494030 - Flags: review?(bgirard)
Tom, you can click on the orange, then on the "+" button (bottom left corner) to retrigger the test and see if it's intermittent or not. I retriggered the test for you.
Yep. Looks very much unrelated to me.
Comment on attachment 8494030 [details] [diff] [review]
preserve unpaired START markers until next pop

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

r- because I think this can be simpler and I'd like to see the next iteration.

::: docshell/base/nsDocShell.cpp
@@ +2896,5 @@
> +
> +      // If we did not see the corresponding END, keep the START.
> +      if (!hasSeenEnd) {
> +        if (i != next_kept_index) {
> +          mProfileTimelineMarkers[next_kept_index] = mProfileTimelineMarkers[i];

This is really complicated and I can't convince myself that it's correct. It looks like you're doing this to optimize the code. I'm not convinced that in practice it's actually that efficient because this line is an insertion (i.e. we're not doing this in-place).

Can we just go for the straight forward way to write this here? Allocate a new 'keep' array. When we want to keep an unpaired start move it to the 'keep' array. And the end of the loop you can clear mProfileTimelineMarkers and move everything from 'keep' to mProfileTimelineMarkers.

@@ +2906,5 @@
>  
>    ToJSValue(aCx, profileTimelineMarkers, aProfileTimelineMarkers);
>  
> +  for (uint32_t i = next_kept_index; i < mProfileTimelineMarkers.Length(); ++i) {
> +    if (mProfileTimelineMarkers[i]) {

We shouldn't have any null items in our array AFAIK. Let's avoid that unless we have a reason to store null entries.
Attachment #8494030 - Flags: review?(bgirard) → review-
(In reply to Benoit Girard (:BenWa) from comment #17)
 
> > +  for (uint32_t i = next_kept_index; i < mProfileTimelineMarkers.Length(); ++i) {
> > +    if (mProfileTimelineMarkers[i]) {
> 
> We shouldn't have any null items in our array AFAIK. Let's avoid that unless
> we have a reason to store null entries.

The null is a side effect of the earlier assignment, because mProfileTimelineMarkers
holds an nsAutoPtr<>.  So it's either a null check or allocating a copy.  I'll do the
copy unless you want me to add the check to ClearProfileTimelineMarkers as well.

Another solution would be to make the mPayload field an nsAutoPtr.  This would eliminate
the need for explicit deletes, at the cost of some obfuscation (at least at the point
where the "keeping" is done if that makes sense).
I think this version addresses the review comments.
I wasn't sure how you felt about decltype but I went ahead
with that.  Easy to change if you dislike it.

The try is still working
https://tbpl.mozilla.org/?tree=Try&rev=18d095578235
(That one includes Paul's test case, not suitable for this patch,
but handy for actually trying the functionality.)
Attachment #8494030 - Attachment is obsolete: true
Attachment #8496226 - Flags: review?(bgirard)
Attachment #8496226 - Flags: review?(bgirard) → review-
Could you say why?
I don't know what to change.
Sorry my review comments got deleted (bad token).

You don't have a valid copy constructor since you don't deep copy the fields. You 'correct' this by messing with the pointer but this is a bad OOP design. Also new'ing a object is a bad way to copy it. There no guarantee that the object you new will be identical according to the implied constructor API (i.e. it's not a copy constructor, i.e. if we take timestamp we will have a newer timestamps and thus not a copy).

Let's use make the nsTArray track pointers instead of objects then we can just remove/append the object.
(In reply to Benoit Girard (:BenWa) from comment #21)
> Sorry my review comments got deleted (bad token).
> 
> You don't have a valid copy constructor since you don't deep copy the
> fields. You 'correct' this by messing with the pointer but this is a bad OOP
> design.

Yeah -- I was just copying the existing approach in the code,
in particular how clearing works.  The fundamental issue is that 
InternalProfileTimelineMarker does not have a destructor, so the nsDocShell
is responsible for tracking the payload memory.

This is why I suggested using an nsAutoPtr there.

> Also new'ing a object is a bad way to copy it. There no guarantee
> that the object you new will be identical according to the implied
> constructor API (i.e. it's not a copy constructor, i.e. if we take timestamp
> we will have a newer timestamps and thus not a copy).

The constructor copies the time.

> 
> Let's use make the nsTArray track pointers instead of objects then we can
> just remove/append the object.

This is the part I don't understand.  The nsTArray does track pointers --
but they are "auto" pointers.  We could certainly change the assignment to avoid
the "new":

keptMarkers.AppendElement(mProfileTimelineMarkers[i]);

... but this will nullify the entry in mProfileTimelineMarkers.

I think there are two decent solutions.

One would be to make mPayload itself an nsAutoPtr.  This way the implicit
destructor would do the right thing.

Another would be to add a destructor as mentioned above.

Both of these solutions would involve removing the explicit delete
from the 'clear' function, which I think would be a net plus.

If you let me know which you prefer, I will implement it.  Thanks.

If on the other hand you'd prefer the nsTArray to track raw (not auto)
pointers, that's fine too.  That will involve more deletes elsewhere.
It was easy to write the patch all three ways.
I'll upload them so you can see what you like more directly.
This variant uses nsAutoPtr to manage mPayload.  This lets us remove
the explicit memory management code from ClearProfileTimelineMarkers.
This variant adds a destructor to InternalProfileTimelineMarker,
to clean up the payload.  This way we can remove explicit memory
management from ClearProfileTimelineMarkers and also avoid messing
with it when moving an nsAutoPtr from mProfileTimelineMarkers to the
"keptMarkers" array.
This variant changes the mProfileTimelineMarkers to hold a plain
pointer rather than an nsAutoPtr.  Also, following what I understood
comment #21 to say, I wrote the code to remove the pointer from
mProfileTimelineMarkers and append it so keptMarkers (rather than,
say, setting the mProfileTimelineMarkers entry to nullptr).
Attachment #8496226 - Attachment is obsolete: true
Please let me know which of these you prefer.
Flags: needinfo?(bgirard)
Attachment #8498128 - Flags: review?(bgirard)
Attachment #8498130 - Flags: review?(bgirard)
Attachment #8498131 - Flags: review?(bgirard)
Benoit, review-spamming you. We need to move forward with this bug.
Comment on attachment 8498131 [details] [diff] [review]
preserve unpaired START markers until next pop

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

::: docshell/base/nsDocShell.cpp
@@ +2956,5 @@
>  nsDocShell::ClearProfileTimelineMarkers()
>  {
>  #ifdef MOZ_ENABLE_PROFILER_SPS
>    for (uint32_t i = 0; i < mProfileTimelineMarkers.Length(); ++i) {
>      delete mProfileTimelineMarkers[i]->mPayload;

Can you move this to the destructor for InternalProfileTimelineMarker like in your other path?
Attachment #8498131 - Flags: review?(bgirard) → review+
Attachment #8498130 - Flags: review?(bgirard)
Flags: needinfo?(bgirard)
Attachment #8498128 - Flags: review?(bgirard)
This version introduces a destructor for InternalProfileTimelineMarker
but also changes mProfileTimelineStartTime to hold a raw pointer
rather than an auto pointer.
Attachment #8498128 - Attachment is obsolete: true
Attachment #8498130 - Attachment is obsolete: true
Attachment #8498131 - Attachment is obsolete: true
Attachment #8502692 - Flags: review?(bgirard)
Attachment #8502692 - Flags: review?(bgirard) → review+
Keywords: checkin-needed
Hi Tom, seems this patch didn't apply cleanly:

patching file docshell/base/nsDocShell.cpp
Hunk #2 succeeded at 2883 with fuzz 1 (offset 1 lines).
patching file docshell/base/nsDocShell.h
Hunk #1 FAILED at 952
1 out of 1 hunks FAILED -- saving rejects to file docshell/base/nsDocShell.h.rej


could you take a look and maybe rebase against a current tree, thanks!
Flags: needinfo?(ttromey)
Keywords: checkin-needed
Hi!  Sorry about the difficulty there.

I don't know what happened, since rebasing didn't give any issues at
all.

Anyway this version is based on mozilla-central from today, aka
changeset:   209753:097821fd89ed

I hope this one applies ok :)
Attachment #8502692 - Attachment is obsolete: true
FWIW the patch turns out identically if I rebase onto fx-team.
Flags: needinfo?(ttromey)
Rebased just now onto fx-team.

I neglected to mark this checkin-needed again; I'll do it now.
Attachment #8503140 - Attachment is obsolete: true
Keywords: checkin-needed
Bustage, let's take the time to fix this properly and not hold up the tree.

https://hg.mozilla.org/integration/mozilla-inbound/rev/bc585ed304a4
I'm sorry about the breakage.

This version adds the missing #include to nsDocShell.h,
eliminating the warning.
https://hg.mozilla.org/mozilla-central/rev/0a3982b6cf3a
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 36
Depends on: 1082990
Comment on attachment 8504282 [details] [diff] [review]
preserve unpaired START markers until next pop

>+++ b/docshell/base/nsDocShell.cpp
This should have got a docshell peer review.


>+  // If we see an unpaired START, we keep it around for the next call
>+  // to PopProfileTimelineMarkers.  We store the kept START objects in
>+  // this array.
>+  decltype(mProfileTimelineMarkers) keptMarkers;
Please don't use decltype. It makes the code harder to read.
(In reply to Olli Pettay [:smaug] from comment #40)
> Comment on attachment 8504282 [details] [diff] [review]
> preserve unpaired START markers until next pop
> 
> >+++ b/docshell/base/nsDocShell.cpp
> This should have got a docshell peer review.

I'm very sorry!
At the time I thought I had done the right thing.

> >+  // If we see an unpaired START, we keep it around for the next call
> >+  // to PopProfileTimelineMarkers.  We store the kept START objects in
> >+  // this array.
> >+  decltype(mProfileTimelineMarkers) keptMarkers;
> Please don't use decltype. It makes the code harder to read.

I will file a follow-up.
Tom, does this patch require manual QA coverage? If that's the case, please provide some information on how to verify it and set the qe-verify flag accordingly.
Flags: qe-verify?
Flags: needinfo?(ttromey)
(In reply to Andrei Vaida, QA [:avaida] from comment #42)
> Tom, does this patch require manual QA coverage? If that's the case, please
> provide some information on how to verify it and set the qe-verify flag
> accordingly.

This problem could only be seen when a preliminary patch for bug 1050502 was applied.
If the test case in that bug works, then this patch is ok.
Flags: needinfo?(ttromey)
(In reply to Tom Tromey :tromey from comment #43)
> (In reply to Andrei Vaida, QA [:avaida] from comment #42)
> > Tom, does this patch require manual QA coverage? If that's the case, please
> > provide some information on how to verify it and set the qe-verify flag
> > accordingly.
> 
> This problem could only be seen when a preliminary patch for bug 1050502 was
> applied.
> If the test case in that bug works, then this patch is ok.

Thank you, Tom. I'll make sure this gets looked at.
Flags: qe-verify? → qe-verify+
QA Contact: andrei.vaida
Verified fixed on Nightly 36.0a1 (2014-11-10), based on the testing performed in Bug 1050502. Tests covered multiple console markers under Windows 7 64-bit, Mac OS X 10.9.5 and Ubuntu 14.04 LTS 32-bit.
Status: RESOLVED → VERIFIED
Sorry for the spam. Moving bugs to Firefox :: Developer Tools: Performance Tools (Profiler/Timeline).

dkl
Component: Developer Tools: Timeline → Developer Tools: Performance Tools (Profiler/Timeline)
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.