Skip to content

[Fireperf][AASA] send _experiment_app_start_ttid trace, controlled by RC flag #4114

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 9 commits into from
Sep 28, 2022
Merged
Show file tree
Hide file tree
Changes from 7 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions firebase-perf/dev-app/src/main/AndroidManifest.xml
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,9 @@
<meta-data
android:name="fragment_sampling_percentage"
android:value="100.0" />
<meta-data
android:name="experiment_app_start_ttid"
android:value="true" />

<receiver
android:name=".FirebasePerfTestReceiver"
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@
import com.google.firebase.perf.BuildConfig;
import com.google.firebase.perf.config.ConfigurationConstants.CollectionDeactivated;
import com.google.firebase.perf.config.ConfigurationConstants.CollectionEnabled;
import com.google.firebase.perf.config.ConfigurationConstants.ExperimentTTID;
import com.google.firebase.perf.config.ConfigurationConstants.FragmentSamplingRate;
import com.google.firebase.perf.config.ConfigurationConstants.LogSourceName;
import com.google.firebase.perf.config.ConfigurationConstants.NetworkEventCountBackground;
Expand Down Expand Up @@ -767,6 +768,32 @@ public float getFragmentSamplingRate() {
return config.getDefault();
}

/** Returns if _experiment_app_start_ttid should be captured. */
public boolean getIsExperimentTTIDEnabled() {
// Order of precedence is:
// 1. If the value exists in Android Manifest, return this value.
// 2. Cannot read value from RC because it's not initalized yet
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What does this precedence mean?

Copy link
Contributor Author

@leotianlizhan leotianlizhan Sep 27, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a comment in the same style as other flags if you look into the same file. Other flags has the order laid out like this, I just changed the 2nd step to "Cannot read from RC".

EDIT: after some thoughts, I added the RC check back. It doesn't hurt if RC is available, and doesn't hurt if RC isn't initialized because it would skip this step anyway.

// 3. If the value exists in device cache, return this value.
// 4. Otherwise, return default value.
ExperimentTTID config = ExperimentTTID.getInstance();

// 1. Reads value in Android Manifest (it is set by developers during build time).
Optional<Boolean> metadataValue = getMetadataBoolean(config);
if (metadataValue.isAvailable()) {
return metadataValue.get();
}

// 2. Cannot read value from RC because it's not initialized yet.
// 3. Reads value from cache layer.
Optional<Boolean> deviceCacheValue = getDeviceCacheBoolean(config);
if (deviceCacheValue.isAvailable()) {
return deviceCacheValue.get();
}

// 4. Returns default value if there is no valid value from above approaches.
return config.getDefault();
}

// endregion

// Helper functions for interaction with Metadata layer.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -661,4 +661,39 @@ protected String getMetadataFlag() {
return "fragment_sampling_percentage";
}
}

