Skip to content

Move app start trace build logic into a non-main thread. #3008

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.

Sign up for GitHub

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 4 commits into from
Sep 30, 2021
Merged

Move app start trace build logic into a non-main thread. #3008

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
656574e
Move app start trace build logic into a non-main thread.
jeremyjiang-dev Sep 28, 2021
d3167a5
Fix style
jeremyjiang-dev Sep 28, 2021
cbe7176
Incorporate comments
jeremyjiang-dev Sep 29, 2021
5aefc34
Incorporate comments
jeremyjiang-dev Sep 30, 2021
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
133 changes: 84 additions & 49 deletions firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@
import com.google.android.gms.common.util.VisibleForTesting;
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;
Expand All @@ -35,6 +36,9 @@
import java.lang.ref.WeakReference;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;

/**
Expand All @@ -55,7 +59,39 @@ public class AppStartTrace implements ActivityLifecycleCallbacks {

private static final long MAX_LATENCY_BEFORE_UI_INIT = TimeUnit.MINUTES.toMicros(1);

// Core pool size 0 allows threads to shut down if they're idle
private static final int CORE_POOL_SIZE = 0;
private static final int MAX_POOL_SIZE = 1; // Only need single thread

private static volatile AppStartTrace instance;
private static ExecutorService executorService;

private boolean isRegisteredForLifecycleCallbacks = false;
private final TransportManager transportManager;
private final Clock clock;
private Context appContext;
/**
* The first time onCreate() of any activity is called, the activity is saved as launchActivity.
*/
private WeakReference<Activity> launchActivity;
/**
* The first time onResume() of any activity is called, the activity is saved as appStartActivity
*/
private WeakReference<Activity> appStartActivity;

/**
* If the time difference between app starts and creation of any Activity is larger than
* MAX_LATENCY_BEFORE_UI_INIT, set mTooLateToInitUI to true and we don't send AppStart Trace.
*/
private boolean isTooLateToInitUI = false;

private Timer appStartTime = null;
private Timer onCreateTime = null;
private Timer onStartTime = null;
private Timer onResumeTime = null;

private PerfSession startSession;
private boolean isStartedFromBackground = false;

/**
* Called from onCreate() method of an activity by instrumented byte code.
Expand Down Expand Up @@ -94,41 +130,29 @@ static AppStartTrace getInstance(TransportManager transportManager, Clock clock)
if (instance == null) {
synchronized (AppStartTrace.class) {
if (instance == null) {
instance = new AppStartTrace(transportManager, clock);
instance =
new AppStartTrace(
transportManager,
clock,
new ThreadPoolExecutor(
CORE_POOL_SIZE,
MAX_POOL_SIZE,
/* keepAliveTime= */ MAX_LATENCY_BEFORE_UI_INIT + 10,
TimeUnit.SECONDS,
new LinkedBlockingQueue<>(1)));
}
}
}
return instance;
}

private boolean isRegisteredForLifecycleCallbacks = false;
private final TransportManager transportManager;
private final Clock clock;
private Context appContext;
/**
* The first time onCreate() of any activity is called, the activity is saved as launchActivity.
*/
private WeakReference<Activity> launchActivity;
/**
* The first time onResume() of any activity is called, the activity is saved as appStartActivity
*/
private WeakReference<Activity> appStartActivity;

/**
* If the time difference between app starts and creation of any Activity is larger than
* MAX_LATENCY_BEFORE_UI_INIT, set mTooLateToInitUI to true and we don't send AppStart Trace.
*/
private boolean isTooLateToInitUI = false;

private Timer onCreateTime = null;
private Timer onStartTime = null;
private Timer onResumeTime = null;

private boolean isStartedFromBackground = false;

