Skip to content

Commit 725987d

Browse files
authored
[ANR] Reduced AndroidTransactionProfiler lock (#4817)
* reduced lock in AndroidTransactionProfiler * added unbind of currentProfilingTransactionData on failed starts * close always set isRunning to false * added comment * made currentProfilingTransactionData volatile * made AndroidProfiler.isRunning volatile
1 parent 1f3a214 commit 725987d

File tree

4 files changed

+145
-148
lines changed

4 files changed

+145
-148
lines changed

CHANGELOG.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,10 @@
22

33
## Unreleased
44

5+
### Fixes
6+
7+
- [ANR] Removed AndroidTransactionProfiler lock ([#4817](https://github.com/getsentry/sentry-java/pull/4817))
8+
59
### Dependencies
610

711
- Bump Native SDK from v0.11.2 to v0.11.3 ([#4810](https://github.com/getsentry/sentry-java/pull/4810))

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

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -94,7 +94,7 @@ public ProfileEndData(
9494
private final @NotNull Map<String, ProfileMeasurement> measurementsMap = new HashMap<>();
9595
private final @Nullable ISentryExecutorService timeoutExecutorService;
9696
private final @NotNull ILogger logger;
97-
private boolean isRunning = false;
97+
private volatile boolean isRunning = false;
9898
protected final @NotNull AutoClosableReentrantLock lock = new AutoClosableReentrantLock();
9999

100100
public AndroidProfiler(
@@ -354,4 +354,8 @@ private void putPerformanceCollectionDataInMeasurements(
354354
}
355355
}
356356
}
357+
358+
boolean isRunning() {
359+
return isRunning;
360+
}
357361
}

sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java

Lines changed: 116 additions & 127 deletions
Original file line numberDiff line numberDiff line change
@@ -5,8 +5,6 @@
55
import android.annotation.SuppressLint;
66
import android.content.Context;
77
import android.os.Build;
8-
import android.os.Process;
9-
import android.os.SystemClock;
108
import io.sentry.DateUtils;
119
import io.sentry.ILogger;
1210
import io.sentry.ISentryExecutorService;
@@ -26,9 +24,9 @@
2624
import java.util.ArrayList;
2725
import java.util.Date;
2826
import java.util.List;
27+
import java.util.concurrent.atomic.AtomicBoolean;
2928
import org.jetbrains.annotations.NotNull;
3029
import org.jetbrains.annotations.Nullable;
31-
import org.jetbrains.annotations.TestOnly;
3230

3331
final class AndroidTransactionProfiler implements ITransactionProfiler {
3432
private final @NotNull Context context;
@@ -39,10 +37,16 @@ final class AndroidTransactionProfiler implements ITransactionProfiler {
3937
private final @NotNull ISentryExecutorService executorService;
4038
private final @NotNull BuildInfoProvider buildInfoProvider;
4139
private boolean isInitialized = false;
42-
private int transactionsCounter = 0;
40+
private final @NotNull AtomicBoolean isRunning = new AtomicBoolean(false);
4341
private final @NotNull SentryFrameMetricsCollector frameMetricsCollector;
44-
private @Nullable ProfilingTransactionData currentProfilingTransactionData;
45-
private @Nullable AndroidProfiler profiler = null;
42+
private volatile @Nullable ProfilingTransactionData currentProfilingTransactionData;
43+
44+
/**
45+
* The underlying profiler instance. It is thread safe to call it after checking if it's not null,
46+
* because we never nullify it after instantiation.
47+
*/
48+
private volatile @Nullable AndroidProfiler profiler = null;
49+
4650
private long profileStartNanos;
4751
private long profileStartCpuMillis;
4852
private @NotNull Date profileStartTimestamp;
@@ -95,6 +99,7 @@ private void init() {
9599
return;
96100
}
97101
isInitialized = true;
102+
98103
if (!isProfilingEnabled) {
99104
logger.log(SentryLevel.INFO, "Profiling is disabled in options.");
100105
return;
@@ -124,22 +129,30 @@ private void init() {
124129

125130
@Override
126131
public void start() {
127-
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
128-
// Debug.startMethodTracingSampling() is only available since Lollipop, but Android Profiler
129-
// causes crashes on api 21 -> https://github.com/getsentry/sentry-java/issues/3392
130-
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return;
132+
// Debug.startMethodTracingSampling() is only available since Lollipop, but Android Profiler
133+
// causes crashes on api 21 -> https://github.com/getsentry/sentry-java/issues/3392
134+
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return;
131135

136+
// When the first transaction is starting, we can start profiling
137+
if (!isRunning.getAndSet(true)) {
132138
// Let's initialize trace folder and profiling interval
133139
init();
134140

135-
transactionsCounter++;
136-
// When the first transaction is starting, we can start profiling
137-
if (transactionsCounter == 1 && onFirstStart()) {
141+
if (onFirstStart()) {
138142
logger.log(SentryLevel.DEBUG, "Profiler started.");
139143
} else {
140-
transactionsCounter--;
141-
logger.log(
142-
SentryLevel.WARNING, "A profile is already running. This profile will be ignored.");
144+
// If profiler is not null and is running, it means that a profile is already running
145+
if (profiler != null && profiler.isRunning()) {
146+
logger.log(
147+
SentryLevel.WARNING, "A profile is already running. This profile will be ignored.");
148+
} else {
149+
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
150+
// Ensure we unbind any transaction data, just in case of concurrent starts
151+
currentProfilingTransactionData = null;
152+
}
153+
// Otherwise we update the flag, because it means the profiler is not running
154+
isRunning.set(false);
155+
}
143156
}
144157
}
145158
}
@@ -164,11 +177,14 @@ private boolean onFirstStart() {
164177

165178
@Override
166179
public void bindTransaction(final @NotNull ITransaction transaction) {
167-
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
168-
// If the profiler is running, but no profilingTransactionData is set, we bind it here
169-
if (transactionsCounter > 0 && currentProfilingTransactionData == null) {
170-
currentProfilingTransactionData =
171-
new ProfilingTransactionData(transaction, profileStartNanos, profileStartCpuMillis);
180+
// If the profiler is running, but no profilingTransactionData is set, we bind it here
181+
if (isRunning.get() && currentProfilingTransactionData == null) {
182+
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
183+
// If the profiler is running, but no profilingTransactionData is set, we bind it here
184+
if (isRunning.get() && currentProfilingTransactionData == null) {
185+
currentProfilingTransactionData =
186+
new ProfilingTransactionData(transaction, profileStartNanos, profileStartCpuMillis);
187+
}
172188
}
173189
}
174190
}
@@ -178,15 +194,13 @@ public void bindTransaction(final @NotNull ITransaction transaction) {
178194
final @NotNull ITransaction transaction,
179195
final @Nullable List<PerformanceCollectionData> performanceCollectionData,
180196
final @NotNull SentryOptions options) {
181-
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
182-
return onTransactionFinish(
183-
transaction.getName(),
184-
transaction.getEventId().toString(),
185-
transaction.getSpanContext().getTraceId().toString(),
186-
false,
187-
performanceCollectionData,
188-
options);
189-
}
197+
return onTransactionFinish(
198+
transaction.getName(),
199+
transaction.getEventId().toString(),
200+
transaction.getSpanContext().getTraceId().toString(),
201+
false,
202+
performanceCollectionData,
203+
options);
190204
}
191205

192206
@SuppressLint("NewApi")
@@ -197,20 +211,23 @@ public void bindTransaction(final @NotNull ITransaction transaction) {
197211
final boolean isTimeout,
198212
final @Nullable List<PerformanceCollectionData> performanceCollectionData,
199213
final @NotNull SentryOptions options) {
200-
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
201-
// check if profiler was created
202-
if (profiler == null) {
203-
return null;
204-
}
205214

206-
// onTransactionStart() is only available since Lollipop_MR1
207-
// and SystemClock.elapsedRealtimeNanos() since Jelly Bean
208-
// and SUPPORTED_ABIS since KITKAT
209-
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return null;
215+
// onTransactionStart() is only available since Lollipop_MR1
216+
// and SystemClock.elapsedRealtimeNanos() since Jelly Bean
217+
// and SUPPORTED_ABIS since KITKAT
218+
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP_MR1) return null;
219+
220+
// check if profiler was created
221+
if (profiler == null) {
222+
return null;
223+
}
224+
225+
final ProfilingTransactionData txData;
226+
try (final @NotNull ISentryLifecycleToken ignored = lock.acquire()) {
227+
txData = currentProfilingTransactionData;
210228

211229
// Transaction finished, but it's not in the current profile
212-
if (currentProfilingTransactionData == null
213-
|| !currentProfilingTransactionData.getId().equals(transactionId)) {
230+
if (txData == null || !txData.getId().equals(transactionId)) {
214231
// A transaction is finishing, but it's not profiled. We can skip it
215232
logger.log(
216233
SentryLevel.INFO,
@@ -219,118 +236,90 @@ public void bindTransaction(final @NotNull ITransaction transaction) {
219236
traceId);
220237
return null;
221238
}
239+
currentProfilingTransactionData = null;
240+
}
222241

223-
if (transactionsCounter > 0) {
224-
transactionsCounter--;
225-
}
242+
logger.log(SentryLevel.DEBUG, "Transaction %s (%s) finished.", transactionName, traceId);
226243

227-
logger.log(SentryLevel.DEBUG, "Transaction %s (%s) finished.", transactionName, traceId);
244+
final AndroidProfiler.ProfileEndData endData =
245+
profiler.endAndCollect(false, performanceCollectionData);
228246

229-
if (transactionsCounter != 0) {
230-
// We notify the data referring to this transaction that it finished
231-
if (currentProfilingTransactionData != null) {
232-
currentProfilingTransactionData.notifyFinish(
233-
SystemClock.elapsedRealtimeNanos(),
234-
profileStartNanos,
235-
Process.getElapsedCpuTime(),
236-
profileStartCpuMillis);
237-
}
238-
return null;
239-
}
240-
241-
final AndroidProfiler.ProfileEndData endData =
242-
profiler.endAndCollect(false, performanceCollectionData);
243-
// check if profiler end successfully
244-
if (endData == null) {
245-
return null;
246-
}
247+
isRunning.set(false);
247248

248-
long transactionDurationNanos = endData.endNanos - profileStartNanos;
249+
// check if profiler end successfully
250+
if (endData == null) {
251+
return null;
252+
}
249253

250-
List<ProfilingTransactionData> transactionList = new ArrayList<>(1);
251-
final ProfilingTransactionData txData = currentProfilingTransactionData;
252-
if (txData != null) {
253-
transactionList.add(txData);
254-
}
255-
currentProfilingTransactionData = null;
256-
// We clear the counter in case of a timeout
257-
transactionsCounter = 0;
258-
259-
String totalMem = "0";
260-
final @Nullable Long memory =
261-
(options instanceof SentryAndroidOptions)
262-
? DeviceInfoUtil.getInstance(context, (SentryAndroidOptions) options).getTotalMemory()
263-
: null;
264-
if (memory != null) {
265-
totalMem = Long.toString(memory);
266-
}
267-
String[] abis = Build.SUPPORTED_ABIS;
254+
long transactionDurationNanos = endData.endNanos - profileStartNanos;
268255

269-
// We notify all transactions data that all transactions finished.
270-
// Some may not have been really finished, in case of a timeout
271-
for (ProfilingTransactionData t : transactionList) {
272-
t.notifyFinish(
273-
endData.endNanos, profileStartNanos, endData.endCpuMillis, profileStartCpuMillis);
274-
}
256+
final @NotNull List<ProfilingTransactionData> transactionList = new ArrayList<>(1);
257+
transactionList.add(txData);
258+
txData.notifyFinish(
259+
endData.endNanos, profileStartNanos, endData.endCpuMillis, profileStartCpuMillis);
275260

276-
// cpu max frequencies are read with a lambda because reading files is involved, so it will be
277-
// done in the background when the trace file is read
278-
return new ProfilingTraceData(
279-
endData.traceFile,
280-
profileStartTimestamp,
281-
transactionList,
282-
transactionName,
283-
transactionId,
284-
traceId,
285-
Long.toString(transactionDurationNanos),
286-
buildInfoProvider.getSdkInfoVersion(),
287-
abis != null && abis.length > 0 ? abis[0] : "",
288-
() -> CpuInfoUtils.getInstance().readMaxFrequencies(),
289-
buildInfoProvider.getManufacturer(),
290-
buildInfoProvider.getModel(),
291-
buildInfoProvider.getVersionRelease(),
292-
buildInfoProvider.isEmulator(),
293-
totalMem,
294-
options.getProguardUuid(),
295-
options.getRelease(),
296-
options.getEnvironment(),
297-
(endData.didTimeout || isTimeout)
298-
? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT
299-
: ProfilingTraceData.TRUNCATION_REASON_NORMAL,
300-
endData.measurementsMap);
261+
String totalMem = "0";
262+
final @Nullable Long memory =
263+
(options instanceof SentryAndroidOptions)
264+
? DeviceInfoUtil.getInstance(context, (SentryAndroidOptions) options).getTotalMemory()
265+
: null;
266+
if (memory != null) {
267+
totalMem = Long.toString(memory);
301268
}
269+
final String[] abis = Build.SUPPORTED_ABIS;
270+
271+
// cpu max frequencies are read with a lambda because reading files is involved, so it will be
272+
// done in the background when the trace file is read
273+
return new ProfilingTraceData(
274+
endData.traceFile,
275+
profileStartTimestamp,
276+
transactionList,
277+
transactionName,
278+
transactionId,
279+
traceId,
280+
Long.toString(transactionDurationNanos),
281+
buildInfoProvider.getSdkInfoVersion(),
282+
abis != null && abis.length > 0 ? abis[0] : "",
283+
() -> CpuInfoUtils.getInstance().readMaxFrequencies(),
284+
buildInfoProvider.getManufacturer(),
285+
buildInfoProvider.getModel(),
286+
buildInfoProvider.getVersionRelease(),
287+
buildInfoProvider.isEmulator(),
288+
totalMem,
289+
options.getProguardUuid(),
290+
options.getRelease(),
291+
options.getEnvironment(),
292+
(endData.didTimeout || isTimeout)
293+
? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT
294+
: ProfilingTraceData.TRUNCATION_REASON_NORMAL,
295+
endData.measurementsMap);
302296
}
303297

304298
@Override
305299
public boolean isRunning() {
306-
return transactionsCounter != 0;
300+
return isRunning.get();
307301
}
308302

309303
@Override
310304
public void close() {
305+
final @Nullable ProfilingTransactionData txData = currentProfilingTransactionData;
311306
// we stop profiling
312-
if (currentProfilingTransactionData != null) {
307+
if (txData != null) {
313308
onTransactionFinish(
314-
currentProfilingTransactionData.getName(),
315-
currentProfilingTransactionData.getId(),
316-
currentProfilingTransactionData.getTraceId(),
309+
txData.getName(),
310+
txData.getId(),
311+
txData.getTraceId(),
317312
true,
318313
null,
319314
ScopesAdapter.getInstance().getOptions());
320-
} else if (transactionsCounter != 0) {
321-
// in case the app start profiling is running, and it's not bound to a transaction, we still
322-
// stop profiling, but we also have to manually update the counter.
323-
transactionsCounter--;
324315
}
316+
// in case the app start profiling is running, and it's not bound to a transaction, we still
317+
// stop profiling, but we also have to manually update the flag.
318+
isRunning.set(false);
325319

326320
// we have to first stop profiling otherwise we would lost the last profile
327321
if (profiler != null) {
328322
profiler.close();
329323
}
330324
}
331-
332-
@TestOnly
333-
int getTransactionsCounter() {
334-
return transactionsCounter;
335-
}
336325
}

0 commit comments

Comments
 (0)