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.

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

add app launch TTI log #12

Merged
merged 18 commits into from
Aug 30, 2024
Merged
Show file tree
Hide file tree
Changes from 12 commits
Commits
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
1 change: 1 addition & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

5 changes: 5 additions & 0 deletions examples/android/MainActivity.kt
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,9 @@ import okhttp3.Request
import okhttp3.Response
import java.io.IOException
import kotlin.system.exitProcess
import kotlin.time.Duration
import kotlin.time.DurationUnit
import kotlin.time.toDuration

class MainActivity : ComponentActivity() {

Expand Down Expand Up @@ -121,6 +124,8 @@ class MainActivity : ComponentActivity() {

Logger.addField("field_container_field_key", "field_container_field_value")
Logger.logInfo(mapOf("key" to "value")) { "MainActivity onCreate called" }

Logger.logAppLaunchTTI(1.toDuration(DurationUnit.SECONDS))
Copy link
Contributor

Choose a reason for hiding this comment

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

this is not accurate /trolling

}

private fun createComposeUI() {
Expand Down
3 changes: 2 additions & 1 deletion examples/swift/hello_world/ContentView.swift
Original file line number Diff line number Diff line change
Expand Up @@ -17,8 +17,8 @@ struct ContentView: View {
@State private var selectedLogLevel = LoggerCustomer.LogLevel.info

init(navigationController: UINavigationController?) {
self.navigationController = navigationController
self.loggerCustomer = LoggerCustomer()
self.navigationController = navigationController
self.currentSessionID = self.loggerCustomer.sessionID ?? "No Session ID"
}

Expand Down Expand Up @@ -103,6 +103,7 @@ struct ContentView: View {
}
}
.padding(5)
.onAppear { self.loggerCustomer.logAppLaunchTTI() }
}
}

Expand Down
8 changes: 8 additions & 0 deletions examples/swift/hello_world/LoggerCustomer.swift
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,8 @@ final class LoggerCustomer: NSObject, URLSessionDelegate {
var id: String { return self.rawValue }
}

private var appStartTime: Date