protected static final class ExperimentTTID extends ConfigurationFlag<Boolean> {
private static ExperimentTTID instance;

private ExperimentTTID() {
super();
}

protected static synchronized ExperimentTTID getInstance() {
if (instance == null) {
instance = new ExperimentTTID();
}
return instance;
}

@Override
protected Boolean getDefault() {
return false;
}

@Override
protected String getRemoteConfigFlag() {
return "fpr_experiment_app_start_ttid";
}

@Override
protected String getDeviceCacheFlag() {
return "com.google.firebase.perf.ExperimentTTID";
}

@Override
protected String getMetadataFlag() {
return "experiment_app_start_ttid";
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,8 @@

package com.google.firebase.perf.config;

import static com.google.firebase.perf.config.ConfigurationConstants.ExperimentTTID;

import android.content.Context;
import android.content.pm.PackageInfo;
import android.content.pm.PackageManager.NameNotFoundException;
Expand Down Expand Up @@ -53,6 +55,7 @@ public class RemoteConfigManager {
private static final long MIN_APP_START_CONFIG_FETCH_DELAY_MS = 5000;
private static final int RANDOM_APP_START_CONFIG_FETCH_DELAY_MS = 25000;

private final DeviceCacheManager cache;
private final ConcurrentHashMap<String, FirebaseRemoteConfigValue> allRcConfigMap;
private final Executor executor;
private final long appStartTimeInMs;
Expand All @@ -65,29 +68,25 @@ public class RemoteConfigManager {

private RemoteConfigManager() {
this(
DeviceCacheManager.getInstance(),
new ThreadPoolExecutor(
/* corePoolSize= */ 0,
/* maximumPoolSize= */ 1,
/* keepAliveTime= */ 0L,
TimeUnit.SECONDS,
new LinkedBlockingQueue<Runnable>()),
/* firebaseRemoteConfig= */ null // set once FirebaseRemoteConfig is initialized
);
}

RemoteConfigManager(Executor executor, FirebaseRemoteConfig firebaseRemoteConfig) {
this(
executor,
firebaseRemoteConfig,
/* firebaseRemoteConfig= */ null, // set once FirebaseRemoteConfig is initialized
MIN_APP_START_CONFIG_FETCH_DELAY_MS
+ new Random().nextInt(RANDOM_APP_START_CONFIG_FETCH_DELAY_MS));
}

@VisibleForTesting
RemoteConfigManager(
DeviceCacheManager cache,
Executor executor,
FirebaseRemoteConfig firebaseRemoteConfig,
long appStartConfigFetchDelayInMs) {
this.cache = cache;
this.executor = executor;
this.firebaseRemoteConfig = firebaseRemoteConfig;
this.allRcConfigMap =
Expand Down Expand Up @@ -315,7 +314,7 @@ private void triggerRemoteConfigFetchIfNecessary() {
return;
}
if (allRcConfigMap.isEmpty()) { // Initial fetch.
syncConfigValues(firebaseRemoteConfig.getAll());
allRcConfigMap.putAll(firebaseRemoteConfig.getAll());
}
if (shouldFetchAndActivateRemoteConfigValues()) {
triggerFirebaseRemoteConfigFetchAndActivateOnSuccessfulFetch();
Expand All @@ -342,6 +341,19 @@ protected void syncConfigValues(Map<String, FirebaseRemoteConfigValue> newlyFetc
allRcConfigMap.remove(existingKey);
}
}

// Save to device cache upon successful RC fetchAndActivate
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we detail more comments here since we are syncing a special config here in RC? Needs explanations for future references.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

ExperimentTTID flag = ExperimentTTID.getInstance();
FirebaseRemoteConfigValue rcValue = allRcConfigMap.get(flag.getRemoteConfigFlag());
if (rcValue != null) {
try {
cache.setValue(flag.getDeviceCacheFlag(), rcValue.asBoolean());
} catch (Exception exception) {
logger.debug("ExperimentTTID remote config flag has invalid value, expected boolean.");
}
} else {
logger.debug("ExperimentTTID remote config flag does not exist.");
}
}

@VisibleForTesting
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -18,18 +18,23 @@
import android.app.Application;
import android.app.Application.ActivityLifecycleCallbacks;
import android.content.Context;
import android.os.Build;
import android.os.Bundle;
import android.os.Process;
import android.view.View;
import androidx.annotation.Keep;
import androidx.annotation.NonNull;
import androidx.annotation.Nullable;
import com.google.android.gms.common.util.VisibleForTesting;
import com.google.firebase.perf.config.ConfigResolver;
import com.google.firebase.perf.logging.AndroidLogger;
import com.google.firebase.perf.provider.FirebasePerfProvider;
import com.google.firebase.perf.session.PerfSession;
import com.google.firebase.perf.session.SessionManager;
import com.google.firebase.perf.transport.TransportManager;
import com.google.firebase.perf.util.Clock;
import com.google.firebase.perf.util.Constants;
import com.google.firebase.perf.util.FirstDrawDoneListener;
import com.google.firebase.perf.util.Timer;
import com.google.firebase.perf.v1.ApplicationProcessState;
import com.google.firebase.perf.v1.TraceMetric;
Expand Down Expand Up @@ -69,6 +74,7 @@ public class AppStartTrace implements ActivityLifecycleCallbacks {
private boolean isRegisteredForLifecycleCallbacks = false;
private final TransportManager transportManager;
private final Clock clock;
private final ConfigResolver configResolver;
private Context appContext;
/**
* The first time onCreate() of any activity is called, the activity is saved as launchActivity.
Expand All @@ -89,6 +95,7 @@ public class AppStartTrace implements ActivityLifecycleCallbacks {
private Timer onCreateTime = null;
private Timer onStartTime = null;
private Timer onResumeTime = null;
private Timer firstDrawDone = null;

private PerfSession startSession;
private boolean isStartedFromBackground = false;
Expand Down Expand Up @@ -134,12 +141,13 @@ static AppStartTrace getInstance(TransportManager transportManager, Clock clock)
new AppStartTrace(
transportManager,
clock,
ConfigResolver.getInstance(),
new ThreadPoolExecutor(
CORE_POOL_SIZE,
MAX_POOL_SIZE,
/* keepAliveTime= */ MAX_LATENCY_BEFORE_UI_INIT + 10,
TimeUnit.SECONDS,
new LinkedBlockingQueue<>(1)));
new LinkedBlockingQueue<>()));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we know why they had a max count of 1 item in the queue earlier?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There was only 1 call to executorService.execute() before because we only had 1 app start trace.

}
}
}
Expand All @@ -149,9 +157,11 @@ static AppStartTrace getInstance(TransportManager transportManager, Clock clock)
AppStartTrace(
@NonNull TransportManager transportManager,
@NonNull Clock clock,
@NonNull ConfigResolver configResolver,
@NonNull ExecutorService executorService) {
this.transportManager = transportManager;
this.clock = clock;
this.configResolver = configResolver;
this.executorService = executorService;
}

