From 7c64a713d0c062a2d06dac9e0c28b1b0cb03ae04 Mon Sep 17 00:00:00 2001
From: Dimitri Fontaine <dim@tapoueh.org>
Date: Sun, 29 Nov 2015 23:23:30 +0100
Subject: [PATCH] Fix PostgreSQL write times in the summary.

It turns out the summary write times included time spent waiting for
batches to be ready, which isn't fair to PostgreSQL COPY implementation,
and moreover doesn't help figuring out the bottlenecks...
---
 src/pgsql/pgsql.lisp | 27 +++++++++++++++++----------
 1 file changed, 17 insertions(+), 10 deletions(-)

diff --git a/src/pgsql/pgsql.lisp b/src/pgsql/pgsql.lisp
index 980dc5a..318abb0 100644
--- a/src/pgsql/pgsql.lisp
+++ b/src/pgsql/pgsql.lisp
@@ -47,7 +47,7 @@
   "Fetch from the QUEUE messages containing how many rows are in the
    *writer-batch* for us to send down to PostgreSQL, and when that's done
    update stats."
-  (let ((start-time (get-internal-real-time)))
+  (let ((seconds 0))
     (when truncate
       (truncate-tables pgconn (list table-name)))
 
@@ -61,21 +61,28 @@
           (loop
              :for (mesg batch read oversized?) := (lq:pop-queue queue)
              :until (eq :end-of-data mesg)
-             :for rows := (copy-batch unqualified-table-name columns batch read)
+             :for (rows batch-seconds) :=
+             (let ((start-time (get-internal-real-time)))
+               (list (copy-batch unqualified-table-name columns batch read)
+                     (elapsed-time-since start-time)))
              :do (progn
                    ;; The SBCL implementation needs some Garbage Collection
                    ;; decision making help... and now is a pretty good time.
                    #+sbcl (when oversized? (sb-ext:gc :full t))
-                   (log-message :debug "copy-batch[~a] ~a ~d row~:p~:[~; [oversized]~]"
+                   (log-message :debug
+                                "copy-batch[~a] ~a ~d row~:p in ~6$s~@[ [oversized]~]"
                                 (lp:kernel-worker-index)
-                                unqualified-table-name rows oversized?)
-                   (update-stats :data table-name :rows rows))))))
+                                unqualified-table-name
+                                rows
+                                batch-seconds
+                                oversized?)
+                   (update-stats :data table-name :rows rows)
+                   (incf seconds batch-seconds))))))
 
-    (let ((seconds (elapsed-time-since start-time)))
-      (log-message :info "Writer[~a] for ~a is done in ~6$s"
-                   (lp:kernel-worker-index) table-name seconds)
-      (update-stats :data table-name :ws seconds)
-      (list :writer table-name seconds))))
+    (update-stats :data table-name :ws seconds)
+    (log-message :debug "Writer[~a] for ~a is done in ~6$s"
+                 (lp:kernel-worker-index) table-name seconds)
+    (list :writer table-name seconds)))
 
 ;;;
 ;;; Compute how many rows we're going to try loading next, depending on