private let requestDefinitions = [
// swiftlint:disable:next force_unwrapping use_static_string_url_init
RequestDefinition(method: "GET", url: URL(string: "https://httpbin.org/get")!),
Expand Down Expand Up @@ -79,6 +81,8 @@ final class LoggerCustomer: NSObject, URLSessionDelegate {
}

override init() {
self.appStartTime = Date()

Logger
.configure(
withAPIKey: kBitdriftAPIKey,
Expand Down Expand Up @@ -160,6 +164,10 @@ final class LoggerCustomer: NSObject, URLSessionDelegate {
Logger.logTrace("Sending log with level [Trace]", fields: fields)
}
}

func logAppLaunchTTI() {
Logger.logAppLaunchTTI(duration: Date().timeIntervalSince(self.appStartTime))
}
}

extension LoggerCustomer: MXMetricManagerSubscriber {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import io.bitdrift.capture.providers.SystemDateProvider
import io.bitdrift.capture.providers.session.SessionStrategy
import okhttp3.HttpUrl
import java.util.concurrent.atomic.AtomicReference
import kotlin.time.Duration

/**
* Top level namespace Capture SDK.
Expand Down Expand Up @@ -278,6 +279,18 @@ object Capture {
logger()?.log(level = level, fields = fields, throwable = throwable, message = message)
}

/**
* Writes an app launch TTI log event. This event should be logged only once per Logger configuration.
* Consecutive calls have no effect.
*
* @param duration The time between a user's intent to launch the app and when the app becomes
* interactive.
*/
@JvmStatic
fun logAppLaunchTTI(duration: Duration) {
logger()?.logAppLaunchTTI(duration)
}

/**
* Signals that an operation has started at this point in time.
*
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -229,6 +229,19 @@ internal object CaptureJniLibrary {
durationS: Double,
)

/**
* Writes an app launch TTI log. The method should be called only once per logger Id. Consecutive calls
* have no effect.
*
* @param loggerId the ID of the logger to write to.
* @param durationS the time between a user's intent to launch the app and when the app becomes
* interactive.
*/
external fun writeAppLaunchTTILog(
loggerId: Long,
durationS: Double,
Copy link
Contributor

Choose a reason for hiding this comment

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

why the S in the param name? Is it in Seconds?

Copy link
Contributor

Choose a reason for hiding this comment

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

I see below that it is. Is this a standard, to use seconds in Doubles to track time? and if so we should add the seconds unit part to the docstring

Copy link
Contributor

Choose a reason for hiding this comment

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

also worth mentioning that the value should be positive otherwise will be ignored

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I see below that it is. Is this a standard, to use seconds in Doubles to track time? and if so we should add the seconds unit part to the docstring

I like the idea. Will do.

also worth mentioning that the value should be positive otherwise will be ignored

Is there ever a case when negative duration make sense? 🙃 I can add this info to the method documentation but I wonder whether it's worth it given that it will provide little to no value at the expense of more clutter in docs. Thoughts?

Copy link
Contributor

Choose a reason for hiding this comment

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

Anything that an API allows users will do. My opinion is that we should never allow for invalid operations using the type system itself e.g. our Span API doesn't allow negative durations.

So at least we should document that this particular usage is invalid

)

/**
* Flushes logger's state to disk.
*
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ package io.bitdrift.capture
import io.bitdrift.capture.events.span.Span
import io.bitdrift.capture.network.HttpRequestInfo
import io.bitdrift.capture.network.HttpResponseInfo
import kotlin.time.Duration

/**
* A Capture SDK logger interface.
Expand Down Expand Up @@ -72,6 +73,7 @@ interface ILogger {

/**
* Logs a message at a specified level.
*
Copy link
Contributor

Choose a reason for hiding this comment

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

fighting the good fight

Copy link
Contributor Author

Choose a reason for hiding this comment

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

always for the right cause

* @param level the severity of the log.
* @param fields and optional collection of key-value pairs to be added to the log line.
* @param throwable an optional throwable to include in the log line.
Expand All @@ -84,6 +86,15 @@ interface ILogger {
message: () -> String,
)

/**
* Writes an app launch TTI log event. This event should be logged only once per Logger configuration.
* Consecutive calls have no effect.
*
* @param duration The time between a user's intent to launch the app and when the app becomes
* interactive.
*/
fun logAppLaunchTTI(duration: Duration)

/**
* Signals that an operation has started at this point in time. Each operation consists of start
* and end event logs. The start event is emitted immediately upon calling the
Expand All @@ -100,12 +111,14 @@ interface ILogger {

/**
* Records information about an HTTP network request
*
* @param httpRequestInfo information used to enrich the log line
*/
fun log(httpRequestInfo: HttpRequestInfo)

/**
* Records information about an HTTP network response
*
* @param httpResponseInfo information used to enrich the log line
*/
fun log(httpResponseInfo: HttpResponseInfo)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -284,6 +284,10 @@ internal class LoggerImpl(
)
}

override fun logAppLaunchTTI(duration: Duration) {
CaptureJniLibrary.writeAppLaunchTTILog(this.loggerId, duration.toDouble(DurationUnit.SECONDS))
}

override fun startSpan(name: String, level: LogLevel, fields: Map<String, String>?): Span {
return Span(this, name, level, fields)
}
Expand Down
1 change: 1 addition & 0 deletions platform/jvm/jni_symbols.lds
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ Java_io_bitdrift_capture_CaptureJniLibrary_writeResourceUtilizationLog
Java_io_bitdrift_capture_CaptureJniLibrary_writeSDKConfiguredLog
Java_io_bitdrift_capture_CaptureJniLibrary_shouldWriteAppUpdateLog
Java_io_bitdrift_capture_CaptureJniLibrary_writeAppUpdateLog
Java_io_bitdrift_capture_CaptureJniLibrary_writeAppLaunchTTILog
Java_io_bitdrift_capture_CaptureJniLibrary_flush
Java_io_bitdrift_capture_CaptureJniLibrary_debugDebug
Java_io_bitdrift_capture_CaptureJniLibrary_debugError
Expand Down
19 changes: 19 additions & 0 deletions platform/jvm/src/jni.rs
Original file line number Diff line number Diff line change
Expand Up @@ -995,6 +995,25 @@ pub extern "system" fn Java_io_bitdrift_capture_CaptureJniLibrary_writeAppUpdate
);
}

#[no_mangle]
pub extern "system" fn Java_io_bitdrift_capture_CaptureJniLibrary_writeAppLaunchTTILog(
_env: JNIEnv<'_>,
_class: JClass<'_>,
logger_id: jlong,
duration_s: f64,
) {
bd_client_common::error::with_handle_unexpected(
|| -> anyhow::Result<()> {
let logger = unsafe { LoggerId::from_raw(logger_id) };
logger.log_app_launch_tti(Duration::seconds_f64(duration_s));

Ok(())
},
"jni write app launch TTI log",
);
}