AppStartTrace(@NonNull TransportManager transportManager, @NonNull Clock clock) {
AppStartTrace(
@NonNull TransportManager transportManager,
@NonNull Clock clock,
@NonNull ExecutorService executorService) {
this.transportManager = transportManager;
this.clock = clock;
this.executorService = executorService;
}

/** Called from FirebasePerfProvider to register this callback. */
Expand Down Expand Up @@ -191,51 +215,57 @@ public synchronized void onActivityResumed(Activity activity) {
appStartActivity = new WeakReference<Activity>(activity);

onResumeTime = clock.getTime();
final Timer startTime = FirebasePerfProvider.getAppStartTime();
this.appStartTime = FirebasePerfProvider.getAppStartTime();
this.startSession = SessionManager.getInstance().perfSession();
AndroidLogger.getInstance()
.debug(
"onResume(): "
+ activity.getClass().getName()
+ ": "
+ startTime.getDurationMicros(onResumeTime)
+ this.appStartTime.getDurationMicros(onResumeTime)
+ " microseconds");

// Log the app start trace in a non-main thread.
executorService.execute(this::logAppStartTrace);

if (isRegisteredForLifecycleCallbacks) {
// After AppStart trace is logged, we can unregister this callback.
unregisterActivityLifecycleCallbacks();
Copy link
Contributor

Choose a reason for hiding this comment

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

Just out of curiousity - Can this happen on non-main thread? Just thinking if we can delay this for later on a non-main thread.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

We cannot. If we delay this, it is possible that the app enters onActivityResumed multiple times before the executor executes so that we might log the startup time multiple times.

}
}

private void logAppStartTrace() {
TraceMetric.Builder metric =
TraceMetric.newBuilder()
.setName(Constants.TraceNames.APP_START_TRACE_NAME.toString())
.setClientStartTimeUs(startTime.getMicros())
.setDurationUs(startTime.getDurationMicros(onResumeTime));
.setClientStartTimeUs(getappStartTime().getMicros())
.setDurationUs(getappStartTime().getDurationMicros(onResumeTime));
List<TraceMetric> subtraces = new ArrayList<>(/* initialCapacity= */ 3);

TraceMetric.Builder temp =
TraceMetric.Builder traceMetricBuilder =
TraceMetric.newBuilder()
.setName(Constants.TraceNames.ON_CREATE_TRACE_NAME.toString())
.setClientStartTimeUs(startTime.getMicros())
.setDurationUs(startTime.getDurationMicros(onCreateTime));
subtraces.add(temp.build());
.setClientStartTimeUs(getappStartTime().getMicros())
.setDurationUs(getappStartTime().getDurationMicros(onCreateTime));
subtraces.add(traceMetricBuilder.build());

temp = TraceMetric.newBuilder();
temp.setName(Constants.TraceNames.ON_START_TRACE_NAME.toString())
traceMetricBuilder = TraceMetric.newBuilder();
traceMetricBuilder
.setName(Constants.TraceNames.ON_START_TRACE_NAME.toString())
.setClientStartTimeUs(onCreateTime.getMicros())
.setDurationUs(onCreateTime.getDurationMicros(onStartTime));
subtraces.add(temp.build());
subtraces.add(traceMetricBuilder.build());

temp = TraceMetric.newBuilder();
temp.setName(Constants.TraceNames.ON_RESUME_TRACE_NAME.toString())
traceMetricBuilder = TraceMetric.newBuilder();
traceMetricBuilder
.setName(Constants.TraceNames.ON_RESUME_TRACE_NAME.toString())
.setClientStartTimeUs(onStartTime.getMicros())
.setDurationUs(onStartTime.getDurationMicros(onResumeTime));
subtraces.add(temp.build());
subtraces.add(traceMetricBuilder.build());

metric
.addAllSubtraces(subtraces)
.addPerfSessions(SessionManager.getInstance().perfSession().build());
metric.addAllSubtraces(subtraces).addPerfSessions(this.startSession.build());

transportManager.log(metric.build(), ApplicationProcessState.FOREGROUND_BACKGROUND);

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

@Override
Expand Down Expand Up @@ -285,6 +315,11 @@ Activity getAppStartActivity() {
return appStartActivity.get();
}

@VisibleForTesting
Timer getappStartTime() {
return appStartTime;
}

@VisibleForTesting
Timer getOnCreateTime() {
return onCreateTime;
Expand Down
19 changes: 15 additions & 4 deletions firebase-perf/src/test/java/com/google/firebase/perf/metrics/AppStartTraceTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,7 @@
import com.google.firebase.perf.util.Timer;
import com.google.firebase.perf.v1.ApplicationProcessState;
import com.google.firebase.perf.v1.TraceMetric;
import com.google.testing.timing.FakeScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import org.junit.Assert;
import org.junit.Before;
Expand Down Expand Up @@ -87,15 +88,18 @@ public Timer answer(InvocationOnMock invocationOnMock) throws Throwable {
/** Test activity sequentially goes through onCreate()->onStart()->onResume() state change. */
@Test
public void testLaunchActivity() {
AppStartTrace trace = new AppStartTrace(transportManager, clock);
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
// first activity goes through onCreate()->onStart()->onResume() state change.
currentTime = 1;
trace.onActivityCreated(activity1, bundle);
currentTime = 2;
trace.onActivityStarted(activity1);
currentTime = 3;
trace.onActivityResumed(activity1);
fakeExecutorService.runAll();
verifyFinalState(activity1, trace, 1, 2, 3);

// same activity goes through onCreate()->onStart()->onResume() state change again.
// should have no effect on AppStartTrace.
currentTime = 4;
Expand All @@ -104,6 +108,7 @@ public void testLaunchActivity() {
trace.onActivityStarted(activity1);
currentTime = 6;
trace.onActivityResumed(activity1);
fakeExecutorService.runAll();
verifyFinalState(activity1, trace, 1, 2, 3);

// a different activity goes through onCreate()->onStart()->onResume() state change.
Expand All @@ -114,6 +119,7 @@ public void testLaunchActivity() {
trace.onActivityStarted(activity2);
currentTime = 9;
trace.onActivityResumed(activity2);
fakeExecutorService.runAll();
verifyFinalState(activity1, trace, 1, 2, 3);
}

Expand Down Expand Up @@ -158,7 +164,8 @@ private void verifyFinalState(
*/
@Test
public void testInterleavedActivity() {
AppStartTrace trace = new AppStartTrace(transportManager, clock);
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
// first activity onCreate()
currentTime = 1;
trace.onActivityCreated(activity1, bundle);
Expand All @@ -178,19 +185,22 @@ public void testInterleavedActivity() {
trace.onActivityResumed(activity2);
Assert.assertEquals(activity1, trace.getLaunchActivity());
Assert.assertEquals(activity2, trace.getAppStartActivity());
fakeExecutorService.runAll();
verifyFinalState(activity2, trace, 1, 3, 4);

// first activity continues.
currentTime = 5;
trace.onActivityStarted(activity1);
currentTime = 6;
trace.onActivityResumed(activity1);
fakeExecutorService.runAll();
verifyFinalState(activity2, trace, 1, 3, 4);
}

@Test
public void testDelayedAppStart() {
AppStartTrace trace = new AppStartTrace(transportManager, clock);
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
// Delays activity creation after 1 minute from app start time.
currentTime = appStartTime + TimeUnit.MINUTES.toMicros(1) + 1;
trace.onActivityCreated(activity1, bundle);
Expand All @@ -210,7 +220,8 @@ public void testDelayedAppStart() {

@Test
public void testStartFromBackground() {
AppStartTrace trace = new AppStartTrace(transportManager, clock);
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
trace.setIsStartFromBackground();
trace.onActivityCreated(activity1, bundle);
Assert.assertNull(trace.getOnCreateTime());
Expand Down