From 45aa07126106166ddf1655bb88d0b1110293bdb6 Mon Sep 17 00:00:00 2001 From: slene Date: Fri, 9 Aug 2013 13:20:19 +0800 Subject: [PATCH] orm add queries debug logger --- orm/db.go | 7 ++- orm/models.go | 7 --- orm/models_test.go | 4 ++ orm/orm.go | 33 +++++++--- orm/orm_log.go | 152 +++++++++++++++++++++++++++++++++++++++++++++ orm/orm_object.go | 11 ++-- orm/orm_raw.go | 8 ++- orm/types.go | 20 +++++- 8 files changed, 216 insertions(+), 26 deletions(-) create mode 100644 orm/orm_log.go diff --git a/orm/db.go b/orm/db.go index 9f1493ed..77c457ad 100644 --- a/orm/db.go +++ b/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 diff --git a/orm/models.go b/orm/models.go index d2fa9a99..57099089 100644 --- a/orm/models.go +++ b/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 diff --git a/orm/models_test.go b/orm/models_test.go index 2003553b..de611916 100644 --- a/orm/models_test.go +++ b/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! diff --git a/orm/orm.go b/orm/orm.go index ddf8d8a9..da6b827c 100644 --- a/orm/orm.go +++ b/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(" transaction already begin") ErrTxDone = errors.New(" transaction not begin") ErrMultiRows = errors.New(" return multi rows") - ErrNoRows = errors.New(" not row found") + ErrNoRows = errors.New(" no row found") ErrStmtClosed = errors.New(" 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 - o.db = al.DB + if Debug { + o.db = newDbQueryLog(al, al.DB) + } else { + o.db = al.DB + } } else { return errors.New(fmt.Sprintf(" 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 - o.db = tx + 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 } diff --git a/orm/orm_log.go b/orm/orm_log.go new file mode 100644 index 00000000..30be1152 --- /dev/null +++ b/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 +} diff --git a/orm/orm_object.go b/orm/orm_object.go index 927ebbd7..b5935f1a 100644 --- a/orm/orm_object.go +++ b/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 } - bi.stmt = st + if Debug { + bi.stmt = newStmtQueryLog(orm.alias, st, query) + } else { + bi.stmt = st + } return bi, nil } diff --git a/orm/orm_raw.go b/orm/orm_raw.go index 47c068fa..af2d62e6 100644 --- a/orm/orm_raw.go +++ b/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 } - o.stmt = st + if Debug { + o.stmt = newStmtQueryLog(rs.orm.alias, st, rs.query) + } else { + o.stmt = st + } return o, nil } diff --git a/orm/types.go b/orm/types.go index 7fda4488..01ac92ca 100644 --- a/orm/types.go +++ b/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) }