trace/traceAsync extensions use try-finally incorrectly [247066503]

Fixed

Bug

Status Update

No update yet.

Description

be...@mercurydevelopment.com

created issue #1

Sep 16, 2022 11:25AM

https://github.com/androidx/androidx/blob/androidx-main/tracing/tracing-ktx/src/main/java/androidx/tracing/Trace.kt#L28

The common pattern for try-finally with resources is to

open()
try {
  doSmth()
} finally {
  close()
}

With Trace.beginSection inside the try block it's possible to break all the sections in the trace by closing unopened section in case if Trace.beginSection throws an exception.

And Trace.beginSection may throw an exception if sectionName exceeds 127 characters (probably there are other cases), so this piece of code will produce wrong trace output:

fun wrongTraceFun() = trace(0..100.joinToString("")) { // just any long name
    Thread.sleep(1)
}

fun anotherFun() = trace("anotherFun") {
   runCatching { wrongTraceFun() }
   Trace.sleep(1000)
}

In the resulting trace file all the sections will be skewed (e.g. anotherFun section will be short, instead of 1s)

Comments

ra...@google.com <ra...@google.com> #2Sep 19, 2022 10:45PM

I think you would do something like:

try(open()) {

} finally() {
  // No need to close !
}

When using try with resources.

ra...@google.com <ra...@google.com> #3Sep 19, 2022 10:46PM

Also if Trace.beginSection(name) throws an exception, then endSection will throw the same exception given the use of the same name.

be...@mercurydevelopment.com <be...@mercurydevelopment.com> #4Sep 19, 2022 11:04PM

endSection doesn't accept a name (unlike endAsyncSection), so it will not throw

ra...@google.com <ra...@google.com> #5Sep 19, 2022 11:06PM

So, the issue at hand is that beginSection(...) can throw ?

I was a bit confused when you also mentioned try with resources.

be...@mercurydevelopment.com <be...@mercurydevelopment.com> #6Sep 19, 2022 11:16PM

Yeah, I was more about the pattern (that opening resource shouldn't be a part of try block) rather than about exact Java's operator.

The problem here is the beginSection is inside try, while endSection is in the finally block. That means you may not open section, but will always close it (actually previously opened section).

As a fix beginSection just needs to be moved outside of try block

cc...@google.com <cc...@google.com> Sep 22, 2022 06:10PM

Reassigned to cc...@google.com.

ap...@google.com <ap...@google.com> #7Sep 27, 2022 11:27PM

Marked as fixed.

Project: platform/frameworks/support
Branch: androidx-main

commit 1b1aff5c19b657883eb1d657767284a733542c8d
Author: Chris Craik <ccraik@google.com>
Date: Tue Dec 08 17:14:43 2020

Add trace() and traceAsync() lazy string variants, and fix try usage

Test: TraceTestKt
Fixes: 175233952
Fixes: 247066503
Relnote: "Add trace() and traceAsync() variants with lazy string
and cookie computation. Also now correctly skips Trace.end if
Trace.begin throws."

Unable to easily test the try/finally fix, as the incorrect extra end
event only occurs for synchronous events (Trace.endSection), which
doesn't have a unique label or cookie param to validate.

Change-Id: I314210e79d91f7e71140208c61c8672591aef88b

M tracing/tracing-ktx/api/current.txt
M tracing/tracing-ktx/src/androidTest/java/androidx/tracing/TraceTestKt.kt
M tracing/tracing-ktx/api/restricted_current.txt
M tracing/tracing-ktx/api/public_plus_experimental_current.txt
M tracing/tracing-ktx/src/main/java/androidx/tracing/Trace.kt

https://android-review.googlesource.com/2227300

na...@google.com <na...@google.com> #8Oct 5, 2022 05:14PM

This bug was linked in a change in the following release(s):

androidx.tracing:tracing-ktx:1.2.0-alpha01