1367962 - [NPOTB] allow iteration of the stylo styling pass to assist in profiling

Status: NEW

(Core :: CSS Parsing and Computation, defect, P5)

Description

[Julian Seward [:jseward]]

Profiling Stylo as embedded in Firefox is difficult because:

* It is a relatively small piece of a huge C++/Rust application, hence
  requiring effort to separate out relevant results in the various profilers
  in use (the Gecko profiler, VTune, Valgrind-suite tools [Callgrind, DHAT],
  and presumably Instruments).

* The styling passes typically only run for a few tens of milliseconds at
  most.  This means timing numbers from them are very noisy.  It also makes
  it impossible to observe the level of achieved parallelism by simply
  watching /usr/bin/top, since there is far too much other activity
  mixed in at the granularity of top's sampling interval (min 1 second).

The attached patch, created with a lot of help from Emilio, causes Stylo to
take note of the STYLO_ITERS environment variable.  It will then iterate
styling the specified number of times, printing an iteration counter as it
goes.  This has the following advantages:

* less noise in timing numbers

* direct visibility of parallelism in 'top'

* for profilers that can attach/detach a process (eg VTune), it makes it
  possible to collect data only when Stylo is running

* for profilers that must profile the entire run, it makes it possible
  to bias in favour of styling costs

The patch tries to identify and iterate only the top level styling pass, but
sometimes fails.  I do not claim to understand how it works.  Suggestions for
a better identification scheme are welcome.  Note however it has so far defied
various attempts at improvement.

Comment 1

[Julian Seward [:jseward]]

Attachment: bug1367962-1.diff

The patch.  Use by setting (eg) STYLO_ITERS=100 before running.

|get_stylo_iters| is one big |unsafe| block.  Those Proficient
in The Art of Rust may care to suggest how to be rid of it, although
this is not actually important for the functioning of the patch.

Comment 2

[Bobby Holley (:bholley)]

Attachment: bholley's iteration statistics patch. v1

This is my iteration patch. It's oriented towards measurement, and so the
iterations actually deallocate the entire style tree between each iteration.

When a traversal takes longer than STYLO_ITER_THRESHOLD, the traversal
will be repeated STYLO_ITERS times, with the entirety of the style data
dropped after each traversal. The traversals are timed, and statistics
are reported to the console.

With 500 or 1000 iterations, the averages are quite stable, which is good.

Comment 3

[Julian Seward [:jseward]]

