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 69e1278d40393ea9d3d7e75d34cdf452645e8ed1..bf24b0e20c28a7fcbb9a373a656347811a16294b 100644 (file)
--- 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 (file)
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
+