Merge pull request #86 from jgallagher/gwenn-trace_extension

Add Rust interface to SQLite's logging, tracing, and profiling hooks

Cargo.toml

@@ -14,6 +14,7 @@ name = "rusqlite"
 
 [features]
 load_extension = ["libsqlite3-sys/load_extension"]
+trace = []
 
 [dependencies]
 time = "~0.1.0"
@@ -22,7 +23,12 @@ libc = "~0.2"
 
 [dev-dependencies]
 tempdir = "~0.3.4"
+lazy_static = "~0.1"
 
 [dependencies.libsqlite3-sys]
 path = "libsqlite3-sys"
 version = "0.2.0"
+
+[[test]]
+name = "config_log"
+harness = false

Changelog.md

@@ -1,5 +1,6 @@
-# Version UPCOMDING (TBD)
+# Version UPCOMING (TBD)
 
+* Adds `trace` feature that allows the use of SQLite's logging, tracing, and profiling hooks.
 * Slight change to the closure types passed to `query_map` and `query_and_then`:
     * Remove the `'static` requirement on the closure's output type.
     * Give the closure a `&SqliteRow` instead of a `SqliteRow`.

libsqlite3-sys/src/lib.rs

@@ -92,3 +92,5 @@ pub fn code_to_str(code: c_int) -> &'static str {
         _                => "Unknown error code",
     }
 }
+
+pub const SQLITE_CONFIG_LOG  : c_int = 16;

src/lib.rs

@@ -53,6 +53,7 @@
 extern crate libc;
 extern crate libsqlite3_sys as ffi;
 #[macro_use] extern crate bitflags;
+#[cfg(test)] #[macro_use] extern crate lazy_static;
 
 use std::default::Default;
 use std::convert;
