//! Tracing and profiling functions. Error and warning log. use std::borrow::Cow; use std::ffi::{c_char, c_int, c_uint, c_void, CStr, CString}; use std::marker::PhantomData; use std::mem; use std::panic::catch_unwind; use std::ptr; use std::time::Duration; use super::ffi; use crate::{Connection, StatementStatus, MAIN_DB}; /// Set up the process-wide SQLite error logging callback. /// /// # Safety /// /// This function is marked unsafe for two reasons: /// /// * The function is not threadsafe. No other SQLite calls may be made while /// `config_log` is running, and multiple threads may not call `config_log` /// simultaneously. /// * The provided `callback` itself function has two requirements: /// * It must not invoke any SQLite calls. /// * It must be threadsafe if SQLite is used in a multithreaded way. /// /// cf [The Error And Warning Log](http://sqlite.org/errlog.html). #[cfg(not(feature = "loadable_extension"))] pub unsafe fn config_log(callback: Option) -> crate::Result<()> { extern "C" fn log_callback(p_arg: *mut c_void, err: c_int, msg: *const c_char) { let s = unsafe { CStr::from_ptr(msg).to_string_lossy() }; let callback: fn(c_int, &str) = unsafe { mem::transmute(p_arg) }; drop(catch_unwind(|| callback(err, &s))); } let rc = if let Some(f) = callback { ffi::sqlite3_config( ffi::SQLITE_CONFIG_LOG, log_callback as extern "C" fn(_, _, _), f as *mut c_void, ) } else { let nullptr: *mut c_void = ptr::null_mut(); ffi::sqlite3_config(ffi::SQLITE_CONFIG_LOG, nullptr, nullptr) }; if rc == ffi::SQLITE_OK { Ok(()) } else { Err(crate::error::error_from_sqlite_code(rc, None)) } } /// Write a message into the error log established by /// `config_log`. #[inline] pub fn log(err_code: c_int, msg: &str) { let msg = CString::new(msg).expect("SQLite log messages cannot contain embedded zeroes"); unsafe { ffi::sqlite3_log(err_code, b"%s\0" as *const _ as *const c_char, msg.as_ptr()); } } bitflags::bitflags! { /// Trace event codes #[derive(Clone, Copy, Debug, Eq, PartialEq)] #[non_exhaustive] #[repr(C)] pub struct TraceEventCodes: c_uint { /// when a prepared statement first begins running and possibly at other times during the execution /// of the prepared statement, such as at the start of each trigger subprogram const SQLITE_TRACE_STMT = ffi::SQLITE_TRACE_STMT; /// when the statement finishes const SQLITE_TRACE_PROFILE = ffi::SQLITE_TRACE_PROFILE; /// whenever a prepared statement generates a single row of result const SQLITE_TRACE_ROW = ffi::SQLITE_TRACE_ROW; /// when a database connection closes const SQLITE_TRACE_CLOSE = ffi::SQLITE_TRACE_CLOSE; } } /// Trace event #[non_exhaustive] pub enum TraceEvent<'s> { /// when a prepared statement first begins running and possibly at other times during the execution /// of the prepared statement, such as at the start of each trigger subprogram Stmt(StmtRef<'s>, &'s str), /// when the statement finishes Profile(StmtRef<'s>, Duration), /// whenever a prepared statement generates a single row of result Row(StmtRef<'s>), /// when a database connection closes Close(ConnRef<'s>), } /// Statement reference pub struct StmtRef<'s> { ptr: *mut ffi::sqlite3_stmt, phantom: PhantomData<&'s ()>, } impl StmtRef<'_> { fn new(ptr: *mut ffi::sqlite3_stmt) -> Self { StmtRef { ptr, phantom: PhantomData, } } /// SQL text pub fn sql(&self) -> Cow<'_, str> { let sql = unsafe { ffi::sqlite3_sql(self.ptr) }; if sql.is_null() { return Cow::default(); } // Safety: sql is a valid pointer to a cstr returned by sqlite3 unsafe { CStr::from_ptr(sql).to_string_lossy() } } /// Expanded SQL text pub fn expanded_sql(&self) -> Option { unsafe { crate::raw_statement::expanded_sql(self.ptr).map(|s| s.to_string_lossy().to_string()) } } /// Get the value for one of the status counters for this statement. pub fn get_status(&self, status: StatementStatus) -> i32 { unsafe { crate::raw_statement::stmt_status(self.ptr, status, false) } } } /// Connection reference pub struct ConnRef<'s> { ptr: *mut ffi::sqlite3, phantom: PhantomData<&'s ()>, } impl ConnRef<'_> { /// Test for auto-commit mode. pub fn is_autocommit(&self) -> bool { unsafe { crate::inner_connection::get_autocommit(self.ptr) } } /// the path to the database file, if one exists and is known. pub fn db_filename(&self) -> Option<&str> { unsafe { crate::inner_connection::db_filename(self.phantom, self.ptr, MAIN_DB) } } } impl Connection { /// Register or clear a callback function that can be /// used for tracing the execution of SQL statements. /// /// Prepared statement placeholders are replaced/logged with their assigned /// values. There can only be a single tracer defined for each database /// connection. Setting a new tracer clears the old one. #[cfg(not(all(target_family = "wasm", target_os = "unknown")))] #[deprecated(since = "0.33.0", note = "use trace_v2 instead")] pub fn trace(&mut self, trace_fn: Option) { unsafe extern "C" fn trace_callback(p_arg: *mut c_void, z_sql: *const c_char) { let trace_fn: fn(&str) = mem::transmute(p_arg); let s = CStr::from_ptr(z_sql).to_string_lossy(); drop(catch_unwind(|| trace_fn(&s))); } let c = self.db.borrow_mut(); unsafe { ffi::sqlite3_trace( c.db(), trace_fn.as_ref().map(|_| trace_callback as _), trace_fn.map_or_else(ptr::null_mut, |f| f as *mut c_void), ); } } /// Register or clear a callback function that can be /// used for profiling the execution of SQL statements. /// /// There can only be a single profiler defined for each database /// connection. Setting a new profiler clears the old one. #[cfg(not(all(target_family = "wasm", target_os = "unknown")))] #[deprecated(since = "0.33.0", note = "use trace_v2 instead")] pub fn profile(&mut self, profile_fn: Option) { unsafe extern "C" fn profile_callback( p_arg: *mut c_void, z_sql: *const c_char, nanoseconds: u64, ) { let profile_fn: fn(&str, Duration) = mem::transmute(p_arg); let s = CStr::from_ptr(z_sql).to_string_lossy(); let duration = Duration::from_nanos(nanoseconds); drop(catch_unwind(|| profile_fn(&s, duration))); } let c = self.db.borrow_mut(); unsafe { ffi::sqlite3_profile( c.db(), profile_fn.as_ref().map(|_| profile_callback as _), profile_fn.map_or_else(ptr::null_mut, |f| f as *mut c_void), ); } } /// Register or clear a trace callback function pub fn trace_v2(&self, mask: TraceEventCodes, trace_fn: Option)>) { unsafe extern "C" fn trace_callback( evt: c_uint, ctx: *mut c_void, p: *mut c_void, x: *mut c_void, ) -> c_int { let trace_fn: fn(TraceEvent<'_>) = mem::transmute(ctx); drop(catch_unwind(|| match evt { ffi::SQLITE_TRACE_STMT => { let str = CStr::from_ptr(x as *const c_char).to_string_lossy(); trace_fn(TraceEvent::Stmt( StmtRef::new(p as *mut ffi::sqlite3_stmt), &str, )) } ffi::SQLITE_TRACE_PROFILE => { let ns = *(x as *const i64); trace_fn(TraceEvent::Profile( StmtRef::new(p as *mut ffi::sqlite3_stmt), Duration::from_nanos(u64::try_from(ns).unwrap_or_default()), )) } ffi::SQLITE_TRACE_ROW => { trace_fn(TraceEvent::Row(StmtRef::new(p as *mut ffi::sqlite3_stmt))) } ffi::SQLITE_TRACE_CLOSE => trace_fn(TraceEvent::Close(ConnRef { ptr: p as *mut ffi::sqlite3, phantom: PhantomData, })), _ => {} })); // The integer return value from the callback is currently ignored, though this may change in future releases. // Callback implementations should return zero to ensure future compatibility. ffi::SQLITE_OK } let c = self.db.borrow_mut(); unsafe { ffi::sqlite3_trace_v2( c.db(), mask.bits(), trace_fn.as_ref().map(|_| trace_callback as _), trace_fn.map_or_else(ptr::null_mut, |f| f as *mut c_void), ); } } } #[cfg(test)] mod test { #[cfg(all(target_family = "wasm", target_os = "unknown"))] use wasm_bindgen_test::wasm_bindgen_test as test; #[cfg(not(all(target_family = "wasm", target_os = "unknown")))] use std::sync::{LazyLock, Mutex}; use std::time::Duration; use super::{TraceEvent, TraceEventCodes}; use crate::{Connection, Result, MAIN_DB}; #[cfg(not(all(target_family = "wasm", target_os = "unknown")))] #[test] #[allow(deprecated)] fn test_trace() -> Result<()> { static TRACED_STMTS: LazyLock>> = LazyLock::new(|| Mutex::new(Vec::new())); fn tracer(s: &str) { let mut traced_stmts = TRACED_STMTS.lock().unwrap(); traced_stmts.push(s.to_owned()); } let mut db = Connection::open_in_memory()?; db.trace(Some(tracer)); { let _ = db.query_row("SELECT ?1", [1i32], |_| Ok(())); let _ = db.query_row("SELECT ?1", ["hello"], |_| Ok(())); } db.trace(None); { let _ = db.query_row("SELECT ?1", [2i32], |_| Ok(())); let _ = db.query_row("SELECT ?1", ["goodbye"], |_| Ok(())); } let traced_stmts = TRACED_STMTS.lock().unwrap(); assert_eq!(traced_stmts.len(), 2); assert_eq!(traced_stmts[0], "SELECT 1"); assert_eq!(traced_stmts[1], "SELECT 'hello'"); Ok(()) } #[cfg(not(all(target_family = "wasm", target_os = "unknown")))] #[test] #[allow(deprecated)] fn test_profile() -> Result<()> { static PROFILED: LazyLock>> = LazyLock::new(|| Mutex::new(Vec::new())); fn profiler(s: &str, d: Duration) { let mut profiled = PROFILED.lock().unwrap(); profiled.push((s.to_owned(), d)); } let mut db = Connection::open_in_memory()?; db.profile(Some(profiler)); db.execute_batch("PRAGMA application_id = 1")?; db.profile(None); db.execute_batch("PRAGMA application_id = 2")?; let profiled = PROFILED.lock().unwrap(); assert_eq!(profiled.len(), 1); assert_eq!(profiled[0].0, "PRAGMA application_id = 1"); Ok(()) } #[test] pub fn trace_v2() -> Result<()> { use std::borrow::Borrow; use std::cmp::Ordering; let db = Connection::open_in_memory()?; db.trace_v2( TraceEventCodes::all(), Some(|e| match e { TraceEvent::Stmt(s, sql) => { assert_eq!(s.sql(), sql); } TraceEvent::Profile(s, d) => { assert_eq!(s.get_status(crate::StatementStatus::Sort), 0); #[cfg(not(all(target_family = "wasm", target_os = "unknown")))] assert_eq!(d.cmp(&Duration::ZERO), Ordering::Greater); // Timers on the web are not very accurate #[cfg(all(target_family = "wasm", target_os = "unknown"))] assert!(matches!( d.cmp(&Duration::ZERO), Ordering::Equal | Ordering::Greater )); } TraceEvent::Row(s) => { assert_eq!(s.expanded_sql().as_deref(), Some(s.sql().borrow())); } TraceEvent::Close(db) => { assert!(db.is_autocommit()); // https://www.sqlite.org/c3ref/db_filename.html // if database N is a temporary or in-memory database, // then this function will return either a NULL pointer or an empty string. assert!(db.db_filename().is_none_or(|s| s.is_empty())); } }), ); db.one_column::("PRAGMA user_version", [])?; drop(db); let db = Connection::open_in_memory()?; db.trace_v2(TraceEventCodes::empty(), None); Ok(()) } #[test] #[cfg(feature = "blob")] pub fn null_sql() -> Result<()> { let db = Connection::open_in_memory()?; let sql = "CREATE TABLE test (content BLOB); INSERT INTO test VALUES (ZEROBLOB(10));"; db.execute_batch(sql)?; let rowid = db.last_insert_rowid(); db.trace_v2( TraceEventCodes::SQLITE_TRACE_ROW, Some(|e| { if let TraceEvent::Row(s) = e { assert_eq!(s.sql(), ""); } }), ); db.blob_open(MAIN_DB, c"test", c"content", rowid, true)?; Ok(()) } }