Skip to content
This repository has been archived by the owner on Feb 20, 2023. It is now read-only.

Investigate allocations in Fact.toEvent: allocates a Pair for each comparison #21171

Closed
mcomella opened this issue Sep 7, 2021 · 5 comments
Closed
Assignees
Labels
needs:triage Issue needs triage performance Possible performance wins

Comments

@mcomella
Copy link
Contributor

mcomella commented Sep 7, 2021

Fact.toEvent uses a when statement with 36 items to compare its value. For each value, it's comparing to a Pair:

    private fun Fact.toEvent(): Event? = when (Pair(component, item)) {
        Component.FEATURE_PROMPTS to LoginDialogFacts.Items.DISPLAY -> Event.LoginDialogPromptDisplayed
        Component.FEATURE_PROMPTS to LoginDialogFacts.Items.CANCEL -> Event.LoginDialogPromptCancelled
        ...

The to function is actually allocating a Pair for each item, each time this is called (i.e. we may allocate 35 times in the current code). It doesn't get optimized out: here's the bytecode for the first comparison:

   L4
    LINENUMBER 161 L4
    ALOAD 2
    GETSTATIC mozilla/components/support/base/Component.FEATURE_PROMPTS : Lmozilla/components/support/base/Component;
    LDC "display"
    INVOKESTATIC kotlin/TuplesKt.to (Ljava/lang/Object;Ljava/lang/Object;)Lkotlin/Pair;
    INVOKESTATIC kotlin/jvm/internal/Intrinsics.areEqual (Ljava/lang/Object;Ljava/lang/Object;)Z
    IFEQ L5
   L6
    GETSTATIC org/mozilla/fenix/components/metrics/Event$LoginDialogPromptDisplayed.INSTANCE : Lorg/mozilla/fenix/components/metrics/Event$LoginDialogPromptDisplayed;
    CHECKCAST org/mozilla/fenix/components/metrics/Event
    GOTO L7

It's unclear how bad this is in practice: e.g. what the duration is for being called once, how many times it may be called in a row, if it's blocking the main thread, and if 35 Pairs (4.4 KiB?) will create a lot of churn in the GC.

┆Issue is synchronized with this Jira Task

@mcomella mcomella added the performance Possible performance wins label Sep 7, 2021
@github-actions github-actions bot added the needs:triage Issue needs triage label Sep 7, 2021
@mcomella
Copy link
Contributor Author

mcomella commented Sep 7, 2021

This code is wrapped by the MetricController.track function and will eventually go through the even larger switch statement:

This might be a good opportunity to measure that too as this will also execute synchronously and could block the following code.

Question: is taking a profile good enough to understand this code or should we benchmark?

@mcomella
Copy link
Contributor Author

mcomella commented Sep 8, 2021

In browsing around the app, I subjectively noticed that Fact.toEvent returns null in most cases so we're hitting the worst case in most cases. It's unclear what the granularity of the clock is but once the code is jitted, it's anywhere from 0.21ms (it might be lower because it might be hitting clock granularity) to 1.14ms per Fact.toEvent call.

In the case of the awesomebar providers, each keystroke triggers 7 facts, which is 1.75ms summed in the best case (caveat: clock granularity) and 2.64ms in one case where I measured each call individually (caveat still applies). This isn't a user perceptible delay so I'm more concerned about this from a battery and memory perspective.

This code is wrapped by the MetricController.track function and will eventually go through the even larger switch statement:

In 13 iterations of the track block, a median run through it is 0.66ms with the max as 1.09ms and min as 0.36ms (i.e. this doesn't seem to hit clock granularity). This seems to get called roughly as often as Fact.toEvent so I'm also concerned about this from a battery perspective but not duration.

Then again we have no idea how much battery these use beyond "less work is better for battery" so it's difficult to measure the power use impact. However, they seem like relatively straight forward fixes so it might be worth it for a blind fix.

@mcomella
Copy link
Contributor Author

mcomella commented Sep 8, 2021

wrt allocations, typing in the awesomebar produces a sin wave pattern:
image

image

In the first screenshot, I typed "no no im figuring it out" and the memory went from ~144.3 MB to 167.6 MB and back down to 144.4 MB, and it continues to climb afterwards. This may not be directly related to the Fact.toEvent calls. In general, memory usage appears to increase the longer the awesome screen is open with a GC maybe every 20s, even if I'm not typing anything:
image

Summary

There are three issues in this bug:

I'm guessing we should file these separately? They seem like they could be good help wanted tickets. I'll wait for triage to decide.

@mcomella
Copy link
Contributor Author

and it continues to climb afterwards. This may not be directly related to the Fact.toEvent calls. In general, memory usage appears to increase the longer the awesome screen is open with a GC maybe every 20s, even if I'm not typing anything:

I discovered the gradual increase was because the Gecko profiler was sampling because I accidentally left the profiler file in.

However, without the gradual allocations, I was able to determine each keystroke allocates 0.2-0.3 MB of memory.

@mcomella mcomella changed the title Fact.toEvent allocates a Pair for each comparison Investigate allocations in Fact.toEvent: allocates a Pair for each comparison Sep 14, 2021
@mcomella mcomella self-assigned this Sep 14, 2021
@mcomella
Copy link
Contributor Author

To make the issues easier to understand, I changed this issue to an investigation issue and filed 3 follow-ups linked from #21171 (comment)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
needs:triage Issue needs triage performance Possible performance wins
Projects
None yet
Development

No branches or pull requests

1 participant