Add log track on prepare & tx

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
 	}

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) {

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
 }

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
 }