#[no_mangle]
pub extern "system" fn Java_io_bitdrift_capture_CaptureJniLibrary_flush(
_env: JNIEnv<'_>,
Expand Down
1 change: 1 addition & 0 deletions platform/shared/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ bd-log-primitives.workspace = true
bd-logger.workspace = true
bd-runtime.workspace = true
bd-session.workspace = true
log.workspace = true
parking_lot.workspace = true
regex.workspace = true
time.workspace = true
Expand Down
37 changes: 37 additions & 0 deletions platform/shared/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,9 @@ pub mod error;
pub mod metadata;

use bd_client_common::error::handle_unexpected;
use bd_logger::{log_level, AnnotatedLogField, LogField, LogFieldKind, LogType};
use bd_runtime::runtime::Snapshot;
use parking_lot::Once;
use std::future::Future;
use std::ops::Deref;
use std::pin::Pin;
Expand Down Expand Up @@ -92,6 +94,7 @@ pub struct LoggerHolder {
logger: bd_logger::Logger,
handle: bd_logger::LoggerHandle,
future: parking_lot::Mutex<Option<LoggerFuture>>,
app_launch_tti_log: Once,
}

impl Deref for LoggerHolder {
Expand All @@ -109,6 +112,7 @@ impl LoggerHolder {
logger,
handle,
future: parking_lot::Mutex::new(Some(future)),
app_launch_tti_log: Once::new(),
}
}

Expand Down Expand Up @@ -158,6 +162,39 @@ impl LoggerHolder {
holder.shutdown(false);
drop(holder);
}

/// Logs an out-of-the-box app launch TTI log event. The method should be called only once.
/// Consecutive calls have not effect.
pub fn log_app_launch_tti(&self, duration: time::Duration) {
self.app_launch_tti_log.call_once(|| {
Copy link
Contributor

@murki murki Aug 29, 2024

Choose a reason for hiding this comment

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

I'm just learning about this primitive and their docs say

This method will block the calling thread if another initialization routine is currently running.

which seems to be aimed to help with

It is also guaranteed that any memory writes performed by the executed closure can be reliably observed by other threads at this point

This sounds like an overkill to me since there are no shared resources that we'd like to guard, but maybe I'm misunderstanding something

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This method will block the calling thread if another initialization routine is currently running.

yes, makes sense. Basically there is a lock in here to guarantee that the critical path is run only once. I do not think that it's a problem, we use locks here and there.

This sounds like an overkill to me since there are no shared resources that we'd like to guard, but maybe I'm misunderstanding something

I think it's fine, we use it in similar cases in other places in code. We want to protect ourselves from cases where a user wants to log app launch TTI multiple times, with this method we can implement it with a minimal amount of effort + it protects us from cases where a user have multiple threads that try to log app launch TTI at the same time (yes, it will most likely not happen in real life scenarios but since we get this protection almost fore free it's nice to have)

Copy link
Contributor

Choose a reason for hiding this comment

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

sg

let duration_ms = duration.as_seconds_f64() * 1_000f64;
if duration_ms < 0.0 {
log::warn!(
"dropping app launch TTI log: reported TTI is negative: {}",
duration_ms
);
return;
}

let fields = vec![AnnotatedLogField {
field: LogField {
key: "_duration_ms".into(),
value: duration_ms.to_string().into(),
},
kind: LogFieldKind::Ootb,
}];

self.log(
log_level::INFO,
LogType::Lifecycle,
"AppLaunchTTI".into(),
Copy link
Contributor

Choose a reason for hiding this comment

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

It could be argued that this value should be just a field in the existing app launch event, but I see how exposing it in our public api would make that complicated, so I guess this will have to do for now

Copy link
Contributor Author

Choose a reason for hiding this comment

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

yea, making it a part of existing TTI would be tricky. Also, I think that they may diverge in the past: app launch is app launch as defined by the system while app launch TTI may be time to interaction to the first time a user touches a screen (depending on what we mean by TTI) and having them combined then would be tricky. I agree tho, we can cross this bridge when we get there

fields,
vec![],
None,
false,
);
});
}
Copy link
Contributor

