log: add log on unclean stops

Author: Ariel Ben-Yehuda

examples/simple/main.rs

@@ -67,6 +67,9 @@ struct Args {
     /// Use the spawn_thread API instead of the Tokio API (does not demonstrate stopping)
     #[arg(long)]
     spawn_into_thread: bool,
+    /// Whether to not do a clean stop. Used to test unclean stops.
+    #[arg(long)]
+    no_clean_stop: bool,
 }
 
 impl Args {
@@ -155,13 +158,21 @@ async fn main_internal(args: Args) -> Result<(), anyhow::Error> {
         });
         run_slow(&args).await;
     } else {
-        tracing::info!("starting profiler");
-        let handle = profiler.spawn_controllable()?;
-        tracing::info!("profiler started");
+        if args.no_clean_stop {
+            tracing::info!("starting profiler");
+            profiler.spawn()?;
+            tracing::info!("profiler started");
 
-        run_slow(&args).await;
+            run_slow(&args).await;
+        } else {
+            tracing::info!("starting profiler");
+            let handle = profiler.spawn_controllable()?;
+            tracing::info!("profiler started");
+
+            run_slow(&args).await;
 
-        handle.stop().await;
+            handle.stop().await;
+        }
     }
 
     Ok(())

src/profiler.rs

@@ -10,7 +10,7 @@ use crate::{
 };
 use std::{
     fs::File,
-    io,
+    io, mem,
     path::{Path, PathBuf},
     time::{Duration, SystemTime, SystemTimeError, UNIX_EPOCH},
 };
@@ -1068,6 +1068,18 @@ impl Profiler {
     }
 
     fn spawn_inner<E: ProfilerEngine>(self, asprof: E) -> Result<RunningProfiler, SpawnError> {
+        struct LogOnDrop;
+        impl Drop for LogOnDrop {
+            fn drop(&mut self) {
+                // Tokio will call destructors during runtime shutdown. Have something that will
+                // emit a log in that case
+                tracing::info!(
+                    "unable to upload the last jfr due to Tokio runtime shutdown. \
+                Add a call to `RunningProfiler::stop` to wait for jfr upload to finish."
+                );
+            }
+        }
+
         // Initialize async profiler - needs to be done once.
         E::init_async_profiler()?;
         tracing::info!("successfully initialized async profiler.");
@@ -1089,6 +1101,7 @@ impl Profiler {
             let mut agent_metadata = self.agent_metadata;
             let mut done = false;
 
+            let guard = LogOnDrop;
             while !done {
                 // Wait until a timer or exit event
                 tokio::select! {
@@ -1128,6 +1141,7 @@ impl Profiler {
                 }
             }
 
+            mem::forget(guard);
             tracing::info!("profiling task finished");
         });
 

tests/integration.sh

@@ -12,6 +12,14 @@ dir="profiles"
 mkdir -p $dir
 rm -f $dir/*.jfr
 
+# test the "unable to uploqad the last jfr" logic
+rm -rf $dir/short
+mkdir $dir/short
+./simple --local $dir/short --duration 1s --reporting-interval 10s --no-clean-stop 2>$dir/short/log
+cat $dir/short/log
+grep "unable to upload the last jfr" $dir/short/log
+rm -rf $dir/short
+
 # Pass --worker-threads 16 to make the test much less flaky since there is always some worker thread running
 ./simple --local $dir --duration 30s --reporting-interval 10s --worker-threads 16 --native-mem 4096