1361372 - Many short lived allocations associated with font processing

Status: RESOLVED WORKSFORME

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

Description

[Julian Seward [:jseward]]

This is with a Stylo enabled build.  I don't know if it actually has anything
to do with Stylo, so please feel free to reclassify as appropriate.

STR: mozconfig as below.  Test case is the Wikipedia Obama web page,
from a local file.  Platform is x86_64-linux (F25).  Command:

Run valgrind-listener in a different terminal, then:

STYLO_THREADS=8 DUMP_STYLE_STATISTICS=2 DISPLAY=:2 /home/sewardj/VgTRUNK/progress/Inst/bin/valgrind --progress-interval=10 --num-transtab-sectors=48 --px-default=allregs-at-mem-access --px-file-backed=unwindregs-at-mem-access --fair-sched=yes --fullpath-after=/MOZ/ --trace-children=yes --error-limit=no --read-inline-info=yes --tool=exp-dhat --sort-by=tot-blocks-allocd --show-top-n=1000 --num-callers=8 --log-socket=127.0.0.1 ./mach run --disable-e10s file:///home/sewardj/MOZ/STYLO/Barack_Obama_Wikipedia.html 2>&1 | cat

The main process runs for 20.257 billion insns, allocating 901.1 MB in
2,168,952 blocks.  Of those, around 265,000 (12%) are allocated by chains
of the form 

   gfxFont* -> Fc* (several of) -> FcValueSave -> strdup -> malloc

and they have very short lifetimes, typically 0.01% of the program
lifetime, and often even less.  See "12 of 1000" in the log, which has
11739 blocks with a lifetime of just 526 instructions, that is, 
2.6e-8 of the program's lifetime.

I don't know if this behaviour is expected or avoidable, but it seems
strange enough to warrant a bug report.



------------------------ mozconfig:
. $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/gcc-Og-nondebug-stylo
ac_add_options --enable-tests
ac_add_options --enable-optimize="-g -Og"
ac_add_options --enable-debug-symbols
ac_add_options --enable-stylo
ac_add_options --enable-valgrind
ac_add_options --enable-profiling
ac_add_options --enable-elf-hack
ac_add_options --disable-crashreporter

mk_add_options MOZ_MAKE_FLAGS="-j8"
mk_add_options AUTOCLOBBER=1

Comment 1

[Julian Seward [:jseward]]

Attachment: DHAT output (the relevant bits thereof)

Comment 2

[Ben Kelly [:bkelly, not reviewing]]

In case this is not stylo specific...

Comment 3

[Julian Seward [:jseward]]

Who would be a good contact for this?  It may not be Stylo specific,
but given that we're allocating at the rate of 1 byte every 22 machine
instructions here, it's all extra overhead that it would be good to
avoid if possible.

Comment 4

[Emilio Cobos Álvarez (:emilio)]

These seem to come from FontConfig... Jonathan Kew is probably a good guess.

Also, the platform font stuff in stylo was implemented by Manish, and if this is not too stylo-specific, I suspect we may be collecting platform fonts more often than Gecko, which is something we should look into, so looping him in too.

Comment 5

[Jonathan Kew [:jfkthame]]

I think :karlt probably has a better grasp of fontconfig stuff... ni'ing him for any thoughts.

:jseward, can you get more complete stacks (reaching up as far as Gecko code, not just fontconfig internals) for the high-count cases like "3 of 100" and "4 of 100" where attachment 8863744 [details] doesn't show anything beyond FcConfigValues?

Comment 6

[Julian Seward [:jseward]]

Attachment: Some slightly deeper stacks

:jfkthame, is that enough info to be useful?

Comment 7

[Jonathan Kew [:jfkthame]]

They're interesting (it looks like we're creating a lot of nsFontMetrics instances, for example, making me wonder whether we're not caching and sharing them as effectively as we should?), though they don't seem to correspond to either of the examples in your initial log that show a whole series of nested calls to FcConfigValues. I was curious where those come from?

Comment 8

[Karl Tomlinson (:karlt)]

Wikipedia pages use many different languages and so many different fonts will be instantiated, and wikipedia pages have been historically slow on first load.
Fontconfig does perform many short term allocations when processing system config for each font requested.

There are caches intended to provide that requesting the same font again does not repeat this config processing.
I suggest comparing results with a reload of the same page to check that the caches are working.  If that indicates that they are preventing repeat of the work, then there may be little improvement available without changing the interpretation of the system config.

Comment 9

[Naveed Ihsanullah [:naveed]]

Julian can you run the same test on a non-stylo build so we can some sense of how bad the short lived allocation issue is for non-stylo and FF57?

Comment 10

[Julian Seward [:jseward]]

(In reply to Naveed Ihsanullah [:naveed] from comment #9)
> Julian can you run the same test on a non-stylo build so we can some sense
> of how bad the short lived allocation issue is for non-stylo and FF57?

It's not much different, modulo the difficulty of getting repeatable measurements
out of Firefox.  I ran it for 26.2 billion insns and it is allocating at
a rate of 1 byte every 21 insns, compared to 1 every 22 insns for the
Stylo-enabled build.

And the top entries -- as sorted by decreasing total-blocks-allocated --
are still fontconfig stuff.

Comment 11

[Julian Seward [:jseward]]

Attachment: Complete dhat log as relevant to comment 10

Comment 12

[Julian Seward [:jseward]]

(In reply to Julian Seward [:jseward] from comment #11)
> Complete dhat log as relevant to comment 10

Note also entry 6 of 1000, where we allocate 24,241 blocks, hold on
to them for much of the program lifetime, and never read them.  This
is apparently to do with Thai language support.  May well be not our
fault and nothing we can do about it, but nevertheless..

Comment 13

[Jonathan Kew [:jfkthame]]

(In reply to Julian Seward [:jseward] from comment #12)
> (In reply to Julian Seward [:jseward] from comment #11)
> > Complete dhat log as relevant to comment 10
> 
> Note also entry 6 of 1000, where we allocate 24,241 blocks, hold on
> to them for much of the program lifetime, and never read them.  This
> is apparently to do with Thai language support.  May well be not our
> fault and nothing we can do about it, but nevertheless..

That's for Thai line-breaking support (rather than font-related), I believe. I wonder if we can defer loading it until first use? Might be worth filing a separate bug to look into that. It would be helpful to see more of the stack, to identify where in gecko this originates. (I suspect it may be an indirect dependency via other libs, so might turn out to be hard to modify...)

Comment 14

[Daniel Holbert [:dholbert]]

jseward, would you mind retesting to see if this is still an issue?

Comment 15

[Julian Seward [:jseward]]

(In reply to Daniel Holbert [:dholbert] from comment #14)

I tried m-c just now, using njn's majorly rehashed DHAT tool, again
using the Barack Obama wikipedia page as a test case. I no longer
see any obvious badness (short lived allocations) relating to font
handling. So I think you're good.

Comment 16

[Daniel Holbert [:dholbert]]

Thanks for checking!