Skip to content
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

Jump to bottom

Disable Android concurrent profiling #2434

Merged
merged 10 commits into from Dec 22, 2022
Merged

Disable Android concurrent profiling #2434

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
b99cd60
SentryTracer sends profile inside transaction envelope
stefanosiano Dec 16, 2022
ed4f8ca
Merge branch 'main' into android/revert-concurrent-profiling
stefanosiano Dec 16, 2022
9fdeddd
updated changelog
stefanosiano Dec 16, 2022
3d109e1
Merge branch 'main' into android/revert-concurrent-profiling
stefanosiano Dec 19, 2022
eaf74c6
removed transaction map from profiler, as now only one transaction at…
stefanosiano Dec 20, 2022
c8003a0
Merge branch 'main' into android/revert-concurrent-profiling
stefanosiano Dec 20, 2022
907cf94
renamed internal field in AndroidTransactionProfiler currentTransacti…
stefanosiano Dec 20, 2022
c255e2e
used logger to log exceptions
stefanosiano Dec 21, 2022
a67ea7a
Merge branch 'main' into android/revert-concurrent-profiling
stefanosiano Dec 21, 2022
fcc20dc
Merge branch 'main' into android/revert-concurrent-profiling
stefanosiano Dec 22, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
4 changes: 4 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Expand Up @@ -2,6 +2,10 @@

## Unreleased

### Features

