From 36d017f129053f0bf8fa0f32c3cdf0c2cea21d4f Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jos=C3=A9=20Carlos=20Nieto?= <jose.carlos@menteslibres.net>
Date: Fri, 27 Jun 2014 17:35:15 -0500
Subject: [PATCH] Adding query time (seconds) to the logger output.

---
 mysql/database.go      | 23 ++++++++++++++++++-----
 postgresql/database.go | 23 ++++++++++++++++++-----
 ql/database.go         | 23 +++++++++++++++++------
 sqlite/database.go     | 29 +++++++++++++++++++++++------
 util/sqlutil/main.go   | 16 ++++++++++------
 5 files changed, 86 insertions(+), 28 deletions(-)

diff --git a/mysql/database.go b/mysql/database.go
index 1b1830f2..4eb19052 100644
--- a/mysql/database.go
+++ b/mysql/database.go
@@ -27,6 +27,7 @@ import (
 	"os"
 	"regexp"
 	"strings"
+	"time"
 
 	_ "github.com/go-sql-driver/mysql"
 	"upper.io/db"
@@ -68,9 +69,9 @@ func debugEnabled() bool {
 	return false
 }
 
-func debugLog(query string, args []interface{}, err error) {
+func debugLog(query string, args []interface{}, err error, start int64, end int64) {
 	if debugEnabled() == true {
-		d := sqlutil.Debug{query, args, err}
+		d := sqlutil.Debug{query, args, err, start, end}
 		d.Print()
 	}
 }
@@ -114,9 +115,13 @@ func (self *Source) doExec(stmt sqlgen.Statement, args ...interface{}) (sql.Resu
 	var query string
 	var res sql.Result
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -138,9 +143,13 @@ func (self *Source) doQuery(stmt sqlgen.Statement, args ...interface{}) (*sql.Ro
 	var rows *sql.Rows
 	var query string
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -162,9 +171,13 @@ func (self *Source) doQueryRow(stmt sqlgen.Statement, args ...interface{}) (*sql
 	var query string
 	var row *sql.Row
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
diff --git a/postgresql/database.go b/postgresql/database.go
index cff0f7ef..4af576b4 100644
--- a/postgresql/database.go
+++ b/postgresql/database.go
@@ -27,6 +27,7 @@ import (
 	"os"
 	"regexp"
 	"strings"
+	"time"
 
 	_ "github.com/xiam/gopostgresql"
 	"upper.io/db"
@@ -70,9 +71,9 @@ func debugEnabled() bool {
 	return false
 }
 
-func debugLog(query string, args []interface{}, err error) {
+func debugLog(query string, args []interface{}, err error, start int64, end int64) {
 	if debugEnabled() == true {
-		d := sqlutil.Debug{query, args, err}
+		d := sqlutil.Debug{query, args, err, start, end}
 		d.Print()
 	}
 }
@@ -116,9 +117,13 @@ func (self *source) doExec(stmt sqlgen.Statement, args ...interface{}) (sql.Resu
 	var query string
 	var res sql.Result
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -145,9 +150,13 @@ func (self *source) doQuery(stmt sqlgen.Statement, args ...interface{}) (*sql.Ro
 	var rows *sql.Rows
 	var query string
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -174,9 +183,13 @@ func (self *source) doQueryRow(stmt sqlgen.Statement, args ...interface{}) (*sql
 	var query string
 	var row *sql.Row
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
diff --git a/ql/database.go b/ql/database.go
index 27e7da7d..13af8cf1 100644
--- a/ql/database.go
+++ b/ql/database.go
@@ -71,9 +71,9 @@ func debugEnabled() bool {
 	return false
 }
 
-func debugLog(query string, args []interface{}, err error) {
+func debugLog(query string, args []interface{}, err error, start int64, end int64) {
 	if debugEnabled() == true {
-		d := sqlutil.Debug{query, args, err}
+		d := sqlutil.Debug{query, args, err, start, end}
 		d.Print()
 	}
 }
@@ -114,13 +114,16 @@ func init() {
 }
 
 func (self *source) doExec(stmt sqlgen.Statement, args ...interface{}) (sql.Result, error) {
-
 	var query string
 	var res sql.Result
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -159,9 +162,13 @@ func (self *source) doQuery(stmt sqlgen.Statement, args ...interface{}) (*sql.Ro
 	var rows *sql.Rows
 	var query string
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -200,9 +207,13 @@ func (self *source) doQueryRow(stmt sqlgen.Statement, args ...interface{}) (*sql
 	var query string
 	var row *sql.Row
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
diff --git a/sqlite/database.go b/sqlite/database.go
index d923092d..59e7523a 100644
--- a/sqlite/database.go
+++ b/sqlite/database.go
@@ -26,6 +26,7 @@ import (
 	"fmt"
 	"os"
 	"strings"
+	"time"
 
 	_ "github.com/mattn/go-sqlite3"
 	"upper.io/db"
@@ -67,9 +68,9 @@ func debugEnabled() bool {
 	return false
 }
 
-func debugLog(query string, args []interface{}, err error) {
+func debugLog(query string, args []interface{}, err error, start int64, end int64) {
 	if debugEnabled() == true {
-		d := sqlutil.Debug{query, args, err}
+		d := sqlutil.Debug{query, args, err, start, end}
 		d.Print()
 	}
 }
@@ -113,9 +114,13 @@ func (self *source) doExec(stmt sqlgen.Statement, args ...interface{}) (sql.Resu
 	var query string
 	var res sql.Result
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -137,9 +142,13 @@ func (self *source) doQuery(stmt sqlgen.Statement, args ...interface{}) (*sql.Ro
 	var rows *sql.Rows
 	var query string
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -161,9 +170,13 @@ func (self *source) doQueryRow(stmt sqlgen.Statement, args ...interface{}) (*sql
 	var query string
 	var row *sql.Row
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
@@ -184,9 +197,13 @@ func (self *source) doQueryRow(stmt sqlgen.Statement, args ...interface{}) (*sql
 func (self *source) doRawQuery(query string, args ...interface{}) (*sql.Rows, error) {
 	var rows *sql.Rows
 	var err error
+	var start, end int64
+
+	start = time.Now().UnixNano()
 
 	defer func() {
-		debugLog(query, args, err)
+		end = time.Now().UnixNano()
+		debugLog(query, args, err, start, end)
 	}()
 
 	if self.session == nil {
diff --git a/util/sqlutil/main.go b/util/sqlutil/main.go
index c28f99b0..cd909862 100644
--- a/util/sqlutil/main.go
+++ b/util/sqlutil/main.go
@@ -43,9 +43,11 @@ type T struct {
 }
 
 type Debug struct {
-	SQL  string
-	Args []interface{}
-	Err  error
+	SQL   string
+	Args  []interface{}
+	Err   error
+	Start int64
+	End   int64
 }
 
 func (self *Debug) Print() {
@@ -55,17 +57,19 @@ func (self *Debug) Print() {
 	s := make([]string, 0, 3)
 
 	if self.SQL != "" {
-		s = append(s, fmt.Sprintf(`SQL: %s`, self.SQL))
+		s = append(s, fmt.Sprintf(`Q: %s`, self.SQL))
 	}
 
 	if len(self.Args) > 0 {
-		s = append(s, fmt.Sprintf(`ARG: %v`, self.Args))
+		s = append(s, fmt.Sprintf(`A: %v`, self.Args))
 	}
 
 	if self.Err != nil {
-		s = append(s, fmt.Sprintf(`ERR: %q`, self.Err))
+		s = append(s, fmt.Sprintf(`E: %q`, self.Err))
 	}
 
+	s = append(s, fmt.Sprintf(`T: %0.5fs`, float64(self.End-self.Start)/float64(1e9)))
+
 	log.Printf("\n\t%s\n\n", strings.Join(s, "\n\t"))
 }
 
-- 
GitLab