1978973 - Fenix startup spends 600ms of CPU time in RemoteSettingsClient::get_records, re-compiling JEXL regular expressions for every filtered record

Status: RESOLVED FIXED

(Application Services :: Remote Settings, defect)

Description

[Markus Stange [:mstange]]

This profile shows RemoteSettingsClient::get_records taking up a lot of CPU time during Fenix startup: https://share.firefox.dev/4kWj26X

It appears that JexlFilter::evaluate only spends a tiny percentage (< 1%) of its time actually evaluating, in jexl_eval::Evaluator::eval_ast.
And jexl_parser::Parser::parse spends only 5% of its time in ExpressionParser::parse.
The rest is overhead from repeatedly re-creating regular expressions and freeing their representations.

See https://firefox-source-docs.mozilla.org/performance/profiling_with_simpleperf.html for profiling instructions.

Comment 1

[Markus Stange [:mstange]]

This PR from last year seems very relevant: https://github.com/mozilla/jexl-rs/pull/32

Beth, can you take a look? Is it possible that this code is being exercised more these days? I don't recall seeing this much CPU usage during startup a few months ago.

Comment 2

[Beth Rennie [:beth] (she/her)]

Theoretically we can address this by using an expression cache, so it should be a pretty simple fix. I talked to :emcminn and she is interested in taking this on.

Comment 3

[Beth Rennie [:beth] (she/her)]

I talked with :jrmuizel about this and it sounds like pushing https://github.com/mozilla/jexl-rs/pull/32 or a similar fix would be most of the heavy lifting. That does require an API change, so maybe it would be better to stick the regex into a OnceCell to avoid that. Otherwise, we will likely have to abandon the existing lexer+parser

Comment 4

[Jeff Muizelaar [:jrmuizel]]

It looks like the lexer problem is a known problem lalrpop: https://github.com/lalrpop/lalrpop/issues/1028

I tried out a custom lexer and it increased performance by about 1000x

Comment 5

[Mark Hammond [:markh] [:mhammond]]

Attachment: logcat output

Jeff asked me to log the jexl expression at https://searchfox.org/mozilla-central/source/third_party/rust/remote_settings/src/client.rs#230 - the output after starting Fenix is attached.

Comment 6

[Jeff Muizelaar [:jrmuizel]]

The ~414 expressions is higher than the 175 that you predicted Beth. Do you know why it's higher?

Comment 7

[Markus Stange [:mstange]]

Here's a profile with 700ms of SuggestStore.ingest: https://share.firefox.dev/4lKJ521

Comment 8

[Beth Rennie [:beth] (she/her)]

Attachment: jexl.log

Comment 9

[Beth Rennie [:beth] (she/her)]

:markh got a custom build with some logging. There are indeed three collections involved:

~$ cat jexl.log | cut -d: -f1 | sort | uniq
quicksuggest-amp
quicksuggest-other
search-config-icons

And there are some repeats:

~$ cat jexl.log | sort | uniq | wc -l
     310
~$ cat jexl.log | wc -l
     414

If you look at the attached jexl.log you will see that we process every record in the search-config-icons collections three times. (I wrote a script to double check and verified that to be true.)

Comment 10

[Markus Stange [:mstange]]

This relanded in bug 1984561.

Comment 11

[Markus Stange [:mstange]]

The profiles show that this is indeed fixed. Thank you Jeff for for rewriting the jexl tokenizer in https://github.com/mozilla/jexl-rs/pull/35 and thank you Beth for shepherding the fix into the tree!

Profiles:
Before: https://share.firefox.dev/4g0fkIv (591 samples in filter_records)
After: https://share.firefox.dev/3VmhCrR (17 samples in filter_records, 35x faster)

Comment 12

[Markus Stange [:mstange]]

This change also improved various startup performance numbers, not just CPU time:

• 8.6% faster on cold_main_first_frame.mean
• 10.6% faster on cold_view_nav_start.mean
• 4.12 % faster on newssite-applink-startup