Record database_id in QueryExecution; record query in Query

resources/migrations/000_migrations.yaml

@@ -4989,6 +4989,38 @@ databaseChangeLog:
             tableName: metabase_field
             columnName: raw_column_id
 
+# Add database_id column to query_execution
+
+  - changeSet:
+      id: 92
+      author: camsaul
+      comment: 'Added 0.31.0'
+      validCheckSum: 8:a875945f36824a0667c740888c00c37f
+      validCheckSum: 8:83ded48e18fe8f70d6ec09add042124d
+      changes:
+        - addColumn:
+            tableName: query_execution
+            columns:
+              name: database_id
+              type: integer
+              remarks: 'ID of the database this query was ran against.'
+        - sql:
+            sql: UPDATE query_execution SET database_id = (select database_id from report_card where id = query_execution.card_id);
+
+# Start recording the actual query dictionary that's been executed
+
+  - changeSet:
+      id: 93
+      author: camsaul
+      comment: 'Added 0.31.0'
+      changes:
+        - addColumn:
+            tableName: query
+            columns:
+              name: query
+              type: text
+              remarks: 'The actual "query dictionary" for this query.'
+
 # Create the TaskHistory table, intended to provide debugging info on our background/quartz processes
   - changeSet:
       id: 94

src/metabase/models/query.clj

 (ns metabase.models.query
   "Functions related to the 'Query' model, which records stuff such as average query execution time."
-  (:require [metabase.db :as mdb]
+  (:require [cheshire.core :as json]
+            [metabase
+             [db :as mdb]
+             [util :as u]]
             [metabase.mbql.normalize :as normalize]
             [metabase.util.honeysql-extensions :as hx]
             [toucan
@@ -9,6 +12,11 @@
 
 (models/defmodel Query :query)
 
+(u/strict-extend (class Query)
+  models/IModel
+  (merge models/IModelDefaults
+         {:types (constantly {:query :json})}))
+
 ;;; Helper Fns
 
 (defn average-execution-time-ms
@@ -30,32 +38,43 @@
 (defn- update-rolling-average-execution-time!
   "Update the rolling average execution time for query with QUERY-HASH. Returns `true` if a record was updated,
    or `false` if no matching records were found."
-  ^Boolean [^bytes query-hash, ^Integer execution-time-ms]
-  (db/update-where! Query {:query_hash query-hash}
-    :average_execution_time (hx/cast (int-casting-type) (hx/round (hx/+ (hx/* 0.9 :average_execution_time)
-                                                                        (*    0.1 execution-time-ms))
-                                                                  0))))
+  ^Boolean [query, ^bytes query-hash, ^Integer execution-time-ms]
+  (let [avg-execution-time (hx/cast (int-casting-type) (hx/round (hx/+ (hx/* 0.9 :average_execution_time)
+                                                                       (*    0.1 execution-time-ms))
+                                                                 0))]
+
+    (or
+     ;; if it DOES NOT have a query (yet) set that. In 0.31.0 we added the query.query column, and it gets set for all
+     ;; new entries, so at some point in the future we can take this out, and save a DB call.
+     (db/update-where! Query {:query_hash query-hash, :query nil}
+       :query                 (json/generate-string query)
+       :average_execution_time avg-execution-time)
+     ;; if query is already set then just update average_execution_time. (We're doing this separate call to avoid
+     ;; updating query on every single UPDATE)
+     (db/update-where! Query {:query_hash query-hash}
+       :average_execution_time avg-execution-time))))
 
-(defn- record-new-execution-time!
-  "Record the execution time for a query with QUERY-HASH that's not already present in the DB.
-   EXECUTION-TIME-MS is used as a starting point."
-  [^bytes query-hash, ^Integer execution-time-ms]
+(defn- record-new-query-entry!
+  "Record a query and its execution time for a `query` with `query-hash` that's not already present in the DB.
+  `execution-time-ms` is used as a starting point."
+  [query, ^bytes query-hash, ^Integer execution-time-ms]
   (db/insert! Query
+    :query                  query
     :query_hash             query-hash
     :average_execution_time execution-time-ms))
 
-(defn update-average-execution-time!
-  "Update the recorded average execution time for query with QUERY-HASH."
-  [^bytes query-hash, ^Integer execution-time-ms]
+(defn save-query-and-update-average-execution-time!
+  "Update the recorded average execution time (or insert a new record if needed) for `query` with `query-hash`."
+  [query, ^bytes query-hash, ^Integer execution-time-ms]
   {:pre [(instance? (Class/forName "[B") query-hash)]}
   (or
    ;; if there's already a matching Query update the rolling average
-   (update-rolling-average-execution-time! query-hash execution-time-ms)
+   (update-rolling-average-execution-time! query query-hash execution-time-ms)
    ;; otherwise try adding a new entry. If for some reason there was a race condition and a Query entry was added in
    ;; the meantime we'll try updating that existing record
-   (try (record-new-execution-time! query-hash execution-time-ms)
+   (try (record-new-query-entry! query query-hash execution-time-ms)
         (catch Throwable e
-          (or (update-rolling-average-execution-time! query-hash execution-time-ms)
+          (or (update-rolling-average-execution-time! query query-hash execution-time-ms)
               ;; rethrow e if updating an existing average execution time failed
               (throw e))))))
 

src/metabase/query_processor.clj

@@ -106,10 +106,10 @@
       wrap-value-literals/wrap-value-literals
       annotate/add-column-info
       perms/check-query-permissions
+      cumulative-ags/handle-cumulative-aggregations
       resolve-joined-tables/resolve-joined-tables
       dev/check-results-format
       limit/limit
-      cumulative-ags/handle-cumulative-aggregations
       results-metadata/record-and-return-metadata!
       format-rows/format-rows
       desugar/desugar
@@ -226,9 +226,9 @@
 
 (defn- save-query-execution!
   "Save a `QueryExecution` and update the average execution time for the corresponding `Query`."
-  [query-execution]
+  [{query :json_query, :as query-execution}]
   (u/prog1 query-execution
-    (query/update-average-execution-time! (:hash query-execution) (:running_time query-execution))
+    (query/save-query-and-update-average-execution-time! query (:hash query-execution) (:running_time query-execution))
     (db/insert! QueryExecution (dissoc query-execution :json_query))))
 
 (defn- save-and-return-failed-query!
@@ -293,10 +293,14 @@
 
 (defn- query-execution-info
   "Return the info for the `QueryExecution` entry for this QUERY."
-  [{{:keys [executed-by query-hash query-type context card-id dashboard-id pulse-id]} :info, :as query}]
+  {:arglists '([query])}
+  [{{:keys [executed-by query-hash query-type context card-id dashboard-id pulse-id]} :info
+    database-id                                                                       :database
+    :as                                                                               query}]
   {:pre [(instance? (Class/forName "[B") query-hash)
          (string? query-type)]}
-  {:executor_id       executed-by
+  {:database_id       database-id
+   :executor_id       executed-by
    :card_id           card-id
    :dashboard_id      dashboard-id
    :pulse_id          pulse-id

test/metabase/api/dataset_test.clj

@@ -71,7 +71,8 @@
                                 (assoc :constraints qp/default-query-constraints))
     :started_at             true
     :running_time           true
-    :average_execution_time nil}
+    :average_execution_time nil
+    :database_id            (id)}
    ;; QueryExecution record in the DB
    {:hash         true
     :row_count    1
@@ -84,6 +85,7 @@
     :dashboard_id nil
     :error        nil
     :id           true
+    :database_id  (id)
     :started_at   true
     :running_time true}]
   (let [result ((user->client :rasta) :post 200 "dataset" (data/mbql-query checkins
@@ -94,7 +96,7 @@
 
 ;; Even if a query fails we still expect a 200 response from the api
 (expect
-  [;; API call response
+  [ ;; API call response
    {:data         {:rows    []
                    :columns []
                    :cols    []}
@@ -106,6 +108,7 @@
                    :type        "native"
                    :native      {:query "foobar"}
                    :constraints qp/default-query-constraints}
+    :database_id  (id)
     :started_at   true
     :running_time true}
    ;; QueryExecution entry in the DB
@@ -115,6 +118,7 @@
     :row_count    0
     :context      :ad-hoc
     :error        true
+    :database_id  (id)
     :started_at   true
     :running_time true
     :executor_id  (user->id :rasta)

test/metabase/query_processor_test/failure_test.clj

@@ -45,7 +45,8 @@
 
 ;; running via `process-query-and-save-execution!` should return similar info and a bunch of other nonsense too
 (expect
-  {:started_at   true
+  {:database_id  (data/id)
+   :started_at   true
    :json_query   (bad-query)
    :native       bad-query:native
    :status       :failed