From 046c6bc7e56ecf2879dc26b00fe8e6bba5149997 Mon Sep 17 00:00:00 2001 From: Lunny Xiao Date: Sat, 29 Feb 2020 14:51:42 +0800 Subject: [PATCH] Add log track on prepare & tx --- core/stmt.go | 59 +++++++++++++++++++++- core/tx.go | 38 +++++++++++--- dialects/dialect.go | 5 -- session_tx.go | 117 ++++++++++++++++++++++++++++---------------- 4 files changed, 164 insertions(+), 55 deletions(-) diff --git a/core/stmt.go b/core/stmt.go index 366a9350..d3c46977 100644 --- a/core/stmt.go +++ b/core/stmt.go @@ -9,6 +9,9 @@ import ( "database/sql" "errors" "reflect" + "time" + + "xorm.io/xorm/log" ) // Stmt reprents a stmt objects @@ -16,6 +19,7 @@ type Stmt struct { *sql.Stmt db *DB names map[string]int + query string } func (db *DB) PrepareContext(ctx context.Context, query string) (*Stmt, error) { @@ -27,11 +31,27 @@ func (db *DB) PrepareContext(ctx context.Context, query string) (*Stmt, error) { return "?" }) + start := time.Now() + if db.Logger != nil { + db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: "PREPARE", + }) + } stmt, err := db.DB.PrepareContext(ctx, query) + if db.Logger != nil { + db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: "PREPARE", + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + } if err != nil { return nil, err } - return &Stmt{stmt, db, names}, nil + + return &Stmt{stmt, db, names, query}, nil } func (db *DB) Prepare(query string) (*Stmt, error) { @@ -73,11 +93,46 @@ func (s *Stmt) ExecStruct(st interface{}) (sql.Result, error) { } func (s *Stmt) ExecContext(ctx context.Context, args ...interface{}) (sql.Result, error) { - return s.Stmt.ExecContext(ctx, args) + start := time.Now() + if s.db.Logger != nil { + s.db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: s.query, + Args: args, + }) + } + res, err := s.Stmt.ExecContext(ctx, args) + if s.db.Logger != nil { + s.db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: s.query, + Args: args, + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + } + return res, err } func (s *Stmt) QueryContext(ctx context.Context, args ...interface{}) (*Rows, error) { + start := time.Now() + if s.db.Logger != nil { + s.db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: s.query, + Args: args, + }) + } rows, err := s.Stmt.QueryContext(ctx, args...) + if s.db.Logger != nil { + s.db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: s.query, + Args: args, + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + } if err != nil { return nil, err } diff --git a/core/tx.go b/core/tx.go index 614213c9..10022efc 100644 --- a/core/tx.go +++ b/core/tx.go @@ -18,7 +18,22 @@ type Tx struct { } func (db *DB) BeginTx(ctx context.Context, opts *sql.TxOptions) (*Tx, error) { + start := time.Now() + if db.Logger != nil { + db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: "BEGIN TRANSACTION", + }) + } tx, err := db.DB.BeginTx(ctx, opts) + if db.Logger != nil { + db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: "BEGIN TRANSACTION", + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + } if err != nil { return nil, err } @@ -26,11 +41,7 @@ func (db *DB) BeginTx(ctx context.Context, opts *sql.TxOptions) (*Tx, error) { } func (db *DB) Begin() (*Tx, error) { - tx, err := db.DB.Begin() - if err != nil { - return nil, err - } - return &Tx{tx, db}, nil + return db.BeginTx(context.Background(), nil) } func (tx *Tx) PrepareContext(ctx context.Context, query string) (*Stmt, error) { @@ -42,11 +53,26 @@ func (tx *Tx) PrepareContext(ctx context.Context, query string) (*Stmt, error) { return "?" }) + start := time.Now() + if tx.db.Logger != nil { + tx.db.Logger.BeforeSQL(log.LogContext{ + Ctx: ctx, + SQL: "PREPARE", + }) + } stmt, err := tx.Tx.PrepareContext(ctx, query) + if tx.db.Logger != nil { + tx.db.Logger.AfterSQL(log.LogContext{ + Ctx: ctx, + SQL: "PREPARE", + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + } if err != nil { return nil, err } - return &Stmt{stmt, tx.db, names}, nil + return &Stmt{stmt, tx.db, names, query}, nil } func (tx *Tx) Prepare(query string) (*Stmt, error) { diff --git a/dialects/dialect.go b/dialects/dialect.go index 5efd1da4..a0139d9f 100644 --- a/dialects/dialect.go +++ b/dialects/dialect.go @@ -45,7 +45,6 @@ type Dialect interface { IsReserved(string) bool Quoter() schemas.Quoter - RollBackStr() string AutoIncrStr() string SupportInsertMany() bool @@ -178,10 +177,6 @@ func (b *Base) DataSourceName() string { return b.dataSourceName } -func (db *Base) RollBackStr() string { - return "ROLL BACK" -} - func (db *Base) SupportDropIfExists() bool { return true } diff --git a/session_tx.go b/session_tx.go index ee3d473f..6da9ecb4 100644 --- a/session_tx.go +++ b/session_tx.go @@ -4,6 +4,12 @@ package xorm +import ( + "time" + + "xorm.io/xorm/log" +) + // Begin a transaction func (session *Session) Begin() error { if session.isAutoCommit { @@ -14,6 +20,7 @@ func (session *Session) Begin() error { session.isAutoCommit = false session.isCommitedOrRollbacked = false session.tx = tx + session.saveLastSQL("BEGIN TRANSACTION") } return nil @@ -22,10 +29,23 @@ func (session *Session) Begin() error { // Rollback When using transaction, you can rollback if any error func (session *Session) Rollback() error { if !session.isAutoCommit && !session.isCommitedOrRollbacked { - session.saveLastSQL(session.engine.dialect.RollBackStr()) + session.saveLastSQL("ROLL BACK") session.isCommitedOrRollbacked = true session.isAutoCommit = true - return session.tx.Rollback() + + start := time.Now() + session.engine.logger.BeforeSQL(log.LogContext{ + Ctx: session.ctx, + SQL: "ROLL BACK", + }) + err := session.tx.Rollback() + session.engine.logger.AfterSQL(log.LogContext{ + Ctx: session.ctx, + SQL: "ROLL BACK", + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + return err } return nil } @@ -36,48 +56,61 @@ func (session *Session) Commit() error { session.saveLastSQL("COMMIT") session.isCommitedOrRollbacked = true session.isAutoCommit = true - var err error - if err = session.tx.Commit(); err == nil { - // handle processors after tx committed - closureCallFunc := func(closuresPtr *[]func(interface{}), bean interface{}) { - if closuresPtr != nil { - for _, closure := range *closuresPtr { - closure(bean) - } - } - } - for bean, closuresPtr := range session.afterInsertBeans { - closureCallFunc(closuresPtr, bean) - - if processor, ok := interface{}(bean).(AfterInsertProcessor); ok { - processor.AfterInsert() - } - } - for bean, closuresPtr := range session.afterUpdateBeans { - closureCallFunc(closuresPtr, bean) - - if processor, ok := interface{}(bean).(AfterUpdateProcessor); ok { - processor.AfterUpdate() - } - } - for bean, closuresPtr := range session.afterDeleteBeans { - closureCallFunc(closuresPtr, bean) - - if processor, ok := interface{}(bean).(AfterDeleteProcessor); ok { - processor.AfterDelete() - } - } - cleanUpFunc := func(slices *map[interface{}]*[]func(interface{})) { - if len(*slices) > 0 { - *slices = make(map[interface{}]*[]func(interface{}), 0) - } - } - cleanUpFunc(&session.afterInsertBeans) - cleanUpFunc(&session.afterUpdateBeans) - cleanUpFunc(&session.afterDeleteBeans) + start := time.Now() + session.engine.logger.BeforeSQL(log.LogContext{ + Ctx: session.ctx, + SQL: "COMMIT", + }) + err := session.tx.Commit() + if err != nil { + return err } - return err + session.engine.logger.AfterSQL(log.LogContext{ + Ctx: session.ctx, + SQL: "COMMIT", + ExecuteTime: time.Now().Sub(start), + Err: err, + }) + + // handle processors after tx committed + closureCallFunc := func(closuresPtr *[]func(interface{}), bean interface{}) { + if closuresPtr != nil { + for _, closure := range *closuresPtr { + closure(bean) + } + } + } + + for bean, closuresPtr := range session.afterInsertBeans { + closureCallFunc(closuresPtr, bean) + + if processor, ok := interface{}(bean).(AfterInsertProcessor); ok { + processor.AfterInsert() + } + } + for bean, closuresPtr := range session.afterUpdateBeans { + closureCallFunc(closuresPtr, bean) + + if processor, ok := interface{}(bean).(AfterUpdateProcessor); ok { + processor.AfterUpdate() + } + } + for bean, closuresPtr := range session.afterDeleteBeans { + closureCallFunc(closuresPtr, bean) + + if processor, ok := interface{}(bean).(AfterDeleteProcessor); ok { + processor.AfterDelete() + } + } + cleanUpFunc := func(slices *map[interface{}]*[]func(interface{})) { + if len(*slices) > 0 { + *slices = make(map[interface{}]*[]func(interface{}), 0) + } + } + cleanUpFunc(&session.afterInsertBeans) + cleanUpFunc(&session.afterUpdateBeans) + cleanUpFunc(&session.afterDeleteBeans) } return nil }