@@ -80,6 +81,7 @@ pub use transaction::{SqliteTransactionBehavior,
 pub mod types;
 mod transaction;
 #[cfg(feature = "load_extension")] mod load_extension_guard;
+#[cfg(feature = "trace")] pub mod trace;
 
 /// A typedef of the result returned by many methods.
 pub type SqliteResult<T> = Result<T, SqliteError>;
@@ -141,15 +143,6 @@ fn path_to_cstring(p: &Path) -> SqliteResult<CString> {
 }
 
 /// A connection to a SQLite database.
-///
-/// ## Warning
-///
-/// Note that despite the fact that most `SqliteConnection` methods take an immutable reference to
-/// `self`, `SqliteConnection` is NOT threadsafe, and using it from multiple threads may result in
-/// runtime panics or data races. The SQLite connection handle has at least two pieces of internal
-/// state (the last insertion ID and the last error message) that rusqlite uses, but wrapping these
-/// APIs in a safe way from Rust would be too restrictive (for example, you would not be able to
-/// prepare multiple statements at the same time).
 pub struct SqliteConnection {
     db: RefCell<InnerSqliteConnection>,
     path: Option<PathBuf>,

src/trace.rs

@@ -0,0 +1,162 @@
+//! Tracing and profiling functions. Error and warning log.
+
+use libc::{c_char, c_int, c_void};
+use std::ffi::{CStr, CString};
+use std::mem;
+use std::ptr;
+use std::str;
+use std::time::Duration;
+
+use super::ffi;
+use {SqliteError, SqliteResult, SqliteConnection};
+
+/// Set up the process-wide SQLite error logging callback.
+/// 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).
+pub unsafe fn config_log(callback: Option<fn(c_int, &str)>) -> SqliteResult<()> {
+    extern "C" fn log_callback(p_arg: *mut c_void, err: c_int, msg: *const c_char) {
+        let c_slice = unsafe { CStr::from_ptr(msg).to_bytes() };
+        let callback: fn(c_int, &str) = unsafe { mem::transmute(p_arg) };
+
+        if let Ok(s) = str::from_utf8(c_slice) {
+            callback(err, s);
+        }
+    }
+
+    let rc = match callback {
+        Some(f) => {
+            let p_arg: *mut c_void = mem::transmute(f);
+            ffi::sqlite3_config(ffi::SQLITE_CONFIG_LOG, Some(log_callback), p_arg)
+        },
+        None => {
+            let nullptr: *mut c_void = ptr::null_mut();
+            ffi::sqlite3_config(ffi::SQLITE_CONFIG_LOG, nullptr, nullptr)
+        }
+    };
+
+    if rc != ffi::SQLITE_OK {
+        return Err(SqliteError{ code: rc, message: "sqlite3_config(SQLITE_CONFIG_LOG, ...)".to_string() });
+    }
+
+    Ok(())
+}
+
+/// Write a message into the error log established by `config_log`.
+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, msg.as_ptr());
+    }
+}
+
+impl SqliteConnection {
+    /// 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.
+    pub fn trace(&mut self, trace_fn: Option<fn(&str)>) {
+        extern "C" fn trace_callback (p_arg: *mut c_void, z_sql: *const c_char) {
+            let trace_fn: fn(&str) = unsafe { mem::transmute(p_arg) };
+            let c_slice = unsafe { CStr::from_ptr(z_sql).to_bytes() };
+            if let Ok(s) = str::from_utf8(c_slice) {
+                trace_fn(s);
+            }
+        }
+
+        let c = self.db.borrow_mut();
+        match trace_fn {
+            Some(f) => unsafe { ffi::sqlite3_trace(c.db(), Some(trace_callback), mem::transmute(f)); },
+            None    => unsafe { ffi::sqlite3_trace(c.db(), None, ptr::null_mut()); },
+        }
+    }
+
+    /// 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.
+    pub fn profile(&mut self, profile_fn: Option<fn(&str, Duration)>) {
+        extern "C" fn profile_callback(p_arg: *mut c_void, z_sql: *const c_char, nanoseconds: u64) {
+            let profile_fn: fn(&str, Duration) = unsafe { mem::transmute(p_arg) };
+            let c_slice = unsafe { CStr::from_ptr(z_sql).to_bytes() };
+            if let Ok(s) = str::from_utf8(c_slice) {
+                const NANOS_PER_SEC: u64 = 1_000_000_000;
+
+                let duration = Duration::new(nanoseconds / NANOS_PER_SEC,
+                                             (nanoseconds % NANOS_PER_SEC) as u32);
+                profile_fn(s, duration);
+            }
+        }
+
+        let c = self.db.borrow_mut();
+        match profile_fn {
+            Some(f) => unsafe { ffi::sqlite3_profile(c.db(), Some(profile_callback), mem::transmute(f)) },
+            None    => unsafe { ffi::sqlite3_profile(c.db(), None, ptr::null_mut()) },
+        };
+    }
+}
+
+#[cfg(test)]
+mod test {
+    use std::sync::Mutex;
+    use std::time::Duration;
+
+    use SqliteConnection;
+
+    #[test]
+    fn test_trace() {
+        lazy_static! {
+            static ref TRACED_STMTS: Mutex<Vec<String>> = 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 = SqliteConnection::open_in_memory().unwrap();
+        db.trace(Some(tracer));
+        {
+            let _ = db.query_row("SELECT ?", &[&1i32], |_| {});
+            let _ = db.query_row("SELECT ?", &[&"hello"], |_| {});
+        }
+        db.trace(None);
+        {
+            let _ = db.query_row("SELECT ?", &[&2i32], |_| {});
+            let _ = db.query_row("SELECT ?", &[&"goodbye"], |_| {});
+        }
+
+        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'");
+    }
+
+    #[test]
+    fn test_profile() {
+        lazy_static! {
+            static ref PROFILED: Mutex<Vec<(String, Duration)>> = 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 = SqliteConnection::open_in_memory().unwrap();
+        db.profile(Some(profiler));
+        db.execute_batch("PRAGMA application_id = 1").unwrap();
+        db.profile(None);
+        db.execute_batch("PRAGMA application_id = 2").unwrap();
+
+        let profiled = PROFILED.lock().unwrap();
+        assert_eq!(profiled.len(), 1);
+        assert_eq!(profiled[0].0, "PRAGMA application_id = 1");
+    }
+}

tests/config_log.rs

@@ -0,0 +1,36 @@
+//! This file contains unit tests for rusqlite::trace::config_log. This function affects
+//! SQLite process-wide and so is not safe to run as a normal #[test] in the library.
+
+#[macro_use] extern crate lazy_static;
+extern crate libc;
+extern crate rusqlite;
+
+#[cfg(feature = "trace")]
+fn main() {
+    use libc::c_int;
+    use std::sync::Mutex;
+
+    lazy_static! {
+        static ref LOGS_RECEIVED: Mutex<Vec<(c_int, String)>> = Mutex::new(Vec::new());
+    }
+
+    fn log_handler(err: c_int, message: &str) {
+        let mut logs_received = LOGS_RECEIVED.lock().unwrap();
+        logs_received.push((err, message.to_owned()));
+    }
+
+    use rusqlite::trace;
+
+    unsafe { trace::config_log(Some(log_handler)) }.unwrap();
+    trace::log(10, "First message from rusqlite");
+    unsafe { trace::config_log(None) }.unwrap();
+    trace::log(11, "Second message from rusqlite");
+
+    let logs_received = LOGS_RECEIVED.lock().unwrap();
+    assert_eq!(logs_received.len(), 1);
+    assert_eq!(logs_received[0].0, 10);
+    assert_eq!(logs_received[0].1, "First message from rusqlite");
+}
+
+#[cfg(not(feature = "trace"))]
+fn main() {}