refactored logging

README.md

@@ -686,8 +686,14 @@ fmt.Println(err)
 
 ## Logging Executed SQL Statements
 
-When `DB.LogFunc` is configured with a compatible log function, all SQL statements being executed will be logged.
-The following example shows how to configure the logger using the standard `log` package:
+You can log and instrument DB queries by installing loggers with a DB connection. There are three kinds of loggers you
+can install:
+* `DB.LogFunc`: this is called each time when a SQL statement is queried or executed. The function signature is the
+  same as that of `fmt.Printf`, which makes it very easy to use. 
+* `DB.QueryLogFunc`: this is called each time when querying with a SQL statement.
+* `DB.ExecLogFunc`: this is called when executing a SQL statement.
+
+The following example shows how you can make use of these loggers.
 
 ```go
 import (
@@ -698,37 +704,20 @@ import (
 
 func main() {
 	db, _ := dbx.Open("mysql", "user:pass@/example")
-	db.LogFunc = log.Printf
-
-	// ...
-)
-```
-
-You can also configure `DB.PerfFunc` to capture the SQL statement execution times. Each time when a SQL statement
-is executed or queried, this function will be called with the time used. This allows you to profile your DB performance.
-
-The following example shows how to use the `ozzo-log` package which allows logging message severities and categories
-and sending logged messages to different targets (e.g. files, console window, network).
-
-```go
-import (
-	"fmt"
-	"github.com/go-ozzo/ozzo-dbx"
-	"github.com/go-ozzo/ozzo-log"
-	_ "github.com/go-sql-driver/mysql"
-)
-
-func main() {
-	logger := log.NewLogger()
-	logger.Targets = []log.Target{log.NewConsoleTarget()}
-	logger.Open()
 
-	db, _ := dbx.Open("mysql", "user:pass@/example")
-	db.LogFunc = logger.Info
+	// simple logging
+	db.LogFunc = log.Printf
 
+	// or you can use the following more flexible logging
+	db.QueryLogFunc = func(ctx context.Context, t time.Duration, sql string, rows *sql.Rows, err error) {
+		log.Printf("[%.2fms] Query SQL: %v", float64(t.Milliseconds()), sql))
+	}
+	db.ExecLogFunc = func(ctx context.Context, t time.Duration, sql string, result sql.Result, err error) {
+		log.Printf("[%.2fms] Execute SQL: %v", float64(t.Milliseconds()), sql))
+	}
 	// ...
 )
-```
+``` 
 
 ## Supporting New Databases
 

db.go

@@ -49,7 +49,6 @@ type (
 		// FieldMapper maps struct fields to DB columns. Defaults to DefaultFieldMapFunc.
 		FieldMapper FieldMapFunc
 		// LogFunc logs the SQL statements being executed. Defaults to nil, meaning no logging.
-		// Deprecated: Please use QueryLogFunc and ExecLogFunc instead.
 		LogFunc LogFunc
 		// PerfFunc logs the SQL execution time. Defaults to nil, meaning no performance profiling.
 		// Deprecated: Please use QueryLogFunc and ExecLogFunc instead.

query.go

@@ -49,7 +49,6 @@ type Query struct {
 	// LastError is cleared by Execute(), Row(), Rows(), One(), and All().
 	LastError error
 	// LogFunc is used to log the SQL statement being executed.
-	// Deprecated: Please use QueryLogFunc and ExecLogFunc instead.
 	LogFunc LogFunc
 	// PerfFunc is used to log the SQL execution time. It is ignored if nil.
 	// Deprecated: Please use QueryLogFunc and ExecLogFunc instead.
@@ -116,25 +115,6 @@ func (q *Query) logSQL() string {
 	return s
 }
 
-// log logs a message for the currently executed SQL statement.
-func (q *Query) log(start time.Time, execute bool) {
-	if q.LogFunc == nil && q.PerfFunc == nil {
-		return
-	}
-	ns := time.Now().Sub(start).Nanoseconds()
-	s := q.logSQL()
-	if q.LogFunc != nil {
-		if execute {
-			q.LogFunc("[%.2fms] Execute SQL: %v", float64(ns)/1e6, s)
-		} else {
-			q.LogFunc("[%.2fms] Query SQL: %v", float64(ns)/1e6, s)
-		}
-	}
-	if q.PerfFunc != nil {
-		q.PerfFunc(ns, s, execute)
-	}
-}
-
 // Params returns the parameters to be bound to the SQL statement represented by this query.
 func (q *Query) Params() Params {
 	return q.params
@@ -192,7 +172,6 @@ func (q *Query) Execute() (result sql.Result, err error) {
 	}
 
 	start := time.Now()
-	defer q.log(start, true)
 
 	if q.ctx == nil {
 		if q.stmt == nil {
@@ -211,6 +190,12 @@ func (q *Query) Execute() (result sql.Result, err error) {
 	if q.ExecLogFunc != nil {
 		q.ExecLogFunc(q.ctx, time.Now().Sub(start), q.logSQL(), result, err)
 	}
+	if q.LogFunc != nil {
+		q.LogFunc("[%.2fms] Execute SQL: %v", float64(time.Now().Sub(start).Milliseconds()), q.logSQL())
+	}
+	if q.PerfFunc != nil {
+		q.PerfFunc(time.Now().Sub(start).Nanoseconds(), q.logSQL(), true)
+	}
 	return
 }
 
@@ -274,7 +259,6 @@ func (q *Query) Rows() (rows *Rows, err error) {
 	}
 
 	start := time.Now()
-	defer q.log(start, false)
 
 	var rr *sql.Rows
 	if q.ctx == nil {
@@ -295,6 +279,12 @@ func (q *Query) Rows() (rows *Rows, err error) {
 	if q.QueryLogFunc != nil {
 		q.QueryLogFunc(q.ctx, time.Now().Sub(start), q.logSQL(), rr, err)
 	}
+	if q.LogFunc != nil {
+		q.LogFunc("[%.2fms] Query SQL: %v", float64(time.Now().Sub(start).Milliseconds()), q.logSQL())
+	}
+	if q.PerfFunc != nil {
+		q.PerfFunc(time.Now().Sub(start).Nanoseconds(), q.logSQL(), false)
+	}
 	return
 }