Expand All @@ -178,6 +188,33 @@ public synchronized void unregisterActivityLifecycleCallbacks() {
isRegisteredForLifecycleCallbacks = false;
}

/**
* Gets the timetamp that marks the beginning of app start, currently defined as the beginning of
* BIND_APPLICATION. Fallback to class-load time of {@link FirebasePerfProvider} when API < 24.
*
* @return {@link Timer} at the beginning of app start by Fireperf definition.
*/
private static Timer getStartTimer() {
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) {
return Timer.ofElapsedRealtime(Process.getStartElapsedRealtime());
}
return FirebasePerfProvider.getAppStartTime();
}

private void recordFirstDrawDone() {
if (firstDrawDone != null) {
return;
}
this.firstDrawDone = clock.getTime();
executorService.execute(
() -> this.logColdStart(getStartTimer(), this.firstDrawDone, this.startSession));

if (isRegisteredForLifecycleCallbacks) {
// After AppStart trace is queued to be logged, we can unregister this callback.
unregisterActivityLifecycleCallbacks();
}
}

@Override
public synchronized void onActivityCreated(Activity activity, Bundle savedInstanceState) {
if (isStartedFromBackground || onCreateTime != null // An activity already called onCreate()
Expand Down Expand Up @@ -206,9 +243,18 @@ public synchronized void onActivityStarted(Activity activity) {

@Override
public synchronized void onActivityResumed(Activity activity) {
if (isStartedFromBackground
|| onResumeTime != null // An activity already called onResume()
|| isTooLateToInitUI) {
if (isStartedFromBackground || isTooLateToInitUI) {
return;
}

// Shadow-launch experiment of new app start time
final boolean isExperimentTTIDEnabled = configResolver.getIsExperimentTTIDEnabled();
if (isExperimentTTIDEnabled) {
View rootView = activity.findViewById(android.R.id.content);
FirstDrawDoneListener.registerForNextDraw(rootView, this::recordFirstDrawDone);
}

if (onResumeTime != null) { // An activity already called onResume()
return;
}

Expand All @@ -228,12 +274,30 @@ public synchronized void onActivityResumed(Activity activity) {
// Log the app start trace in a non-main thread.
executorService.execute(this::logAppStartTrace);

if (isRegisteredForLifecycleCallbacks) {
if (!isExperimentTTIDEnabled && isRegisteredForLifecycleCallbacks) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What happens if the flag dynamically changes from No to YES (or) vice versa? Would that cause a situation where we try to unregister for callbacks when we have not registered or the other way about?

Copy link
Contributor Author

@leotianlizhan leotianlizhan Sep 27, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good question! Since this flag is only read once in the beginning of AppStartTrace#onActivityResumed, it's not a problem.

Scenario 1: experiment disabled, an activity resumed, experiment enabled, another activity resumed.

After the first resume, the unregistering would be called, so the 2nd activity resume would not do anything. TTID isn't recorded for this app start, it will only start working next app start.

Scenario 2: experiment enabled, an activity resumed, experiment disabled, another activity resumed.

After the first resume, the AppStartTrace.onResume variable would be set, so even if the 2nd activity resume triggers, nothing happens because this method will return immediately without sending anything else.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good.

For the first scenario - I assume that experiment is disabled?

In the second scenario - I assume that would mean experiment is enabled?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, these scenarios show what happens if the app starts with 1 state, then changes after app start.

// After AppStart trace is logged, we can unregister this callback.
unregisterActivityLifecycleCallbacks();
}
}

private void logColdStart(Timer start, Timer end, PerfSession session) {
TraceMetric.Builder metric =
TraceMetric.newBuilder()
.setName("_experiment_app_start_ttid")
.setClientStartTimeUs(start.getMicros())
.setDurationUs(start.getDurationMicros(end));

TraceMetric.Builder subtrace =
TraceMetric.newBuilder()
.setName("_experiment_classLoadTime")
.setClientStartTimeUs(FirebasePerfProvider.getAppStartTime().getMicros())
.setDurationUs(FirebasePerfProvider.getAppStartTime().getDurationMicros(end));

metric.addSubtraces(subtrace).addPerfSessions(this.startSession.build());

transportManager.log(metric.build(), ApplicationProcessState.FOREGROUND_BACKGROUND);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why FOREGROUND_BACKGROUND?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

_app_start is FOREGROUND_BACKGROUND so I am just following the same behavior.

}

private void logAppStartTrace() {
TraceMetric.Builder metric =
TraceMetric.newBuilder()
Expand Down
Loading