Add ability to automatically log query plans. (#583)

* Add support for automatically logging query plans to stdout or to a file
* Change sql api calls around so more of them have their query plans logged
* Make the log_query_plans feature explicit in logins/places
* Log query plans as a fancy tree, same as sqlite with `.eqp` on
* Document query plan feature of sql-support
* Use cached queries in matcher.rs

components/logins/Cargo.toml

@@ -6,6 +6,7 @@ authors = ["Thom Chiovoloni <tchiovoloni@mozilla.com>"]
 
 [features]
 ffi = ["ffi-support"]
+log_query_plans = ["sql-support/log_query_plans"]
 default = []
 
 [dependencies]

components/places/Cargo.toml

@@ -6,6 +6,7 @@ authors = []
 
 [features]
 ffi = ["ffi-support"]
+log_query_plans = ["sql-support/log_query_plans"]
 default = []
 
 [dependencies]

components/places/src/api/matcher.rs

@@ -4,10 +4,10 @@
 
 use crate::db::PlacesDb;
 use crate::error::Result;
-use serde_derive::*;
-use url::Url;
-
 pub use crate::match_impl::{MatchBehavior, SearchBehavior};
+use serde_derive::*;
+use sql_support::ConnExt;
+use url::Url;
 
 #[derive(Debug, Clone)]
 pub struct SearchParams {
@@ -78,20 +78,18 @@ fn match_with_limit(matchers: &[&dyn Matcher], max_results: u32) -> Result<(Vec<
 /// and chosen URL for subsequent matches.
 pub fn accept_result(conn: &PlacesDb, result: &SearchResult) -> Result<()> {
     // See `nsNavHistory::AutoCompleteFeedback`.
-    let mut stmt = conn.db.prepare(
+    conn.execute_named(
-        "
+        "INSERT OR REPLACE INTO moz_inputhistory(place_id, input, use_count)
-        INSERT OR REPLACE INTO moz_inputhistory(place_id, input, use_count)
+         SELECT h.id, IFNULL(i.input, :input_text), IFNULL(i.use_count, 0) * .9 + 1
-        SELECT h.id, IFNULL(i.input, :input_text), IFNULL(i.use_count, 0) * .9 + 1
+         FROM moz_places h
-        FROM moz_places h
+         LEFT JOIN moz_inputhistory i ON i.place_id = h.id AND i.input = :input_text
-        LEFT JOIN moz_inputhistory i ON i.place_id = h.id AND i.input = :input_text
+         WHERE url_hash = hash(:page_url) AND url = :page_url",
-        WHERE url_hash = hash(:page_url) AND url = :page_url
+        &[
-    ",
+            (":input_text", &result.search_string),
+            (":page_url", &result.url.as_str()),
+        ],
     )?;
-    let params: &[(&str, &dyn rusqlite::types::ToSql)] = &[
+
-        (":input_text", &result.search_string),
-        (":page_url", &result.url.as_str()),
-    ];
-    stmt.execute_named(params)?;
     Ok(())
 }
 
@@ -311,95 +309,95 @@ impl<'query, 'conn> OriginOrUrl<'query, 'conn> {
     }
 }
 
+const URL_SQL: &'static str = "
+    SELECT h.url as url,
+            :host || :remainder AS strippedURL,
+            h.frecency as frecency,
+            h.foreign_count > 0 AS bookmarked,
+            h.id as id,
+            :searchString AS searchString
+    FROM moz_places h
+    JOIN moz_origins o ON o.id = h.origin_id
+    WHERE o.rev_host = reverse_host(:host)
+            AND MAX(h.frecency, 0) >= :frecencyThreshold
+            AND h.hidden = 0
+            AND strip_prefix_and_userinfo(h.url) BETWEEN strippedURL AND strippedURL || X'FFFF'
+    UNION ALL
+    SELECT h.url as url,
+            :host || :remainder AS strippedURL,
+            h.frecency as frecency,
+            h.foreign_count > 0 AS bookmarked,
+            h.id as id,
+            :searchString AS searchString
+    FROM moz_places h
+    JOIN moz_origins o ON o.id = h.origin_id
+    WHERE o.rev_host = reverse_host(:host) || 'www.'
+            AND MAX(h.frecency, 0) >= :frecencyThreshold
+            AND h.hidden = 0
+            AND strip_prefix_and_userinfo(h.url) BETWEEN 'www.' || strippedURL AND 'www.' || strippedURL || X'FFFF'
+    ORDER BY h.frecency DESC, h.id DESC
+    LIMIT 1
+";
+const ORIGIN_SQL: &'static str = "
+    SELECT IFNULL(:prefix, prefix) || moz_origins.host || '/' AS url,
+            moz_origins.host || '/' AS displayURL,
+            frecency,
+            bookmarked,
+            id,
+            :searchString AS searchString
+    FROM (
+        SELECT host,
+                TOTAL(frecency) AS host_frecency,
+                (SELECT TOTAL(foreign_count) > 0 FROM moz_places
+                WHERE moz_places.origin_id = moz_origins.id) AS bookmarked
+        FROM moz_origins
+        WHERE host BETWEEN :searchString AND :searchString || X'FFFF'
+        GROUP BY host
+        HAVING host_frecency >= :frecencyThreshold
+        UNION ALL
+        SELECT host,
+                TOTAL(frecency) AS host_frecency,
+                (SELECT TOTAL(foreign_count) > 0 FROM moz_places
+                WHERE moz_places.origin_id = moz_origins.id) AS bookmarked
+        FROM moz_origins
+        WHERE host BETWEEN 'www.' || :searchString AND 'www.' || :searchString || X'FFFF'
+        GROUP BY host
+        HAVING host_frecency >= :frecencyThreshold
+    ) AS grouped_hosts
+    JOIN moz_origins ON moz_origins.host = grouped_hosts.host
+    ORDER BY frecency DESC, id DESC
+    LIMIT 1
+";
+
 impl<'query, 'conn> Matcher for OriginOrUrl<'query, 'conn> {
     fn search(&self, _: u32) -> Result<Vec<SearchResult>> {
-        let mut results = Vec::new();
+        Ok(if looks_like_origin(self.query) {
-        if looks_like_origin(self.query) {
+            self.conn.query_rows_and_then_named_cached(
-            let mut stmt = self.conn.db.prepare(
+                ORIGIN_SQL,
-                "
+                &[
-                SELECT IFNULL(:prefix, prefix) || moz_origins.host || '/' AS url,
+                    (":prefix", &rusqlite::types::Null),
-                       moz_origins.host || '/' AS displayURL,
+                    (":searchString", &self.query),
-                       frecency,
+                    (":frecencyThreshold", &-1i64),
-                       bookmarked,
+                ],
-                       id,
+                SearchResult::from_origin_row,
-                       :searchString AS searchString
+            )?
-                FROM (
-                  SELECT host,
-                         TOTAL(frecency) AS host_frecency,
-                         (SELECT TOTAL(foreign_count) > 0 FROM moz_places
-                          WHERE moz_places.origin_id = moz_origins.id) AS bookmarked
-                  FROM moz_origins
-                  WHERE host BETWEEN :searchString AND :searchString || X'FFFF'
-                  GROUP BY host
-                  HAVING host_frecency >= :frecencyThreshold
-                  UNION ALL
-                  SELECT host,
-                         TOTAL(frecency) AS host_frecency,
-                         (SELECT TOTAL(foreign_count) > 0 FROM moz_places
-                          WHERE moz_places.origin_id = moz_origins.id) AS bookmarked
-                  FROM moz_origins
-                  WHERE host BETWEEN 'www.' || :searchString AND 'www.' || :searchString || X'FFFF'
-                  GROUP BY host
-                  HAVING host_frecency >= :frecencyThreshold
-                ) AS grouped_hosts
-                JOIN moz_origins ON moz_origins.host = grouped_hosts.host
-                ORDER BY frecency DESC, id DESC
-                LIMIT 1
-            ",
-            )?;
-            let params: &[(&str, &dyn rusqlite::types::ToSql)] = &[
-                (":prefix", &rusqlite::types::Null),
-                (":searchString", &self.query),
-                (":frecencyThreshold", &-1i64),
-            ];
-            for result in stmt.query_and_then_named(params, SearchResult::from_origin_row)? {
-                results.push(result?);
-            }
         } else if self.query.contains(|c| c == '/' || c == ':' || c == '?') {
             let (host, remainder) = split_after_host_and_port(self.query);
             let punycode_host = idna::domain_to_ascii(host).ok();
             let host_str = punycode_host.as_ref().map(|s| s.as_str()).unwrap_or(host);
-
+            self.conn.query_rows_and_then_named_cached(
-            let mut stmt = self.conn.db.prepare("
+                URL_SQL,
-                SELECT h.url as url,
+                &[
-                       :host || :remainder AS strippedURL,
+                    (":searchString", &self.query),
-                       h.frecency as frecency,
+                    (":host", &host_str),
-                       h.foreign_count > 0 AS bookmarked,
+                    (":remainder", &remainder),
-                       h.id as id,
+                    (":frecencyThreshold", &-1i64),
-                       :searchString AS searchString
+                ],
-                FROM moz_places h
+                SearchResult::from_url_row,
-                JOIN moz_origins o ON o.id = h.origin_id
+            )?
-                WHERE o.rev_host = reverse_host(:host)
+        } else {
-                      AND MAX(h.frecency, 0) >= :frecencyThreshold
+            vec![]
-                      AND h.hidden = 0
+        })
-                      AND strip_prefix_and_userinfo(h.url) BETWEEN strippedURL AND strippedURL || X'FFFF'
-                UNION ALL
-                SELECT h.url as url,
-                       :host || :remainder AS strippedURL,
-                       h.frecency as frecency,
-                       h.foreign_count > 0 AS bookmarked,
-                       h.id as id,
-                       :searchString AS searchString
-                FROM moz_places h
-                JOIN moz_origins o ON o.id = h.origin_id
-                WHERE o.rev_host = reverse_host(:host) || 'www.'
-                      AND MAX(h.frecency, 0) >= :frecencyThreshold
-                      AND h.hidden = 0
-                      AND strip_prefix_and_userinfo(h.url) BETWEEN 'www.' || strippedURL AND 'www.' || strippedURL || X'FFFF'
-                ORDER BY h.frecency DESC, h.id DESC
-                LIMIT 1
-            ")?;
-            let params: &[(&str, &dyn rusqlite::types::ToSql)] = &[
-                (":searchString", &self.query),
-                (":host", &host_str),
-                (":remainder", &remainder),
-                (":frecencyThreshold", &-1i64),
-            ];
-            for result in stmt.query_and_then_named(params, SearchResult::from_url_row)? {
-                results.push(result?);
-            }
-        }
-        Ok(results)
     }
 }
 
@@ -437,7 +435,7 @@ impl<'query, 'conn> Adaptive<'query, 'conn> {
 
 impl<'query, 'conn> Matcher for Adaptive<'query, 'conn> {
     fn search(&self, max_results: u32) -> Result<Vec<SearchResult>> {
-        let mut stmt = self.conn.db.prepare(
+        Ok(self.conn.query_rows_and_then_named_cached(
             "
             SELECT h.url as url,
                    h.title as title,
@@ -468,20 +466,15 @@ impl<'query, 'conn> Matcher for Adaptive<'query, 'conn> {
                                      visit_count, h.typed, bookmarked,
                                      NULL, :matchBehavior, :searchBehavior)
             ORDER BY rank DESC, h.frecency DESC
-            LIMIT :maxResults
+            LIMIT :maxResults",
-        ",
+            &[
-        )?;
+                (":searchString", &self.query),
-        let params: &[(&str, &dyn rusqlite::types::ToSql)] = &[
+                (":matchBehavior", &self.match_behavior),
-            (":searchString", &self.query),
+                (":searchBehavior", &self.search_behavior),
-            (":matchBehavior", &self.match_behavior),
+                (":maxResults", &max_results),
-            (":searchBehavior", &self.search_behavior),
+            ],
-            (":maxResults", &max_results),
+            SearchResult::from_adaptive_row,
-        ];
+        )?)
-        let mut results = Vec::new();
-        for result in stmt.query_and_then_named(params, SearchResult::from_adaptive_row)? {
-            results.push(result?);
-        }
-        Ok(results)
     }
 }
 
@@ -519,7 +512,7 @@ impl<'query, 'conn> Suggestions<'query, 'conn> {
 
 impl<'query, 'conn> Matcher for Suggestions<'query, 'conn> {
     fn search(&self, max_results: u32) -> Result<Vec<SearchResult>> {
-        let mut stmt = self.conn.db.prepare(
+        Ok(self.conn.query_rows_and_then_named_cached(
             "
             SELECT h.url, h.title,
                    EXISTS(SELECT 1 FROM moz_bookmarks
@@ -543,20 +536,15 @@ impl<'query, 'conn> Matcher for Suggestions<'query, 'conn> {
                                      :matchBehavior, :searchBehavior)
               AND (+h.visit_count_local > 0 OR +h.visit_count_remote > 0)
             ORDER BY h.frecency DESC, h.id DESC
-            LIMIT :maxResults
+            LIMIT :maxResults",
-        ",
+            &[
-        )?;
+                (":searchString", &self.query),
-        let params: &[(&str, &dyn rusqlite::types::ToSql)] = &[
+                (":matchBehavior", &self.match_behavior),
-            (":searchString", &self.query),
+                (":searchBehavior", &self.search_behavior),
-            (":matchBehavior", &self.match_behavior),
+                (":maxResults", &max_results),
-            (":searchBehavior", &self.search_behavior),
+            ],
-            (":maxResults", &max_results),
+            SearchResult::from_suggestion_row,
-        ];
+        )?)
-        let mut results = Vec::new();
-        for result in stmt.query_and_then_named(params, SearchResult::from_suggestion_row)? {
-            results.push(result?);
-        }
-        Ok(results)
     }
 }
 

components/places/src/storage/history.rs

@@ -258,22 +258,17 @@ pub mod history_sync {
             Some(pi) => pi,
         };
 
-        let mut stmt = db.prepare(
+        let visits = db.query_rows_and_then_named(
-            "
+            "SELECT is_local, visit_type, visit_date
-          SELECT is_local, visit_type, visit_date
+            FROM moz_historyvisits
-          FROM moz_historyvisits
+            WHERE place_id = :place_id
-          WHERE place_id = :place_id
+            LIMIT :limit",
-          LIMIT :limit",
+            &[
+                (":place_id", &page_info.row_id),
+                (":limit", &(limit as u32)),
+            ],
+            FetchedVisit::from_row,
         )?;
-        let visits = stmt
-            .query_and_then_named(
-                &[
-                    (":place_id", &page_info.row_id),
-                    (":limit", &(limit as u32)),
-                ],
-                FetchedVisit::from_row,
-            )?
-            .collect::<Result<Vec<_>>>()?;
         Ok(Some((page_info, visits)))
     }
 
@@ -386,7 +381,7 @@ pub mod history_sync {
     ) -> Result<HashMap<SyncGuid, OutgoingInfo>> {
         // Note that we want *all* "new" regardless of change counter,
         // so that we do the right thing after a "reset".
-        let mut stmt = db.conn().prepare(&format!(
+        let places_sql = format!(
             "
             SELECT guid, url, id, title, hidden, typed, frecency,
                 visit_count_local, visit_count_remote,
@@ -397,31 +392,30 @@ pub mod history_sync {
             ORDER BY frecency DESC
             LIMIT :max_places",
             (SyncStatus::Normal as u8)
-        ))?;
+        );
-        let mut visits = db.conn().prepare(
+        let visits_sql = "
-            "
             SELECT visit_date as date, visit_type as transition
             FROM moz_historyvisits
             WHERE place_id = :place_id
             ORDER BY visit_date DESC
-            LIMIT :max_visits",
+            LIMIT :max_visits";
-        )?;
         // tombstones
-        let mut tombstones_stmt = db.conn().prepare(
+        let tombstones_sql = "SELECT guid FROM moz_places_tombstones LIMIT :max_places";
-            "
-            SELECT guid FROM moz_places_tombstones LIMIT :max_places",
-        )?;
 
         let mut result: HashMap<SyncGuid, OutgoingInfo> = HashMap::new();
 
         // We want to limit to 5000 places - tombstones are arguably the
         // most important, so we fetch these first.
-        let ts_rows = tombstones_stmt.query_and_then_named(
+        let ts_rows = db.query_rows_and_then_named(
+            tombstones_sql,
             &[(":max_places", &(max_places as u32))],
             |row| -> rusqlite::Result<_> { Ok(SyncGuid(row.get_checked::<_, String>("guid")?)) },
         )?;
-        for r in ts_rows {
+        // It's unfortunatee that query_rows_and_then_named returns a Vec instead of an iterator
-            let guid = r?;
+        // (which would be very hard to do), but as long as we have it, we might as well make use
+        // of it...
+        result.reserve(ts_rows.len());
+        for guid in ts_rows {
             log::trace!("outgoing tombstone {:?}", &guid);
             result.insert(guid, OutgoingInfo::Tombstone);
         }
@@ -444,26 +438,26 @@ pub mod history_sync {
         let insert_meta_sql = "
             INSERT INTO temp_sync_updated_meta VALUES (:row_id, :change_delta)";
 
-        let rows = stmt.query_and_then_named(
+        let rows = db.query_rows_and_then_named(
+            &places_sql,
             &[(":max_places", &(max_places_left as u32))],
             PageInfo::from_row,
         )?;
-        let mut ids_to_update = Vec::new();
+        let mut ids_to_update = Vec::with_capacity(rows.len());
-        for t in rows {
+        for page in rows {
-            let page = t?;
+            let visits = db.query_rows_and_then_named_cached(
-            let visit_rows = visits.query_and_then_named(
+                visits_sql,
                 &[
                     (":max_visits", &(max_visits as u32)),
                     (":place_id", &page.row_id),
                 ],
-                |row| {
+                |row| -> RusqliteResult<_> {
                     Ok(HistoryRecordVisit {
                         date: row.get_checked::<_, Timestamp>("date")?.into(),
                         transition: row.get_checked::<_, u8>("transition")?,
                     })
                 },
             )?;
-            let visits = visit_rows.collect::<RusqliteResult<Vec<_>>>()?;
             if result.contains_key(&page.guid) {
                 // should be impossible!
                 log::warn!("Found {:?} in both tombstones and live records", &page.guid);
@@ -639,9 +633,8 @@ pub fn get_visited_urls(
     // TODO: if `end` is >= now then we can probably just look at last_visit_date_{local,remote},
     // and avoid touching `moz_historyvisits` at all. That said, this query is taken more or less
     // from what places does so it's probably fine.
-    let mut stmt = db.prepare(&format!(
+    let sql = format!(
-        "
+        "SELECT h.url
-        SELECT h.url
         FROM moz_places h
         WHERE EXISTS (
             SELECT 1 FROM moz_historyvisits v
@@ -649,16 +642,14 @@ pub fn get_visited_urls(
                 AND visit_date BETWEEN :start AND :end
                 {and_is_local}
             LIMIT 1
-        )
+        )",
-    ",
         and_is_local = if include_remote { "" } else { "AND is_local" }
-    ))?;
+    );
-
+    Ok(db.query_rows_and_then_named_cached(
-    let iter = stmt.query_and_then_named(&[(":start", &start), (":end", &end)], |row| {
+        &sql,
-        Ok(row.get_checked::<_, String>(0)?)
+        &[(":start", &start), (":end", &end)],
-    })?;
+        |row| -> RusqliteResult<_> { Ok(row.get_checked::<_, String>(0)?) },
-
+    )?)
-    Ok(iter.collect::<RusqliteResult<Vec<_>>>()?)
 }
 
 // Mini experiment with an "Origin" object that knows how to rev_host() itself,

components/support/sql/Cargo.toml

@@ -7,6 +7,7 @@ authors = ["Thom Chiovoloni <tchiovoloni@mozilla.com>"]
 [features]
 default = ["sqlcipher"]
 sqlcipher = ["rusqlite/sqlcipher"]
+log_query_plans = []
 
 [dependencies]
 log = "0.4"

components/support/sql/doc/query-plan.md

@@ -0,0 +1,79 @@
+# Getting query plans out of places/logins/other consumers.
+
+If these crates are built with the `log_query_plans` feature enabled (or cargo decides to use a version of `sql-support` that has beeen built with that feature), then queries that go through sql-support will have their [query plans](https://www.sqlite.org/eqp.html) logged. The default place they get logged is stdout, however you can also specify a file by setting the `QUERY_PLAN_LOG` variable in the environment to a file where the plans will be appended.
+
+Worth noting that new logs will be appended to `QUERY_PLAN_LOG`, we don't clear the file. This is so that you can more easily see how the query plan changed during testing.
+
+The queries that go through this are any that are
+
+1. Executed entirely within sql-support (we need both the query and it's parameters)
+2. Take named (and not positional) parameters.
+
+At the time of writing this, that includes:
+
+- `try_query_row`
+- `query_rows_and_then_named_cached`
+- `query_rows_and_then_named`
+- `query_row_and_then_named`
+- `query_one`
+- `execute_named_cached`
+- Possibly more, check [ConnExt](https://github.com/mozilla/application-services/blob/master/components/support/sql/src/conn_ext.rs).
+
+In particular, this excludes queries where the statement is prepared separately from execution.
+
+## Usage
+
+As mentioned, this is turned on with the log_query_plans feature. I don't know why, but I've had mediocre luck enabling it explicitly, but 100% success enabling it via `--all-features`. So that's what I recommend.
+
+Note that for tests, if you're logging to stdout, you'll need to end the test command with `-- --no-capture`, or else it will hide stdout output from you. You also may want to pass `--test-threads 1` (also after the `--`) so that the plans are logged near the tests that are executing, but it doesn't matter that much, since we log the SQL before the plan.
+
+
+Executing tests, having the output logged to stdout:
+
+```
+$ cargo test -p logins --all-features -- --no-capture
+... <snip>
+test engine::test::test_general ...
+### QUERY PLAN
+#### SQL:
+      SELECT <bunch of fields here>
+      FROM loginsL
+      WHERE is_deleted = 0
+        AND guid = :guid
+      UNION ALL
+      SELECT <same bunch of fields here>
+      FROM loginsM
+      WHERE is_overridden IS NOT 1
+        AND guid = :guid
+      ORDER BY hostname ASC
+      LIMIT 1
+
+#### PLAN:
+QUERY PLAN
+`--MERGE (UNION ALL)
+   |--LEFT
+   |  `--SEARCH TABLE loginsL USING INDEX sqlite_autoindex_loginsL_1 (guid=?)
+   `--RIGHT
+      `--SEARCH TABLE loginsM USING INDEX sqlite_autoindex_loginsM_1 (guid=?)
+### END QUERY PLAN
+... <snip>
+```
+
+Executing an example, with the output logged to a file.
+
+```
+$ env QUERY_PLAN_LOG=/path/to/my/logfile.txt cargo run -p places --all-features --example autocomplete -- <args for example go here>
+# (many shells can also do this as follows)
+$ QUERY_PLAN_LOG=/path/to/my/logfile.txt cargo run -p places --all-features --example autocomplete -- <args for example go here>
+```
+
+## Using from code
+
+This is also available as types on `sql_support`.
+
+```rust
+println!("This prints the same output as is normally logged, and works \
+          even when the logging feature is off: {}",
+         sql_support:QueryPlan::new(conn, sql, params));
+```
+

components/support/sql/src/conn_ext.rs

@@ -12,6 +12,8 @@ use std::time::Instant;
 
 use crate::maybe_cached::MaybeCached;
 
+pub struct Conn(rusqlite::Connection);
+
 /// This trait exists so that we can use these helpers on `rusqlite::{Transaction, Connection}`.
 /// Note that you must import ConnExt in order to call these methods on anything.
 pub trait ConnExt {
@@ -50,12 +52,14 @@ pub trait ConnExt {
     /// Equivalent to `Connection::execute_named` but caches the statement so that subsequent
     /// calls to `execute_named_cached` will have imprroved performance.
     fn execute_named_cached(&self, sql: &str, params: &[(&str, &dyn ToSql)]) -> SqlResult<usize> {
+        crate::maybe_log_plan(self.conn(), sql, params);
         let mut stmt = self.conn().prepare_cached(sql)?;
         stmt.execute_named(params)
     }
 
     /// Execute a query that returns a single result column, and return that result.
     fn query_one<T: FromSql>(&self, sql: &str) -> SqlResult<T> {
+        crate::maybe_log_plan(self.conn(), sql, &[]);
         let res: T = self
             .conn()
             .query_row_and_then(sql, NO_PARAMS, |row| row.get_checked(0))?;
@@ -76,11 +80,47 @@ pub trait ConnExt {
         E: From<rusqlite::Error>,
         F: FnOnce(&Row) -> Result<T, E>,
     {
+        crate::maybe_log_plan(self.conn(), sql, params);
         Ok(self
             .try_query_row(sql, params, mapper, cache)?
             .ok_or(rusqlite::Error::QueryReturnedNoRows)?)
     }
 
+    /// Helper for when you'd like to get a Vec<T> of all the rows returned by a
+    /// query that takes named arguments. See also
+    /// `query_rows_and_then_named_cached`.
+    fn query_rows_and_then_named<T, E, F>(
+        &self,
+        sql: &str,
+        params: &[(&str, &dyn ToSql)],
+        mapper: F,
+    ) -> Result<Vec<T>, E>
+    where
+        Self: Sized,
+        E: From<rusqlite::Error>,
+        F: FnMut(&Row) -> Result<T, E>,
+    {
+        crate::maybe_log_plan(self.conn(), sql, params);
+        query_rows_and_then_named(self.conn(), sql, params, mapper, false)
+    }
+
+    /// Helper for when you'd like to get a Vec<T> of all the rows returned by a
+    /// query that takes named arguments.
+    fn query_rows_and_then_named_cached<T, E, F>(
+        &self,
+        sql: &str,
+        params: &[(&str, &dyn ToSql)],
+        mapper: F,
+    ) -> Result<Vec<T>, E>
+    where
+        Self: Sized,
+        E: From<rusqlite::Error>,
+        F: FnMut(&Row) -> Result<T, E>,
+    {
+        crate::maybe_log_plan(self.conn(), sql, params);
+        query_rows_and_then_named(self.conn(), sql, params, mapper, true)
+    }
+
     // This should probably have a longer name...
     /// Like `query_row_and_then_named` but returns None instead of erroring if no such row exists.
     fn try_query_row<T, E, F>(
@@ -95,6 +135,7 @@ pub trait ConnExt {
         E: From<rusqlite::Error>,
         F: FnOnce(&Row) -> Result<T, E>,
     {
+        crate::maybe_log_plan(self.conn(), sql, params);
         let conn = self.conn();
         let mut stmt = MaybeCached::prepare(conn, sql, cache)?;
         let mut rows = stmt.query_named(params)?;
@@ -213,3 +254,22 @@ impl<'conn> ConnExt for UncheckedTransaction<'conn> {
         &*self
     }
 }
+
+fn query_rows_and_then_named<T, E, F>(
+    conn: &Connection,
+    sql: &str,
+    params: &[(&str, &dyn ToSql)],
+    mapper: F,
+    cache: bool,
+) -> Result<Vec<T>, E>
+where
+    E: From<rusqlite::Error>,
+    F: FnMut(&Row) -> Result<T, E>,
+{
+    let mut stmt = conn.prepare_maybe_cached(sql, cache)?;
+    let mut res = vec![];
+    for item in stmt.query_and_then_named(params, mapper)? {
+        res.push(item?);
+    }
+    Ok(res)
+}

components/support/sql/src/lib.rs

@@ -5,11 +5,13 @@
 mod conn_ext;
 mod each_chunk;
 mod maybe_cached;
+mod query_plan;
 mod repeat;
 
 pub use crate::conn_ext::*;
 pub use crate::each_chunk::*;
 pub use crate::maybe_cached::*;
+pub use crate::query_plan::*;
 pub use crate::repeat::*;
 
 /// In PRAGMA foo='bar', `'bar'` must be a constant string (it cannot be a

components/support/sql/src/query_plan.rs

@@ -0,0 +1,182 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+use rusqlite::{types::ToSql, Connection, Result as SqlResult};
+
+#[derive(Debug, Clone, PartialEq, Eq, Hash)]
+pub struct QueryPlanStep {
+    pub node_id: i32,
+    pub parent_id: i32,
+    pub aux: i32,
+    pub detail: String,
+}
+
+#[derive(Debug, Clone, PartialEq, Eq, Hash)]
+pub struct QueryPlan {
+    pub query: String,
+    pub plan: Vec<QueryPlanStep>,
+}
+
+impl QueryPlan {
+    // TODO: support positional params (it's a pain...)
+    pub fn new(conn: &Connection, sql: &str, params: &[(&str, &dyn ToSql)]) -> SqlResult<Self> {
+        let plan_sql = format!("EXPLAIN QUERY PLAN {}", sql);
+        let mut stmt = conn.prepare(&plan_sql)?;
+        let plan = stmt
+            .query_and_then_named(params, |row| -> SqlResult<_> {
+                Ok(QueryPlanStep {
+                    node_id: row.get_checked(0)?,
+                    parent_id: row.get_checked(1)?,
+                    aux: row.get_checked(2)?,
+                    detail: row.get_checked(3)?,
+                })
+            })?
+            .collect::<Result<Vec<QueryPlanStep>, _>>()?;
+        Ok(QueryPlan {
+            query: sql.into(),
+            plan,
+        })
+    }
+
+    pub fn print_pretty_tree(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
+        if self.plan.len() == 0 {
+            return writeln!(f, "<no query plan>");
+        }
+        writeln!(f, "QUERY PLAN")?;
+        let children = self
+            .plan
+            .iter()
+            .filter(|e| e.parent_id == 0)
+            .collect::<Vec<_>>();
+        for (i, child) in children.iter().enumerate() {
+            let last = i == children.len() - 1;
+            self.print_tree(f, child, "", last)?;
+        }
+        Ok(())
+    }
+
+    fn print_tree(
+        &self,
+        f: &mut std::fmt::Formatter,
+        entry: &QueryPlanStep,
+        prefix: &str,
+        last_child: bool,
+    ) -> std::fmt::Result {
+        let children = self
+            .plan
+            .iter()
+            .filter(|e| e.parent_id == entry.node_id)
+            .collect::<Vec<_>>();
+        let next_prefix = if last_child {
+            writeln!(f, "{}`--{}", prefix, entry.detail)?;
+            format!("{}   ", prefix)
+        } else {
+            writeln!(f, "{}|--{}", prefix, entry.detail)?;
+            format!("{}|  ", prefix)
+        };
+        for (i, child) in children.iter().enumerate() {
+            let last = i == children.len() - 1;
+            self.print_tree(f, child, &next_prefix, last)?;
+        }
+        Ok(())
+    }
+}
+
+impl std::fmt::Display for QueryPlan {
+    fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result {
+        writeln!(f, "### QUERY PLAN")?;
+        writeln!(f, "#### SQL:\n{}\n#### PLAN:", self.query)?;
+        self.print_pretty_tree(f)?;
+        writeln!(f, "### END QUERY PLAN")
+    }
+}
+
+/// Log a query plan if the `log_query_plans` feature is enabled and it hasn't been logged yet.
+#[inline]
+pub fn maybe_log_plan(_conn: &Connection, _sql: &str, _params: &[(&str, &dyn ToSql)]) {
+    // Note: underscores ar needed becasue those go unused if the feature is not turned on.
+    #[cfg(feature = "log_query_plans")]
+    {
+        plan_log::log_plan(_conn, _sql, _params)
+    }
+}
+
+#[cfg(feature = "log_query_plans")]
+mod plan_log {
+    use super::*;
+    use std::collections::HashMap;
+    use std::io::Write;
+    use std::sync::Mutex;
+
+    struct PlanLogger {
+        seen: HashMap<String, QueryPlan>,
+        out: Box<dyn Write + Send>,
+    }
+
+    impl PlanLogger {
+        fn new() -> Self {
+            let out_file = std::env::var("QUERY_PLAN_LOG").unwrap_or_default();
+            let output: Box<dyn Write + Send> = if out_file != "" {
+                let mut file = std::fs::OpenOptions::new()
+                    .create(true)
+                    .append(true)
+                    .open(out_file)
+                    .expect("QUERY_PLAN_LOG file does not exist!");
+                writeln!(
+                    file,
+                    "\n\n# Query Plan Log starting at time: {:?}\n",
+                    std::time::SystemTime::now()
+                )
+                .expect("Failed to write to plan log file");
+                Box::new(file)
+            } else {
+                println!("QUERY_PLAN_LOG was not set, logging to stdout");
+                Box::new(std::io::stdout())
+            };
+            Self {
+                seen: Default::default(),
+                out: output,
+            }
+        }
+
+        fn maybe_log(&mut self, plan: QueryPlan) {
+            use std::collections::hash_map::Entry;
+            match self.seen.entry(plan.query.clone()) {
+                Entry::Occupied(mut o) => {
+                    if o.get() == &plan {
+                        return;
+                    }
+                    // Ignore IO failures.
+                    let _ = writeln!(self.out, "### QUERY PLAN CHANGED!\n{}", plan);
+                    o.insert(plan);
+                }
+                Entry::Vacant(v) => {
+                    let _ = writeln!(self.out, "{}", plan);
+                    v.insert(plan);
+                }
+            }
+            let _ = self.out.flush();
+        }
+    }
+
+    lazy_static::lazy_static! {
+        static ref PLAN_LOGGER: Mutex<PlanLogger> = Mutex::new(PlanLogger::new());
+    }
+
+    pub fn log_plan(conn: &Connection, sql: &str, params: &[(&str, &dyn ToSql)]) {
+        if sql.starts_with("EXPLAIN") {
+            return;
+        }
+        let plan = match QueryPlan::new(conn, sql, params) {
+            Ok(plan) => plan,
+            Err(e) => {
+                // We're usually doing this during tests where logs often arent available
+                eprintln!("Failed to get query plan for {}: {}", sql, e);
+                return;
+            }
+        };
+        let mut logger = PLAN_LOGGER.lock().unwrap();
+        logger.maybe_log(plan);
+    }
+}