From 872d620121706ad345b7e667521be1c7326c2e00 Mon Sep 17 00:00:00 2001
From: Chris Jaekl <cejaekl@yahoo.com>
Date: Tue, 5 Dec 2017 22:24:49 +0900
Subject: [PATCH] Track SQL statement execution times, so that they can be
 profiled.

As it happens, this revealed one missing index (primary key on the
EFS table was not declared).  Fixing that offers a modest speed-up.
---
 store.rb |  6 +++--
 tconn.rb | 71 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 75 insertions(+), 2 deletions(-)
 create mode 100644 tconn.rb

diff --git a/store.rb b/store.rb
index 69e1278..bf24b0e 100644
--- a/store.rb
+++ b/store.rb
@@ -3,6 +3,7 @@ require 'csv'
 require 'fileutils'
 require 'inifile'
 require 'pg'
+require 'tconn'
 
 require 'series'
 
@@ -33,7 +34,8 @@ class Store
 
   def connect
     # @conn = PGconn.connect('localhost', 5432, '', '', 'quanlib', 'quanlib', 'quanlib')
-    @conn = PG.connect(@dbhost, @dbport, '', '', @dbname, @dbuser, @dbpass)
+    # @conn = PG.connect(@dbhost, @dbport, '', '', @dbname, @dbuser, @dbpass)
+    @conn = TimedConn.new(PG.connect(@dbhost, @dbport, '', '', @dbname, @dbuser, @dbpass))
     return @conn
   end
 
@@ -90,7 +92,7 @@ EOS
     create_efs = 
 <<EOS
       CREATE TABLE EFS (
-        id          INTEGER,
+        id          INTEGER PRIMARY KEY,
         mimetype    VARCHAR(64)
       );
 EOS
diff --git a/tconn.rb b/tconn.rb
new file mode 100644
index 0000000..43fa0f5
--- /dev/null
+++ b/tconn.rb
@@ -0,0 +1,71 @@
+# tconn.rb
+#
+# Timed Connection:  
+# Wrapper around a PG Connection that provides a report on where time was spent executing SQL
+#
+
+require 'pg'
+
+class TimedConn 
+  def initialize(wrapped_conn)
+    @conn = wrapped_conn
+    @stmts = {}
+    @total_time = 0
+  end
+
+  def close
+    @conn.close()
+    puts "Connection closing.  Total SQL time:  " + @total_time.to_s + " secs"
+    @stmts.each do |sql, info| 
+      elapsed = info[2]
+      calls = info[1]
+      puts elapsed.to_s + " secs: " + calls.to_s + " times:  " + sql
+    end
+  end
+
+  def exec(*args, &block)
+    before = Time.now
+    #puts args.inspect
+    result = @conn.exec(*args)
+    #puts result.inspect
+    after = Time.now
+    elapsed = (after - before)
+    remember(args[0], elapsed)
+    @total_time += elapsed
+    if block_given?
+      yield(result)
+    else
+      return result
+    end
+  end
+
+  def exec_params(*args, &block)
+    before = Time.now
+    #puts args.inspect
+    result = @conn.exec_params(*args)
+    #puts result.inspect
+    after = Time.now
+    elapsed = (after - before)
+    remember(args[0], elapsed)
+    @total_time += elapsed
+    if block_given?
+      yield(result)
+    else
+      return result
+    end
+  end
+
+  def remember(sql, elapsed)
+    if @stmts.has_key?(sql)
+      stmt = @stmts[sql]
+    else
+      stmt = [sql, 0, 0]
+    end
+
+    stmt[1] += 1  # Number of times this statement has been invoked
+    stmt[2] += elapsed   # total elapsed time spent on this statement
+    
+    @stmts[sql] = stmt
+  end
+end
+
-- 
2.39.2