orm add queries debug logger

orm/db.go

@@ -527,7 +527,7 @@ func (d *dbBase) collectValues(mi *modelInfo, ind reflect.Value, skipAuto bool,
 	return
 }
 
-func (d *dbBase) PrepareInsert(q dbQuerier, mi *modelInfo) (*sql.Stmt, error) {
+func (d *dbBase) PrepareInsert(q dbQuerier, mi *modelInfo) (stmtQuerier, string, error) {
 	dbcols := make([]string, 0, len(mi.fields.dbcols))
 	marks := make([]string, 0, len(mi.fields.dbcols))
 	for _, fi := range mi.fields.fieldsDB {
@@ -540,10 +540,11 @@ func (d *dbBase) PrepareInsert(q dbQuerier, mi *modelInfo) (*sql.Stmt, error) {
 	columns := strings.Join(dbcols, "`,`")
 
 	query := fmt.Sprintf("INSERT INTO `%s` (`%s`) VALUES (%s)", mi.table, columns, qmarks)
-	return q.Prepare(query)
+	stmt, err := q.Prepare(query)
+	return stmt, query, err
 }
 
-func (d *dbBase) InsertStmt(stmt *sql.Stmt, mi *modelInfo, ind reflect.Value) (int64, error) {
+func (d *dbBase) InsertStmt(stmt stmtQuerier, mi *modelInfo, ind reflect.Value) (int64, error) {
 	_, values, err := d.collectValues(mi, ind, true, true)
 	if err != nil {
 		return 0, err

orm/models.go

@@ -1,8 +1,6 @@
 package orm
 
 import (
-	"log"
-	"os"
 	"sync"
 )
 
@@ -15,7 +13,6 @@ const (
 )
 
 var (
-	errLog     *log.Logger
 	modelCache = &_modelCache{
 		cache:     make(map[string]*modelInfo),
 		cacheByFN: make(map[string]*modelInfo),
@@ -44,10 +41,6 @@ var (
 	}
 )
 
-func init() {
-	errLog = log.New(os.Stderr, "[ORM] ", log.Ldate|log.Ltime|log.Lshortfile)
-}
-
 type _modelCache struct {
 	sync.RWMutex
 	orders    []string

orm/models_test.go

@@ -97,9 +97,11 @@ func NewComment() *Comment {
 var DBARGS = struct {
 	Driver string
 	Source string
+	Debug  string
 }{
 	os.Getenv("ORM_DRIVER"),
 	os.Getenv("ORM_SOURCE"),
+	os.Getenv("ORM_DEBUG"),
 }
 
 var dORM Ormer
@@ -111,6 +113,8 @@ func init() {
 	RegisterModel(new(Tag))
 	RegisterModel(new(Comment))
 
+	Debug, _ = StrTo(DBARGS.Debug).Bool()
+
 	if DBARGS.Driver == "" || DBARGS.Source == "" {
 		fmt.Println(`need driver and source!
 

orm/orm.go

@@ -4,18 +4,26 @@ import (
 	"database/sql"
 	"errors"
 	"fmt"
+	"os"
 	"reflect"
 	"time"
 )
 
+const (
+	Debug_Queries = iota
+)
+
 var (
+	// DebugLevel       = Debug_Queries
+	Debug            = true
+	DebugLog         = NewLog(os.Stderr)
 	DefaultRowsLimit = 1000
 	DefaultRelsDepth = 5
 	DefaultTimeLoc   = time.Local
 	ErrTxHasBegan    = errors.New("<Ormer.Begin> transaction already begin")
 	ErrTxDone        = errors.New("<Ormer.Commit/Rollback> transaction not begin")
 	ErrMultiRows     = errors.New("<QuerySeter> return multi rows")
-	ErrNoRows        = errors.New("<QuerySeter> not row found")
+	ErrNoRows        = errors.New("<QuerySeter> no row found")
 	ErrStmtClosed    = errors.New("<QuerySeter> stmt already closed")
 	ErrNotImplement  = errors.New("have not implement")
 )
@@ -124,7 +132,11 @@ func (o *orm) Using(name string) error {
 	}
 	if al, ok := dataBaseCache.get(name); ok {
 		o.alias = al
+		if Debug {
+			o.db = newDbQueryLog(al, al.DB)
+		} else {
 			o.db = al.DB
+		}
 	} else {
 		return errors.New(fmt.Sprintf("<orm.Using> unknown db alias name `%s`", name))
 	}
@@ -135,12 +147,17 @@ func (o *orm) Begin() error {
 	if o.isTx {
 		return ErrTxHasBegan
 	}
-	tx, err := o.alias.DB.Begin()
+	var tx *sql.Tx
+	tx, err := o.db.(txer).Begin()
 	if err != nil {
 		return err
 	}
 	o.isTx = true
+	if Debug {
+		o.db.(*dbQueryLog).SetDB(tx)
+	} else {
 		o.db = tx
+	}
 	return nil
 }
 
@@ -148,10 +165,10 @@ func (o *orm) Commit() error {
 	if o.isTx == false {
 		return ErrTxDone
 	}
-	err := o.db.(*sql.Tx).Commit()
+	err := o.db.(txEnder).Commit()
 	if err == nil {
 		o.isTx = false
-		o.db = o.alias.DB
+		o.Using(o.alias.Name)
 	} else if err == sql.ErrTxDone {
 		return ErrTxDone
 	}
@@ -162,10 +179,10 @@ func (o *orm) Rollback() error {
 	if o.isTx == false {
 		return ErrTxDone
 	}
-	err := o.db.(*sql.Tx).Rollback()
+	err := o.db.(txEnder).Rollback()
 	if err == nil {
 		o.isTx = false
-		o.db = o.alias.DB
+		o.Using(o.alias.Name)
 	} else if err == sql.ErrTxDone {
 		return ErrTxDone
 	}

orm/orm_log.go

@@ -0,0 +1,152 @@
+package orm
+
+import (
+	"database/sql"
+	"fmt"
+	"io"
+	"log"
+	"strings"
+	"time"
+)
+
+type Log struct {
+	*log.Logger
+}
+
+func NewLog(out io.Writer) *Log {
+	d := new(Log)
+	d.Logger = log.New(out, "[ORM]", 1e9)
+	return d
+}
+
+func debugLogQueies(alias *alias, operaton, query string, t time.Time, err error, args ...interface{}) {
+	sub := time.Now().Sub(t) / 1e5
+	elsp := float64(int(sub)) / 10.0
+	con := fmt.Sprintf(" - %s - [Queries/%s] - [%11s / %7.1fms] - [%s]", t.Format(format_DateTime), alias.Name, operaton, elsp, query)
+	cons := make([]string, 0, len(args))
+	for _, arg := range args {
+		cons = append(cons, fmt.Sprintf("%v", arg))
+	}
+	if len(cons) > 0 {
+		con += fmt.Sprintf(" - `%s`", strings.Join(cons, "`, `"))
+	}
+	if err != nil {
+		con += " - " + err.Error()
+	}
+	DebugLog.Println(con)
+}
+
+type stmtQueryLog struct {
+	alias *alias
+	query string
+	stmt  stmtQuerier
+}
+
+var _ stmtQuerier = new(stmtQueryLog)
+
+func (d *stmtQueryLog) Close() error {
+	a := time.Now()
+	err := d.stmt.Close()
+	debugLogQueies(d.alias, "st.Close", d.query, a, err)
+	return err
+}
+
+func (d *stmtQueryLog) Exec(args ...interface{}) (sql.Result, error) {
+	a := time.Now()
+	res, err := d.stmt.Exec(args...)
+	debugLogQueies(d.alias, "st.Exec", d.query, a, err, args...)
+	return res, err
+}
+
+func (d *stmtQueryLog) Query(args ...interface{}) (*sql.Rows, error) {
+	a := time.Now()
+	res, err := d.stmt.Query(args...)
+	debugLogQueies(d.alias, "st.Query", d.query, a, err, args...)
+	return res, err
+}
+
+func (d *stmtQueryLog) QueryRow(args ...interface{}) *sql.Row {
+	a := time.Now()
+	res := d.stmt.QueryRow(args...)
+	debugLogQueies(d.alias, "st.QueryRow", d.query, a, nil, args...)
+	return res
+}
+
+func newStmtQueryLog(alias *alias, stmt stmtQuerier, query string) stmtQuerier {
+	d := new(stmtQueryLog)
+	d.stmt = stmt
+	d.alias = alias
+	d.query = query
+	return d
+}
+
+type dbQueryLog struct {
+	alias *alias
+	db    dbQuerier
+	tx    txer
+	txe   txEnder
+}
+
+var _ dbQuerier = new(dbQueryLog)
+var _ txer = new(dbQueryLog)
+var _ txEnder = new(dbQueryLog)
+
+func (d *dbQueryLog) Prepare(query string) (*sql.Stmt, error) {
+	a := time.Now()
+	stmt, err := d.db.Prepare(query)
+	debugLogQueies(d.alias, "db.Prepare", query, a, err)
+	return stmt, err
+}
+
+func (d *dbQueryLog) Exec(query string, args ...interface{}) (sql.Result, error) {
+	a := time.Now()
+	res, err := d.db.Exec(query, args...)
+	debugLogQueies(d.alias, "db.Exec", query, a, err, args...)
+	return res, err
+}
+
+func (d *dbQueryLog) Query(query string, args ...interface{}) (*sql.Rows, error) {
+	a := time.Now()
+	res, err := d.db.Query(query, args...)
+	debugLogQueies(d.alias, "db.Query", query, a, err, args...)
+	return res, err
+}
+
+func (d *dbQueryLog) QueryRow(query string, args ...interface{}) *sql.Row {
+	a := time.Now()
+	res := d.db.QueryRow(query, args...)
+	debugLogQueies(d.alias, "db.QueryRow", query, a, nil, args...)
+	return res
+}
+
+func (d *dbQueryLog) Begin() (*sql.Tx, error) {
+	a := time.Now()
+	tx, err := d.db.(txer).Begin()
+	debugLogQueies(d.alias, "db.Begin", "START TRANSACTION", a, err)
+	return tx, err
+}
+
+func (d *dbQueryLog) Commit() error {
+	a := time.Now()
+	err := d.db.(txEnder).Commit()
+	debugLogQueies(d.alias, "tx.Commit", "COMMIT", a, err)
+	return err
+}
+
+func (d *dbQueryLog) Rollback() error {
+	a := time.Now()
+	err := d.db.(txEnder).Commit()
+	debugLogQueies(d.alias, "tx.Rollback", "ROLLBACK", a, err)
+	return err
+}
+
+func (d *dbQueryLog) SetDB(db dbQuerier) {
+	d.db = db
+}
+
+func newDbQueryLog(alias *alias, db dbQuerier) dbQuerier {
+	d := new(dbQueryLog)
+	d.alias = alias
+	d.db = db
+	return d
+}

orm/orm_object.go

@@ -1,7 +1,6 @@
 package orm
 
 import (
-	"database/sql"
 	"fmt"
 	"reflect"
 )
@@ -9,7 +8,7 @@ import (
 type insertSet struct {
 	mi     *modelInfo
 	orm    *orm
-	stmt   *sql.Stmt
+	stmt   stmtQuerier
 	closed bool
 }
 
@@ -49,10 +48,14 @@ func newInsertSet(orm *orm, mi *modelInfo) (Inserter, error) {
 	bi := new(insertSet)
 	bi.orm = orm
 	bi.mi = mi
-	st, err := orm.alias.DbBaser.PrepareInsert(orm.db, mi)
+	st, query, err := orm.alias.DbBaser.PrepareInsert(orm.db, mi)
 	if err != nil {
 		return nil, err
 	}
+	if Debug {
+		bi.stmt = newStmtQueryLog(orm.alias, st, query)
+	} else {
 		bi.stmt = st
+	}
 	return bi, nil
 }

orm/orm_raw.go

@@ -26,7 +26,7 @@ func getResult(res sql.Result) (int64, error) {
 
 type rawPrepare struct {
 	rs     *rawSet
-	stmt   *sql.Stmt
+	stmt   stmtQuerier
 	closed bool
 }
 
@@ -53,7 +53,11 @@ func newRawPreparer(rs *rawSet) (RawPreparer, error) {
 	if err != nil {
 		return nil, err
 	}
+	if Debug {
+		o.stmt = newStmtQueryLog(rs.orm.alias, st, rs.query)
+	} else {
 		o.stmt = st
+	}
 	return o, nil
 }
 

orm/types.go

@@ -94,6 +94,13 @@ type IFieldErrors interface {
 	List() []IFieldError
 }
 
+type stmtQuerier interface {
+	Close() error
+	Exec(args ...interface{}) (sql.Result, error)
+	Query(args ...interface{}) (*sql.Rows, error)
+	QueryRow(args ...interface{}) *sql.Row
+}
+
 type dbQuerier interface {
 	Prepare(query string) (*sql.Stmt, error)
 	Exec(query string, args ...interface{}) (sql.Result, error)
@@ -101,10 +108,19 @@ type dbQuerier interface {
 	QueryRow(query string, args ...interface{}) *sql.Row
 }
 
+type txer interface {
+	Begin() (*sql.Tx, error)
+}
+
+type txEnder interface {
+	Commit() error
+	Rollback() error
+}
+
 type dbBaser interface {
 	Read(dbQuerier, *modelInfo, reflect.Value) error
 	Insert(dbQuerier, *modelInfo, reflect.Value) (int64, error)
-	InsertStmt(*sql.Stmt, *modelInfo, reflect.Value) (int64, error)
+	InsertStmt(stmtQuerier, *modelInfo, reflect.Value) (int64, error)
 	Update(dbQuerier, *modelInfo, reflect.Value) (int64, error)
 	Delete(dbQuerier, *modelInfo, reflect.Value) (int64, error)
 	ReadBatch(dbQuerier, *querySet, *modelInfo, *Condition, interface{}) (int64, error)
@@ -112,6 +128,6 @@ type dbBaser interface {
 	DeleteBatch(dbQuerier, *querySet, *modelInfo, *Condition) (int64, error)
 	Count(dbQuerier, *querySet, *modelInfo, *Condition) (int64, error)
 	GetOperatorSql(*modelInfo, string, []interface{}) (string, []interface{})
-	PrepareInsert(dbQuerier, *modelInfo) (*sql.Stmt, error)
+	PrepareInsert(dbQuerier, *modelInfo) (stmtQuerier, string, error)
 	ReadValues(dbQuerier, *querySet, *modelInfo, *Condition, []string, interface{}) (int64, error)
 }