(In reply to Bobby Holley (:bholley) (busy with Stylo) from comment #2)
> Created attachment 8875902 [details] [diff] [review]
> bholley's iteration statistics patch. v1

This is a big improvement.  But it can cause panicing later on, in some
circumstances that I'm not clear about, but might be timing related, since
they involve running on Valgrind.  These are always preceded by this:

  Spent 21.69212605804205 > 1 time traversing. will do 10 iterations // for example
  Mean time: 0.00, Median time: 0.00, Best time: 0.00  // always happens

The only way I can see that Mean, Median and Best are all zero, is if
the closure that you introduced, returns early here:

    let token = RecalcStyleOnly::pre_traverse(element,
                                              &shared_style_context,
                                              traversal_flags);
    if !token.should_traverse() {
        return 0.0;
    }

What then happens is a panic as below.  I wonder if somehow, the subtree
is left un-decorated after the iteration has finished?  Any ideas as how
to fix it?  I'd like to be able to use this facility reliably.

I verified that this isn't caused by multiple threads calling traverse_subtree
at the same time, by printing the gettid() values, per the next two lines.

[14809] Spent 47.36452805809677 > 1 time traversing. will do 10 iterations
[14809] Mean time: 0.00, Median time: 0.00, Best time: 0.00

thread '<unnamed>' panicked at 'called `Option::unwrap()` on a `None` value', /checkout/src/libcore/option.rs:329
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:71
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   2: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:371
             at /checkout/src/libstd/panicking.rs:549
   3: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   4: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:495
   5: core::panicking::panic_fmt
             at /checkout/src/libstd/panicking.rs:471
   6: core::panicking::panic
             at /checkout/src/libcore/panicking.rs:49
   7: Servo_TraverseSubtree
             at /checkout/src/libcore/macros.rs:21
             at ./servo/ports/geckolib/glue.rs:337
   8: _ZN7mozilla13ServoStyleSet25PrepareAndTraverseSubtreeEPKNS_3dom7ElementENS_21TraversalRootBehaviorENS_24TraversalRestyleBehaviorE
             at ./layout/style/ServoStyleSet.cpp:378
   9: _ZN7mozilla13ServoStyleSet16StyleNewChildrenEPNS_3dom7ElementE
             at ./layout/style/ServoStyleSet.cpp:953
  10: _ZN12nsXBLService12LoadBindingsEP10nsIContentP6nsIURIP12nsIPrincipalPP12nsXBLBindingPb
             at ./dom/xbl/nsXBLService.cpp:432
             at ./gcc-Og-nondebug-stylo/dist/include/mozilla/Maybe.h:446
             at ./gcc-Og-nondebug-stylo/dist/include/mozilla/Maybe.h:100
             at ./dom/xbl/nsXBLService.cpp:481
  11: _ZN21nsCSSFrameConstructor33AddFrameConstructionItemsInternalER23nsFrameConstructorStateP10nsIContentP16nsContainerFrameP7nsIAtomibP14nsStyleContextjP8nsTArrayIN26nsIAnonymousContentCreator11ContentInfoEERNS_25FrameConstructionItemListE
             at ./layout/base/nsCSSFrameConstructor.cpp:5812
[remaining frames rm'd]

Comment 4

[Bobby Holley (:bholley)]

(In reply to Julian Seward [:jseward] from comment #3)
> (In reply to Bobby Holley (:bholley) (busy with Stylo) from comment #2)
> > Created attachment 8875902 [details] [diff] [review]
> > bholley's iteration statistics patch. v1
> 
> This is a big improvement.  But it can cause panicing later on, in some
> circumstances that I'm not clear about, but might be timing related, since
> they involve running on Valgrind.  These are always preceded by this:
> 
>   Spent 21.69212605804205 > 1 time traversing. will do 10 iterations // for
> example
>   Mean time: 0.00, Median time: 0.00, Best time: 0.00  // always happens
> 
> The only way I can see that Mean, Median and Best are all zero, is if
> the closure that you introduced, returns early here:
> 
>     let token = RecalcStyleOnly::pre_traverse(element,
>                                               &shared_style_context,
>                                               traversal_flags);
>     if !token.should_traverse() {
>         return 0.0;
>     }

Have you confirmed that this is actually where it's happening? Just stick a println!() right before the "return 0.0".

If that is the case, then we need to figure out why pre_traverse (which is the thing that decides whether a traversal is needed) allows a traversal the first time but doesn't think one is warranted the second time around. This should be straightforward to diagnose via logging as well.

> 
> What then happens is a panic as below.  I wonder if somehow, the subtree
> is left un-decorated after the iteration has finished?  Any ideas as how
> to fix it?  I'd like to be able to use this facility reliably.
> 
> I verified that this isn't caused by multiple threads calling
> traverse_subtree
> at the same time, by printing the gettid() values, per the next two lines.
> 
> [14809] Spent 47.36452805809677 > 1 time traversing. will do 10 iterations
> [14809] Mean time: 0.00, Median time: 0.00, Best time: 0.00
> 
> thread '<unnamed>' panicked at 'called `Option::unwrap()` on a `None`
> value', /checkout/src/libcore/option.rs:329
> stack backtrace:
>    0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
>              at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
>    1: std::panicking::default_hook::{{closure}}
>              at /checkout/src/libstd/sys_common/backtrace.rs:71
>              at /checkout/src/libstd/sys_common/backtrace.rs:60
>              at /checkout/src/libstd/panicking.rs:355
>    2: std::panicking::rust_panic_with_hook
>              at /checkout/src/libstd/panicking.rs:371
>              at /checkout/src/libstd/panicking.rs:549
>    3: std::panicking::begin_panic
>              at /checkout/src/libstd/panicking.rs:511
>    4: std::panicking::begin_panic_fmt
>              at /checkout/src/libstd/panicking.rs:495
>    5: core::panicking::panic_fmt
>              at /checkout/src/libstd/panicking.rs:471
>    6: core::panicking::panic
>              at /checkout/src/libcore/panicking.rs:49
>    7: Servo_TraverseSubtree
>              at /checkout/src/libcore/macros.rs:21
>              at ./servo/ports/geckolib/glue.rs:337
>    8:
> _ZN7mozilla13ServoStyleSet25PrepareAndTraverseSubtreeEPKNS_3dom7ElementENS_21
> TraversalRootBehaviorENS_24TraversalRestyleBehaviorE
>              at ./layout/style/ServoStyleSet.cpp:378
>    9: _ZN7mozilla13ServoStyleSet16StyleNewChildrenEPNS_3dom7ElementE
>              at ./layout/style/ServoStyleSet.cpp:953
>   10:
> _ZN12nsXBLService12LoadBindingsEP10nsIContentP6nsIURIP12nsIPrincipalPP12nsXBL
> BindingPb
>              at ./dom/xbl/nsXBLService.cpp:432
>              at ./gcc-Og-nondebug-stylo/dist/include/mozilla/Maybe.h:446
>              at ./gcc-Og-nondebug-stylo/dist/include/mozilla/Maybe.h:100
>              at ./dom/xbl/nsXBLService.cpp:481
>   11:
> _ZN21nsCSSFrameConstructor33AddFrameConstructionItemsInternalER23nsFrameConst
> ructorStateP10nsIContentP16nsContainerFrameP7nsIAtomibP14nsStyleContextjP8nsT
> ArrayIN26nsIAnonymousContentCreator11ContentInfoEERNS_25FrameConstructionItem
> ListE
>              at ./layout/base/nsCSSFrameConstructor.cpp:5812
> [remaining frames rm'd]

Comment 5

[Julian Seward [:jseward]]

(In reply to Bobby Holley (:bholley) (busy with Stylo) from comment #4)
> Have you confirmed that this is actually where it's happening? Just stick a
> println!() right before the "return 0.0".

Verified -- see below.  I also added a println of the value returned in the
normal case and so verified that none of the 0.0's arrive from that route.

[31638] Spent 23.221340030431747 > 1 time traversing. will do 10 iterations
early  exit // #1
early  exit
early  exit
early  exit
early  exit
early  exit
early  exit
early  exit
early  exit
early  exit // #10
[31638] Mean time: 0.00, Median time: 0.00, Best time: 0.00

thread '<unnamed>' panicked at 'called `Option::unwrap()` on a `None` value', /checkout/src/libcore/option.rs:329

Comment 6

[Julian Seward [:jseward]]

(In reply to Bobby Holley (:bholley) (busy with Stylo) from comment #4)
> If that is the case, then we need to figure out why pre_traverse (which is
> the thing that decides whether a traversal is needed) allows a traversal the
> first time but doesn't think one is warranted the second time around.

pre_traverse has 3 return points, and it's the first of them that happens
(w.r.t the early-exit discussion):

        if traversal_flags.for_unstyled_children_only() {
            if root.borrow_data().map_or(true, |d| d.has_styles() && d.styles().is_display_none()) {
                return PreTraverseToken {
                    traverse: false,
                    unstyled_children_only: false,
                };

and root.borrow_data() is None, hence the map_or(true, ..) returns true (IIUC).
Does that help?

Comment 7

[Julian Seward [:jseward]]

Attachment: bug1367962-c7.cset

In the end I kludged my way out of this by giving the iteration closure a
boolean parameter which can be used to ignore the decision made by
pre_traverse().  So in the iteration phase we can force the traversal always
to be done.  Seems to work, at least with a bit of superficial testing.

Comment 8

[Bobby Holley (:bholley)]

(In reply to Julian Seward [:jseward] from comment #6)
> (In reply to Bobby Holley (:bholley) (busy with Stylo) from comment #4)
> > If that is the case, then we need to figure out why pre_traverse (which is
> > the thing that decides whether a traversal is needed) allows a traversal the
> > first time but doesn't think one is warranted the second time around.
> 
> pre_traverse has 3 return points, and it's the first of them that happens
> (w.r.t the early-exit discussion):
> 
>         if traversal_flags.for_unstyled_children_only() {
>             if root.borrow_data().map_or(true, |d| d.has_styles() &&
> d.styles().is_display_none()) {
>                 return PreTraverseToken {
>                     traverse: false,
>                     unstyled_children_only: false,
>                 };
> 
> and root.borrow_data() is None, hence the map_or(true, ..) returns true
> (IIUC).
> Does that help?

Oh yeah ok, that makes sense. So that means we're in the mode where we're styling the children but not the parent, and if the parent is unstyled, we bail. Normally the parent wouldn't be unstyled, except my patch explicitly drops the style for the parent.

So the most 'correct' fix here is to check whether this is an unstyled-children-only traversal, and make the |element.clear_data();| conditional on that. But your fix is probably fine too.

Comment 9

[Chris Peterson [:cpeterson]]

status-firefox57=wontfix unless someone thinks this bug should block 57