Skip to content

Commit cc7192c

Browse files
krystofwoldrichkrystofwoldrich
authored
Merge ced557f into 93a76ca 
2 parents 93a76ca + ced557f commit cc7192c

2 files changed

Lines changed: 369 additions & 265 deletions

File tree

‎sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java‎

Lines changed: 330 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,330 @@
1+
package io.sentry.android.core;
2+
3+
import android.annotation.SuppressLint;
4+
import android.os.Build;
5+
import android.os.Debug;
6+
import android.os.Process;
7+
import android.os.SystemClock;
8+
import io.sentry.CpuCollectionData;
9+
import io.sentry.MemoryCollectionData;
10+
import io.sentry.PerformanceCollectionData;
11+
import io.sentry.SentryLevel;
12+
import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
13+
import io.sentry.profilemeasurements.ProfileMeasurement;
14+
import io.sentry.profilemeasurements.ProfileMeasurementValue;
15+
import java.io.File;
16+
import java.util.ArrayDeque;
17+
import java.util.HashMap;
18+
import java.util.List;
19+
import java.util.Map;
20+
import java.util.UUID;
21+
import java.util.concurrent.Future;
22+
import java.util.concurrent.RejectedExecutionException;
23+
import java.util.concurrent.TimeUnit;
24+
import org.jetbrains.annotations.ApiStatus;
25+
import org.jetbrains.annotations.NotNull;
26+
import org.jetbrains.annotations.Nullable;
27+
28+
@ApiStatus.Internal
29+
public class AndroidProfiler {
30+
public static class ProfileStartData {
31+
public final long startNanos;
32+
public final long startCpuMillis;
33+
34+
public ProfileStartData(final long startNanos, final long startCpuMillis) {
35+
this.startNanos = startNanos;
36+
this.startCpuMillis = startCpuMillis;
37+
}
38+
}
39+
40+
public static class ProfileEndData {
41+
public final long endNanos;
42+
public final long endCpuMillis;
43+
public final @NotNull File traceFile;
44+
public final @NotNull Map<String, ProfileMeasurement> measurementsMap;
45+
public final boolean didTimeout;
46+
47+
public ProfileEndData(
48+
final long endNanos,
49+
final long endCpuMillis,
50+
final boolean didTimeout,
51+
final @NotNull File traceFile,
52+
final @NotNull Map<String, ProfileMeasurement> measurementsMap) {
53+
this.endNanos = endNanos;
54+
this.traceFile = traceFile;
55+
this.endCpuMillis = endCpuMillis;
56+
this.measurementsMap = measurementsMap;
57+
this.didTimeout = didTimeout;
58+
}
59+
}
60+
61+
/**
62+
* This appears to correspond to the buffer size of the data part of the file, excluding the key
63+
* part. Once the buffer is full, new records are ignored, but the resulting trace file will be
64+
* valid.
65+
*
66+
* <p>30 second traces can require a buffer of a few MB. 8MB is the default buffer size for
67+
* [Debug.startMethodTracingSampling], but 3 should be enough for most cases. We can adjust this
68+
* in the future if we notice that traces are being truncated in some applications.
69+
*/
70+
private static final int BUFFER_SIZE_BYTES = 3_000_000;
71+
72+
private static final int PROFILING_TIMEOUT_MILLIS = 30_000;
73+
private long transactionStartNanos = 0;
74+
private long profileStartCpuMillis = 0;
75+
private @NotNull File traceFilesDir;
76+
private int intervalUs;
77+
private @Nullable Future<?> scheduledFinish = null;
78+
private @Nullable File traceFile = null;
79+
private @Nullable String frameMetricsCollectorId;
80+
private volatile @Nullable ProfileEndData timedOutProfilingData = null;
81+
private final @NotNull SentryFrameMetricsCollector frameMetricsCollector;
82+
private final @NotNull ArrayDeque<ProfileMeasurementValue> screenFrameRateMeasurements =
83+
new ArrayDeque<>();
84+
private final @NotNull ArrayDeque<ProfileMeasurementValue> slowFrameRenderMeasurements =
85+
new ArrayDeque<>();
86+
private final @NotNull ArrayDeque<ProfileMeasurementValue> frozenFrameRenderMeasurements =
87+
new ArrayDeque<>();
88+
private final @NotNull Map<String, ProfileMeasurement> measurementsMap = new HashMap<>();
89+
private final @NotNull SentryAndroidOptions options;
90+
private final @NotNull BuildInfoProvider buildInfoProvider;
91+
92+
public AndroidProfiler(
93+
final @NotNull String tracesFilesDirPath,
94+
final int intervalUs,
95+
final @NotNull SentryFrameMetricsCollector frameMetricsCollector,
96+
final @NotNull SentryAndroidOptions sentryAndroidOptions,
97+
final @NotNull BuildInfoProvider buildInfoProvider) {
98+
this.traceFilesDir = new File(tracesFilesDirPath);
99+
this.intervalUs = intervalUs;
100+
this.frameMetricsCollector = frameMetricsCollector;
101+
this.options = sentryAndroidOptions;
102+
this.buildInfoProvider = buildInfoProvider;
103+
}
104+
105+
@SuppressLint("NewApi")
106+
public @Nullable ProfileStartData start() {
107+
// intervalUs is 0 only if there was a problem in the init, but
108+
// we already logged that
109+
if (intervalUs == 0) {
110+
return null;
111+
}
112+
113+
// We create a file with a uuid name, so no need to check if it already exists
114+
traceFile = new File(traceFilesDir, UUID.randomUUID() + ".trace");
115+
116+
measurementsMap.clear();
117+
screenFrameRateMeasurements.clear();
118+
slowFrameRenderMeasurements.clear();
119+
frozenFrameRenderMeasurements.clear();
120+
121+
frameMetricsCollectorId =
122+
frameMetricsCollector.startCollection(
123+
new SentryFrameMetricsCollector.FrameMetricsCollectorListener() {
124+
final long nanosInSecond = TimeUnit.SECONDS.toNanos(1);
125+
final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700);
126+
float lastRefreshRate = 0;
127+
128+
@Override
129+
public void onFrameMetricCollected(
130+
final long frameEndNanos, final long durationNanos, float refreshRate) {
131+
// transactionStartNanos is calculated through SystemClock.elapsedRealtimeNanos(),
132+
// but frameEndNanos uses System.nanotime(), so we convert it to get the timestamp
133+
// relative to transactionStartNanos
134+
final long frameTimestampRelativeNanos =
135+
frameEndNanos
136+
- System.nanoTime()
137+
+ SystemClock.elapsedRealtimeNanos()
138+
- transactionStartNanos;
139+
140+
// We don't allow negative relative timestamps.
141+
// So we add a check, even if this should never happen.
142+
if (frameTimestampRelativeNanos < 0) {
143+
return;
144+
}
145+
// Most frames take just a few nanoseconds longer than the optimal calculated
146+
// duration.
147+
// Therefore we subtract one, because otherwise almost all frames would be slow.
148+
boolean isSlow = durationNanos > nanosInSecond / (refreshRate - 1);
149+
float newRefreshRate = (int) (refreshRate * 100) / 100F;
150+
if (durationNanos > frozenFrameThresholdNanos) {
151+
frozenFrameRenderMeasurements.addLast(
152+
new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos));
153+
} else if (isSlow) {
154+
slowFrameRenderMeasurements.addLast(
155+
new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos));
156+
}
157+
if (newRefreshRate != lastRefreshRate) {
158+
lastRefreshRate = newRefreshRate;
159+
screenFrameRateMeasurements.addLast(
160+
new ProfileMeasurementValue(frameTimestampRelativeNanos, newRefreshRate));
161+
}
162+
}
163+
});
164+
165+
// We stop profiling after a timeout to avoid huge profiles to be sent
166+
try {
167+
scheduledFinish =
168+
options
169+
.getExecutorService()
170+
.schedule(
171+
() -> timedOutProfilingData = endAndCollect(true, null),
172+
PROFILING_TIMEOUT_MILLIS);
173+
} catch (RejectedExecutionException e) {
174+
options
175+
.getLogger()
176+
.log(
177+
SentryLevel.ERROR,
178+
"Failed to call the executor. Profiling will not be automatically finished. Did you call Sentry.close()?",
179+
e);
180+
}
181+
182+
transactionStartNanos = SystemClock.elapsedRealtimeNanos();
183+
profileStartCpuMillis = Process.getElapsedCpuTime();
184+
185+
// We don't make any check on the file existence or writeable state, because we don't want to
186+
// make file IO in the main thread.
187+
// We cannot offload the work to the executorService, as if that's very busy, profiles could
188+
// start/stop with a lot of delay and even cause ANRs.
189+
try {
190+
// If there is any problem with the file this method will throw (but it will not throw in
191+
// tests)
192+
Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs);
193+
return new ProfileStartData(transactionStartNanos, profileStartCpuMillis);
194+
} catch (Throwable e) {
195+
endAndCollect(false, null);
196+
options.getLogger().log(SentryLevel.ERROR, "Unable to start a profile: ", e);
197+
return null;
198+
}
199+
}
200+
201+
@SuppressLint("NewApi")
202+
public @Nullable ProfileEndData endAndCollect(
203+
final boolean isTimeout,
204+
final @Nullable List<PerformanceCollectionData> performanceCollectionData) {
205+
// check if profiling timed out
206+
if (timedOutProfilingData != null) {
207+
return timedOutProfilingData;
208+
}
209+
210+
// onTransactionStart() is only available since Lollipop
211+
// and SystemClock.elapsedRealtimeNanos() since Jelly Bean
212+
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return null;
213+
214+
try {
215+
// If there is any problem with the file this method could throw, but the start is also
216+
// wrapped, so this should never happen (except for tests, where this is the only method that
217+
// throws)
218+
Debug.stopMethodTracing();
219+
} catch (Throwable e) {
220+
options.getLogger().log(SentryLevel.ERROR, "Error while stopping profiling: ", e);
221+
}
222+
frameMetricsCollector.stopCollection(frameMetricsCollectorId);
223+
224+
long transactionEndNanos = SystemClock.elapsedRealtimeNanos();
225+
long transactionEndCpuMillis = Process.getElapsedCpuTime();
226+
227+
if (traceFile == null) {
228+
options.getLogger().log(SentryLevel.ERROR, "Trace file does not exists");
229+
return null;
230+
}
231+
232+
if (!slowFrameRenderMeasurements.isEmpty()) {
233+
measurementsMap.put(
234+
ProfileMeasurement.ID_SLOW_FRAME_RENDERS,
235+
new ProfileMeasurement(ProfileMeasurement.UNIT_NANOSECONDS, slowFrameRenderMeasurements));
236+
}
237+
if (!frozenFrameRenderMeasurements.isEmpty()) {
238+
measurementsMap.put(
239+
ProfileMeasurement.ID_FROZEN_FRAME_RENDERS,
240+
new ProfileMeasurement(
241+
ProfileMeasurement.UNIT_NANOSECONDS, frozenFrameRenderMeasurements));
242+
}
243+
if (!screenFrameRateMeasurements.isEmpty()) {
244+
measurementsMap.put(
245+
ProfileMeasurement.ID_SCREEN_FRAME_RATES,
246+
new ProfileMeasurement(ProfileMeasurement.UNIT_HZ, screenFrameRateMeasurements));
247+
}
248+
putPerformanceCollectionDataInMeasurements(performanceCollectionData);
249+
250+
if (scheduledFinish != null) {
251+
scheduledFinish.cancel(true);
252+
scheduledFinish = null;
253+
}
254+
255+
return new ProfileEndData(
256+
transactionEndNanos, transactionEndCpuMillis, isTimeout, traceFile, measurementsMap);
257+
}
258+
259+
public void close() {
260+
// we cancel any scheduled work
261+
if (scheduledFinish != null) {
262+
scheduledFinish.cancel(true);
263+
scheduledFinish = null;
264+
}
265+
}
266+
267+
@SuppressLint("NewApi")
268+
private void putPerformanceCollectionDataInMeasurements(
269+
final @Nullable List<PerformanceCollectionData> performanceCollectionData) {
270+
271+
// onTransactionStart() is only available since Lollipop
272+
// and SystemClock.elapsedRealtimeNanos() since Jelly Bean
273+
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) {
274+
return;
275+
}
276+
277+
// This difference is required, since the PerformanceCollectionData timestamps are expressed in
278+
// terms of System.currentTimeMillis() and measurements timestamps require the nanoseconds since
279+
// the beginning, expressed with SystemClock.elapsedRealtimeNanos()
280+
long timestampDiff =
281+
SystemClock.elapsedRealtimeNanos()
282+
- transactionStartNanos
283+
- TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis());
284+
if (performanceCollectionData != null) {
285+
final @NotNull ArrayDeque<ProfileMeasurementValue> memoryUsageMeasurements =
286+
new ArrayDeque<>(performanceCollectionData.size());
287+
final @NotNull ArrayDeque<ProfileMeasurementValue> nativeMemoryUsageMeasurements =
288+
new ArrayDeque<>(performanceCollectionData.size());
289+
final @NotNull ArrayDeque<ProfileMeasurementValue> cpuUsageMeasurements =
290+
new ArrayDeque<>(performanceCollectionData.size());
291+
for (PerformanceCollectionData performanceData : performanceCollectionData) {
292+
CpuCollectionData cpuData = performanceData.getCpuData();
293+
MemoryCollectionData memoryData = performanceData.getMemoryData();
294+
if (cpuData != null) {
295+
cpuUsageMeasurements.add(
296+
new ProfileMeasurementValue(
297+
TimeUnit.MILLISECONDS.toNanos(cpuData.getTimestampMillis()) + timestampDiff,
298+
cpuData.getCpuUsagePercentage()));
299+
}
300+
if (memoryData != null && memoryData.getUsedHeapMemory() > -1) {
301+
memoryUsageMeasurements.add(
302+
new ProfileMeasurementValue(
303+
TimeUnit.MILLISECONDS.toNanos(memoryData.getTimestampMillis()) + timestampDiff,
304+
memoryData.getUsedHeapMemory()));
305+
}
306+
if (memoryData != null && memoryData.getUsedNativeMemory() > -1) {
307+
nativeMemoryUsageMeasurements.add(
308+
new ProfileMeasurementValue(
309+
TimeUnit.MILLISECONDS.toNanos(memoryData.getTimestampMillis()) + timestampDiff,
310+
memoryData.getUsedNativeMemory()));
311+
}
312+
}
313+
if (!cpuUsageMeasurements.isEmpty()) {
314+
measurementsMap.put(
315+
ProfileMeasurement.ID_CPU_USAGE,
316+
new ProfileMeasurement(ProfileMeasurement.UNIT_PERCENT, cpuUsageMeasurements));
317+
}
318+
if (!memoryUsageMeasurements.isEmpty()) {
319+
measurementsMap.put(
320+
ProfileMeasurement.ID_MEMORY_FOOTPRINT,
321+
new ProfileMeasurement(ProfileMeasurement.UNIT_BYTES, memoryUsageMeasurements));
322+
}
323+
if (!nativeMemoryUsageMeasurements.isEmpty()) {
324+
measurementsMap.put(
325+
ProfileMeasurement.ID_MEMORY_NATIVE_FOOTPRINT,
326+
new ProfileMeasurement(ProfileMeasurement.UNIT_BYTES, nativeMemoryUsageMeasurements));
327+
}
328+
}
329+
}
330+
}

0 commit comments

Comments
 (0)