From 4f9eb8c06b66393fd3d6a0fff8289362d374d911 Mon Sep 17 00:00:00 2001 From: Dimitri Fontaine Date: Wed, 23 Aug 2017 11:55:49 +0200 Subject: [PATCH] Track bytes sent to PostgreSQL. The pgstate infrastructure already had lots of details about what's going on, add to it the information about how many bytes are sent in every batch, and use this information in the monitor when something long is happening to display how many rows we sent from the beginning for this (supposedly) huge table, along with bytes and speed (bytes per seconds). --- src/package.lisp | 1 + src/pgsql/copy-from-queue.lisp | 4 +++- src/utils/monitor.lisp | 28 +++++++++++++++++++--------- src/utils/state.lisp | 19 +++++++++++++++---- 4 files changed, 38 insertions(+), 14 deletions(-) diff --git a/src/package.lisp b/src/package.lisp index 9b9edc3..9522659 100644 --- a/src/package.lisp +++ b/src/package.lisp @@ -208,6 +208,7 @@ #:pgtable-initialize-reject-files #:pgtable-secs #:pgtable-rows + #:pgtable-bytes #:pgtable-start #:pgtable-stop #:pgtable-reject-data diff --git a/src/pgsql/copy-from-queue.lisp b/src/pgsql/copy-from-queue.lisp index 92e065a..3921ec1 100644 --- a/src/pgsql/copy-from-queue.lisp +++ b/src/pgsql/copy-from-queue.lisp @@ -139,7 +139,9 @@ (pretty-print-bytes (batch-bytes current-batch)) batch-seconds (batch-oversized-p current-batch)) - (update-stats :data table :rows (batch-count current-batch)) + (update-stats :data table + :rows (batch-count current-batch) + :bytes (batch-bytes current-batch)) ;; return batch-seconds batch-seconds)))) diff --git a/src/utils/monitor.lisp b/src/utils/monitor.lisp index 32eefc7..c416478 100644 --- a/src/utils/monitor.lisp +++ b/src/utils/monitor.lisp @@ -33,7 +33,7 @@ (defstruct report-summary reset) (defstruct log-message category description arguments) (defstruct new-label section label dbname) -(defstruct update-stats section label read rows errs secs rs ws start stop) +(defstruct update-stats section label read rows errs secs rs ws bytes start stop) (defstruct bad-row section label condition data) (defun log-message (category description &rest arguments) @@ -48,7 +48,8 @@ SECTION." (send-event (make-new-label :section section :label label :dbname dbname))) -(defun update-stats (section label &key read rows errs secs rs ws start stop) +(defun update-stats (section label + &key read rows errs secs rs ws bytes start stop) "Send an event to update stats for given SECTION and LABEL." (send-event (make-update-stats :section section :label label @@ -58,6 +59,7 @@ :secs secs :rs rs :ws ws + :bytes bytes :start start :stop stop))) @@ -233,25 +235,33 @@ (pgstate-incf pgstate label :read (update-stats-read event) :rows (update-stats-rows event) - :secs (update-stats-secs event) :errs (update-stats-errs event) + :secs (update-stats-secs event) :rs (update-stats-rs event) - :ws (update-stats-ws event)) + :ws (update-stats-ws event) + :bytes (update-stats-bytes event)) ;; log some kind of a “keep alive” message to the user, for ;; the sake of showing progress. ;; - ;; something like one message every 20 batches should only + ;; something like one message every 10 batches should only ;; target big tables where we have to wait for a pretty long ;; time. (when (and (update-stats-rows event) (typep label 'pgloader.catalog:table) - (< (* 19 *copy-batch-rows*) + (< (* 9 *copy-batch-rows*) (mod (pgtable-rows table) - (* 20 *copy-batch-rows*)))) - (log-message :notice "copy ~a: ~d rows done" + (* 10 *copy-batch-rows*)))) + (log-message :notice "copy ~a: ~d rows done, ~7<~a~>, ~9<~a~>" (pgloader.catalog:format-table-name label) - (pgtable-rows table))) + (pgtable-rows table) + (pgloader.utils:pretty-print-bytes + (pgtable-bytes table)) + (pgloader.utils:pretty-print-bytes + (truncate (pgtable-bytes table) + (elapsed-time-since + (pgtable-start table))) + :unit "Bps"))) (when (update-stats-start event) (log-message :debug "start ~a ~30t ~a" diff --git a/src/utils/state.lisp b/src/utils/state.lisp index db2292e..b9c6213 100644 --- a/src/utils/state.lisp +++ b/src/utils/state.lisp @@ -16,6 +16,7 @@ (secs 0.0 :type float) ; how many seconds did it take (rs 0.0 :type float) ; seconds spent reading (ws 0.0 :type float) ; seconds spent writing + (bytes 0 :type fixnum) ; how many bytes we sent (start 0 :type integer) ; internal real time when we started (stop 0 :type integer) ; internal real time when we finished reject-data reject-logs) ; files where to find reject data @@ -28,7 +29,8 @@ (errs 0 :type fixnum) (secs 0.0 :type float) (rs 0.0 :type float) - (ws 0.0 :type float)) + (ws 0.0 :type float) + (bytes 0 :type fixnum)) (defun relative-pathname (filename type &optional dbname) "Return the pathname of a file of type TYPE (dat or log) under *ROOT-DIR*" @@ -93,7 +95,7 @@ pgtable))) -(defun pgstate-setf (pgstate name &key read rows errs secs rs ws) +(defun pgstate-setf (pgstate name &key read rows errs secs rs ws bytes) (let ((pgtable (pgstate-get-label pgstate name))) (when read (setf (pgtable-read pgtable) read) @@ -113,9 +115,12 @@ (when ws (setf (pgtable-ws pgtable) ws) (incf (pgstate-ws pgstate) ws)) + (when bytes + (setf (pgtable-bytes pgtable) bytes) + (incf (pgstate-bytes pgstate) bytes)) pgtable)) -(defun pgstate-incf (pgstate name &key read rows errs secs rs ws) +(defun pgstate-incf (pgstate name &key read rows errs secs rs ws bytes) (let ((pgtable (pgstate-get-label pgstate name))) (when read (incf (pgtable-read pgtable) read) @@ -135,9 +140,12 @@ (when ws (incf (pgtable-ws pgtable) ws) (incf (pgstate-ws pgstate) ws)) + (when bytes + (incf (pgtable-bytes pgtable) bytes) + (incf (pgstate-bytes pgstate) bytes)) pgtable)) -(defun pgstate-decf (pgstate name &key read rows errs secs rs ws) +(defun pgstate-decf (pgstate name &key read rows errs secs rs ws bytes) (let ((pgtable (pgstate-get-label pgstate name))) (when read (decf (pgtable-read pgtable) read) @@ -157,4 +165,7 @@ (when secs (decf (pgtable-secs pgtable) secs) (decf (pgstate-secs pgstate) secs)) + (when bytes + (decf (pgtable-bytes pgtable) secs) + (decf (pgstate-bytes pgstate) secs)) pgtable))