@murki murki Aug 29, 2024

Choose a reason for hiding this comment

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

kudos for not putting this logic in shared-core 🙌
so much easier to review and make changes if needed

}

impl<'a> From<LoggerId<'a>> for i64 {
Expand Down
11 changes: 11 additions & 0 deletions platform/swift/source/Capture.swift
Original file line number Diff line number Diff line change
Expand Up @@ -261,6 +261,17 @@ extension Logger {
)
}

// MARK: - Predefined Logs

/// Writes an app launch TTI log event. This event should be logged only once per Logger configuration.
/// Consecutive calls have no effect.
///
/// - parameter duration: The time between a user's intent to launch the app and when the app becomes
/// interactive.
public static func logAppLaunchTTI(_ duration: TimeInterval) {
Self.getShared()?.logAppLaunchTTI(duration)
}

// MARK: - Network Activity Logging

/// Logs information about a network request.
Expand Down
17 changes: 15 additions & 2 deletions platform/swift/source/CaptureRustBridge.h
Original file line number Diff line number Diff line change
Expand Up @@ -137,14 +137,27 @@ bool capture_should_write_app_update_log(
* @param app_version the version of the app.
* @param build_number the app build number.
* @param app_install_size_bytes the size of the app in bytes.
* @param duration_ms the duration of time the preparation of the log took.
* @param duration_s the duration of time the preparation of the log took.
*/
void capture_write_app_update_log(
logger_id logger_id,
NSString *app_version,
NSString *build_number,
uint64_t app_install_size_bytes,
double duration_ms
double duration_s
);

/*
* Writes an app launch TTI log. The method should be called only once per logger Id. Consecutive calls
* have no effect.
*
* @param loggerId the ID of the logger to write to.
* @param duration_s the duration of time between a user's intent to launch an app and the point in time
* when the app became interactive.
*/
void capture_write_app_launch_tti_log(
logger_id logger_id,
double duration_s
);

/*
Expand Down
4 changes: 4 additions & 0 deletions platform/swift/source/CoreLogger.swift
Original file line number Diff line number Diff line change
Expand Up @@ -120,6 +120,10 @@ extension CoreLogger: CoreLogging {
)
}

func logAppLaunchTTI(duration: TimeInterval) {
self.underlyingLogger.logAppLaunchTTI(duration: duration)
}

func startNewSession() {
self.underlyingLogger.startNewSession()
}
Expand Down
7 changes: 7 additions & 0 deletions platform/swift/source/CoreLogging.swift
Original file line number Diff line number Diff line change
Expand Up @@ -89,6 +89,13 @@ protocol CoreLogging: AnyObject {
duration: TimeInterval
)

/// Writes an app launch TTI log event. This event should be logged only once per Logger configuration.
/// Consecutive calls have no effect.
///
/// - parameter duration: The time between a user's intent to launch the app and when the app becomes
/// interactive.
func logAppLaunchTTI(duration: TimeInterval)

/// Stars new session using configured session strategy.
func startNewSession()

Expand Down
4 changes: 4 additions & 0 deletions platform/swift/source/Logger.swift
Original file line number Diff line number Diff line change
Expand Up @@ -442,6 +442,10 @@ extension Logger: Logging {
self.deviceCodeController.createTemporaryDeviceCode(deviceID: self.deviceID, completion: completion)
}

public func logAppLaunchTTI(_ duration: TimeInterval) {
self.underlyingLogger.logAppLaunchTTI(duration)
}

public func startSpan(
name: String,
level: LogLevel,
Expand Down
4 changes: 4 additions & 0 deletions platform/swift/source/LoggerBridge.swift
Original file line number Diff line number Diff line change
Expand Up @@ -127,6 +127,10 @@ final class LoggerBridge: LoggerBridging {
capture_write_app_update_log(self.loggerID, appVersion, buildNumber, appSizeBytes, duration)
}

func logAppLaunchTTI(duration: TimeInterval) {
capture_write_app_launch_tti_log(self.loggerID, duration)
}

func startNewSession() {
capture_start_new_session(self.loggerID)
}
Expand Down
2 changes: 2 additions & 0 deletions platform/swift/source/LoggerBridging.swift
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,8 @@ protocol LoggerBridging {
duration: TimeInterval
)

func logAppLaunchTTI(duration: TimeInterval)

func start()

func startNewSession()
Expand Down
Loading
Loading