From: Chris Jaekl <cejaekl@yahoo.com>
Date: Tue, 5 Dec 2017 13:24:49 +0000 (+0900)
Subject: Track SQL statement execution times, so that they can be profiled.
X-Git-Url: http://jaekl.net/gitweb/?p=quanlib.git;a=commitdiff_plain;h=872d620121706ad345b7e667521be1c7326c2e00

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.
---

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
+