- Disable Android concurrent profiling ([#2434](https://github.com/getsentry/sentry-java/pull/2434))

### Fixes

- Use minSdk compatible `Objects` class ([#2436](https://github.com/getsentry/sentry-java/pull/2436))
Expand Down
169 changes: 92 additions & 77 deletions sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java
View file
Open in desktop
Expand Up @@ -17,11 +17,9 @@
import io.sentry.ITransactionProfiler;
import io.sentry.ProfilingTraceData;
import io.sentry.ProfilingTransactionData;
import io.sentry.SentryEnvelope;
import io.sentry.SentryLevel;
import io.sentry.android.core.internal.util.CpuInfoUtils;
import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
import io.sentry.exception.SentryEnvelopeException;
import io.sentry.profilemeasurements.ProfileMeasurement;
import io.sentry.profilemeasurements.ProfileMeasurementValue;
import io.sentry.util.Objects;
Expand All @@ -32,6 +30,7 @@
import java.util.List;
import java.util.Map;
import java.util.UUID;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import org.jetbrains.annotations.NotNull;
Expand All @@ -56,6 +55,7 @@ final class AndroidTransactionProfiler implements ITransactionProfiler {
private @Nullable File traceFile = null;
private @Nullable File traceFilesDir = null;
private @Nullable Future<?> scheduledFinish = null;
private volatile @Nullable ProfilingTraceData timedOutProfilingData = null;
private final @NotNull Context context;
private final @NotNull SentryAndroidOptions options;
private final @NotNull IHub hub;
Expand All @@ -66,7 +66,7 @@ final class AndroidTransactionProfiler implements ITransactionProfiler {
private int transactionsCounter = 0;
private @Nullable String frameMetricsCollectorId;
private final @NotNull SentryFrameMetricsCollector frameMetricsCollector;
private final @NotNull Map<String, ProfilingTransactionData> transactionMap = new HashMap<>();
private @Nullable ProfilingTransactionData currentProfilingTransactionData;
private final @NotNull ArrayDeque<ProfileMeasurementValue> screenFrameRateMeasurements =
new ArrayDeque<>();
private final @NotNull ArrayDeque<ProfileMeasurementValue> slowFrameRenderMeasurements =
Expand Down Expand Up @@ -160,20 +160,23 @@ private void onTransactionStartSafe(final @NotNull ITransaction transaction) {
// When the first transaction is starting, we can start profiling
if (transactionsCounter == 1) {
onFirstTransactionStarted(transaction);
options
.getLogger()
.log(
SentryLevel.DEBUG,
"Transaction %s (%s) started and being profiled.",
transaction.getName(),
transaction.getSpanContext().getTraceId().toString());
} else {
ProfilingTransactionData transactionData =
new ProfilingTransactionData(
transaction, SystemClock.elapsedRealtimeNanos(), Process.getElapsedCpuTime());
transactionMap.put(transaction.getEventId().toString(), transactionData);
transactionsCounter--;
options
.getLogger()
.log(
SentryLevel.WARNING,
"A transaction is already being profiled. Transaction %s (%s) will be ignored.",
transaction.getName(),
transaction.getSpanContext().getTraceId().toString());
}
options
.getLogger()
.log(
SentryLevel.DEBUG,
"Transaction %s (%s) started. Transactions being profiled: %d",
transaction.getName(),
transaction.getSpanContext().getTraceId().toString(),
transactionsCounter);
}

@SuppressLint("NewApi")
Expand Down Expand Up @@ -229,41 +232,75 @@ public void onFrameMetricCollected(
scheduledFinish =
options
.getExecutorService()
.schedule(() -> onTransactionFinish(transaction, true), PROFILING_TIMEOUT_MILLIS);
.schedule(
() -> timedOutProfilingData = onTransactionFinish(transaction, true),
PROFILING_TIMEOUT_MILLIS);

transactionStartNanos = SystemClock.elapsedRealtimeNanos();
profileStartCpuMillis = Process.getElapsedCpuTime();

ProfilingTransactionData transactionData =
currentProfilingTransactionData =
new ProfilingTransactionData(transaction, transactionStartNanos, profileStartCpuMillis);
transactionMap.put(transaction.getEventId().toString(), transactionData);

Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs);
}

@Override
public synchronized void onTransactionFinish(final @NotNull ITransaction transaction) {
options.getExecutorService().submit(() -> onTransactionFinish(transaction, false));
public @Nullable synchronized ProfilingTraceData onTransactionFinish(
final @NotNull ITransaction transaction) {
try {
return options
.getExecutorService()
.submit(() -> onTransactionFinish(transaction, false))
.get();
Copy link
Member

Choose a reason for hiding this comment

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

hmm, why do we need to use ExecutorService here if we are anyway awaiting for it in a blocking way?

Copy link
Member Author

Choose a reason for hiding this comment

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

to avoid calling onTransactionStart in the executor service thread and onTransactionFinish in a different thread. In case these methods are called very fast there could be a race condition. It's an edge case, tough

} catch (ExecutionException e) {
options.getLogger().log(SentryLevel.ERROR, "Error finishing profiling: ", e);
} catch (InterruptedException e) {
options.getLogger().log(SentryLevel.ERROR, "Error finishing profiling: ", e);
}
return null;
}

@SuppressLint("NewApi")
private void onTransactionFinish(
private @Nullable ProfilingTraceData onTransactionFinish(
final @NotNull ITransaction transaction, final boolean isTimeout) {

// onTransactionStart() is only available since Lollipop
// and SystemClock.elapsedRealtimeNanos() since Jelly Bean
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return;

// Transaction finished, but it's not in the current profile. We can skip it
if (!transactionMap.containsKey(transaction.getEventId().toString())) {
if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return null;

final ProfilingTraceData profilingData = timedOutProfilingData;

// Transaction finished, but it's not in the current profile
if (currentProfilingTransactionData == null
|| !currentProfilingTransactionData.getId().equals(transaction.getEventId().toString())) {
// We check if we cached a profiling data due to a timeout with this profile in it
// If so, we return it back, otherwise we would simply lose it
if (profilingData != null) {
if (profilingData.getTransactionId().equals(transaction.getEventId().toString())) {
timedOutProfilingData = null;
return profilingData;
} else {
// Another transaction is finishing before the timed out one
options
.getLogger()
.log(
SentryLevel.INFO,
"A timed out profiling data exists, but the finishing transaction %s (%s) is not part of it",
transaction.getName(),
transaction.getSpanContext().getTraceId().toString());
return null;
}
}
// A transaction is finishing, but it's not profiled. We can skip it
options
.getLogger()
.log(
SentryLevel.INFO,
"Transaction %s (%s) finished, but was not currently being profiled. Skipping",
transaction.getName(),
transaction.getSpanContext().getTraceId().toString());
return;
return null;
}

if (transactionsCounter > 0) {
Expand All @@ -274,38 +311,32 @@ private void onTransactionFinish(
.getLogger()
.log(
SentryLevel.DEBUG,
"Transaction %s (%s) finished. Transactions to be profiled: %d",
"Transaction %s (%s) finished.",
transaction.getName(),
transaction.getSpanContext().getTraceId().toString(),
transactionsCounter);
transaction.getSpanContext().getTraceId().toString());

if (transactionsCounter != 0 && !isTimeout) {
// We notify the data referring to this transaction that it finished
ProfilingTransactionData transactionData =
transactionMap.get(transaction.getEventId().toString());
if (transactionData != null) {
transactionData.notifyFinish(
if (currentProfilingTransactionData != null) {
currentProfilingTransactionData.notifyFinish(
SystemClock.elapsedRealtimeNanos(),
transactionStartNanos,
Process.getElapsedCpuTime(),
profileStartCpuMillis);
}
return;
return null;
}
onLastTransactionFinished(transaction, isTimeout);
}

@SuppressLint("NewApi")
private void onLastTransactionFinished(final ITransaction transaction, final boolean isTimeout) {
Debug.stopMethodTracing();
frameMetricsCollector.stopCollection(frameMetricsCollectorId);

long transactionEndNanos = SystemClock.elapsedRealtimeNanos();
long transactionEndCpuMillis = Process.getElapsedCpuTime();
long transactionDurationNanos = transactionEndNanos - transactionStartNanos;

List<ProfilingTransactionData> transactionList = new ArrayList<>(transactionMap.values());
transactionMap.clear();
List<ProfilingTransactionData> transactionList = new ArrayList<>(1);
transactionList.add(currentProfilingTransactionData);
currentProfilingTransactionData = null;
// We clear the counter in case of a timeout
transactionsCounter = 0;

Expand All @@ -316,7 +347,7 @@ private void onLastTransactionFinished(final ITransaction transaction, final boo

if (traceFile == null) {
options.getLogger().log(SentryLevel.ERROR, "Trace file does not exists");
return;
return null;
}

String totalMem = "0";
Expand Down Expand Up @@ -355,42 +386,26 @@ private void onLastTransactionFinished(final ITransaction transaction, final boo

// cpu max frequencies are read with a lambda because reading files is involved, so it will be
// done in the background when the trace file is read
ProfilingTraceData profilingTraceData =
new ProfilingTraceData(
traceFile,
transactionList,
transaction,
Long.toString(transactionDurationNanos),
buildInfoProvider.getSdkInfoVersion(),
abis != null && abis.length > 0 ? abis[0] : "",
() -> CpuInfoUtils.getInstance().readMaxFrequencies(),
buildInfoProvider.getManufacturer(),
buildInfoProvider.getModel(),
buildInfoProvider.getVersionRelease(),
buildInfoProvider.isEmulator(),
totalMem,
options.getProguardUuid(),
options.getRelease(),
options.getEnvironment(),
isTimeout
? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT
: ProfilingTraceData.TRUNCATION_REASON_NORMAL,
measurementsMap);

SentryEnvelope envelope;
try {
envelope =
SentryEnvelope.from(
options.getSerializer(),
profilingTraceData,
options.getMaxTraceFileSize(),
options.getSdkVersion());
} catch (SentryEnvelopeException e) {
options.getLogger().log(SentryLevel.ERROR, "Failed to capture profile.", e);
return;
}

hub.captureEnvelope(envelope);
return new ProfilingTraceData(
traceFile,
transactionList,
transaction,
Long.toString(transactionDurationNanos),
buildInfoProvider.getSdkInfoVersion(),
abis != null && abis.length > 0 ? abis[0] : "",
() -> CpuInfoUtils.getInstance().readMaxFrequencies(),
buildInfoProvider.getManufacturer(),
buildInfoProvider.getModel(),
buildInfoProvider.getVersionRelease(),
buildInfoProvider.isEmulator(),
totalMem,
options.getProguardUuid(),
options.getRelease(),
options.getEnvironment(),
isTimeout
? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT
: ProfilingTraceData.TRUNCATION_REASON_NORMAL,
measurementsMap);
}

/**
Expand Down
15 changes: 9 additions & 6 deletions sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt
View file
Open in desktop
Expand Up @@ -378,6 +378,7 @@ class ActivityLifecycleIntegrationTest {
assertEquals(SpanStatus.OK, it.status)
},
anyOrNull<TraceContext>(),
anyOrNull(),
anyOrNull()
)
}
Expand All @@ -397,6 +398,7 @@ class ActivityLifecycleIntegrationTest {
assertEquals(SpanStatus.OK, it.status)
},
anyOrNull<TraceContext>(),
anyOrNull(),
anyOrNull()
)
}
Expand All @@ -420,6 +422,7 @@ class ActivityLifecycleIntegrationTest {
assertEquals(SpanStatus.UNKNOWN_ERROR, it.status)
},
anyOrNull<TraceContext>(),
anyOrNull(),
anyOrNull()
)
}
Expand All @@ -435,7 +438,7 @@ class ActivityLifecycleIntegrationTest {
sut.onActivityCreated(activity, fixture.bundle)
sut.onActivityPostResumed(activity)

verify(fixture.hub, never()).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull())
verify(fixture.hub, never()).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull(), anyOrNull())
}

@Test
Expand All @@ -446,7 +449,7 @@ class ActivityLifecycleIntegrationTest {
val activity = mock<Activity>()
sut.onActivityPostResumed(activity)

verify(fixture.hub, never()).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull())
verify(fixture.hub, never()).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull(), anyOrNull())
}

@Test
Expand All @@ -459,7 +462,7 @@ class ActivityLifecycleIntegrationTest {
sut.onActivityCreated(activity, fixture.bundle)
sut.onActivityDestroyed(activity)

verify(fixture.hub).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull())
verify(fixture.hub).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull(), anyOrNull())
}

@Test
Expand Down Expand Up @@ -561,7 +564,7 @@ class ActivityLifecycleIntegrationTest {
sut.onActivityCreated(mock(), mock())

sut.onActivityCreated(mock(), fixture.bundle)
verify(fixture.hub).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull())
verify(fixture.hub).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull(), anyOrNull())
}

@Test
Expand All @@ -574,7 +577,7 @@ class ActivityLifecycleIntegrationTest {
sut.onActivityCreated(activity, mock())
sut.onActivityResumed(activity)

verify(fixture.hub, never()).captureTransaction(any(), any<TraceContext>(), anyOrNull())
verify(fixture.hub, never()).captureTransaction(any(), any<TraceContext>(), anyOrNull(), anyOrNull())
}

@Test
Expand Down Expand Up @@ -602,7 +605,7 @@ class ActivityLifecycleIntegrationTest {
sut.ttidSpanMap.values.first().finish()
sut.onActivityResumed(activity)

verify(fixture.hub).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull())
verify(fixture.hub).captureTransaction(any(), anyOrNull<TraceContext>(), anyOrNull(), anyOrNull())
}

@Test
Expand Down