add Engine.LogSQLQueryTime and Engine.LogSQLExecutionTime for SQL execution time logging

engine.go

@@ -183,13 +183,37 @@ func (engine *Engine) Ping() error {
 func (engine *Engine) logSQL(sqlStr string, sqlArgs ...interface{}) {
 	if engine.ShowSQL {
 		if len(sqlArgs) > 0 {
-			engine.Logger.Info(fmt.Sprintln("[sql]", sqlStr, "[args]", sqlArgs))
+			engine.Logger.Info(fmt.Sprintf("[sql]", sqlStr, "[args]", sqlArgs))
 		} else {
-			engine.Logger.Info(fmt.Sprintln("[sql]", sqlStr))
+			engine.Logger.Info(fmt.Sprintf("[sql]", sqlStr))
 		}
 	}
 }
 
+func (engine *Engine) LogSQLQueryTime(sqlStr string, args interface{}, executionBlock func() (*core.Stmt, *core.Rows, error)) (*core.Stmt, *core.Rows, error) {
+	if engine.ShowDebug {
+		b4ExecTime := time.Now()
+		stmt, res, err := executionBlock()
+		execDuration := time.Since(b4ExecTime)
+		engine.LogDebugf("sql [%s] - args [%v] - query took: %vns", sqlStr, args, execDuration.Nanoseconds())
+		return stmt, res, err
+	} else {
+		return executionBlock()
+	}
+}
+
+func (engine *Engine) LogSQLExecutionTime(sqlStr string, args interface{}, executionBlock func() (sql.Result, error)) (sql.Result, error) {
+	if engine.ShowDebug {
+		b4ExecTime := time.Now()
+		res, err := executionBlock()
+		execDuration := time.Since(b4ExecTime)
+		engine.LogDebugf("sql [%s] - args [%v] - execution took: %vns", sqlStr, args, execDuration.Nanoseconds())
+		return res, err
+	} else {
+		return executionBlock()
+	}
+}
+
 // logging error
 func (engine *Engine) LogError(contents ...interface{}) {
 	if engine.ShowErr {

session.go

@@ -452,10 +452,12 @@ func (session *Session) exec(sqlStr string, args ...interface{}) (sql.Result, er
 
 	session.Engine.logSQL(sqlStr, args...)
 
+	return session.Engine.LogSQLExecutionTime(sqlStr, args, func() (sql.Result, error) {
 		if session.IsAutoCommit {
 			return session.innerExec(sqlStr, args...)
 		}
 		return session.Tx.Exec(sqlStr, args...)
+	})
 }
 
 // Exec raw sql
@@ -1761,15 +1763,16 @@ func (session *Session) queryPreprocess(sqlStr *string, paramStr ...interface{})
 }
 
 func (session *Session) query(sqlStr string, paramStr ...interface{}) (resultsSlice []map[string][]byte, err error) {
+
 	session.queryPreprocess(&sqlStr, paramStr...)
 
 	if session.IsAutoCommit {
-		return query(session.Db, sqlStr, paramStr...)
+		return session.innerQuery(session.Db, sqlStr, paramStr...)
 	}
-	return txQuery(session.Tx, sqlStr, paramStr...)
+	return session.txQuery(session.Tx, sqlStr, paramStr...)
 }
 
-func txQuery(tx *core.Tx, sqlStr string, params ...interface{}) (resultsSlice []map[string][]byte, err error) {
+func (session *Session) txQuery(tx *core.Tx, sqlStr string, params ...interface{}) (resultsSlice []map[string][]byte, err error) {
 	rows, err := tx.Query(sqlStr, params...)
 	if err != nil {
 		return nil, err
@@ -1779,17 +1782,26 @@ func txQuery(tx *core.Tx, sqlStr string, params ...interface{}) (resultsSlice []
 	return rows2maps(rows)
 }
 
-func query(db *core.DB, sqlStr string, params ...interface{}) (resultsSlice []map[string][]byte, err error) {
+func (session *Session) innerQuery(db *core.DB, sqlStr string, params ...interface{}) (resultsSlice []map[string][]byte, err error) {
-	s, err := db.Prepare(sqlStr)
+
+	stmt, rows, err := session.Engine.LogSQLQueryTime(sqlStr, params, func() (*core.Stmt, *core.Rows, error) {
+		stmt, err := db.Prepare(sqlStr)
 		if err != nil {
-		return nil, err
+			return stmt, nil, err
-	}
-	defer s.Close()
-	rows, err := s.Query(params...)
-	if err != nil {
-		return nil, err
 		}
+		rows, err := stmt.Query(params...)
+
+		return stmt, rows, err
+	})
+	if rows != nil {
 		defer rows.Close()
+	}
+	if stmt != nil {
+		defer stmt.Close()
+	}
+	if err != nil {
+		return nil, err
+	}
 	return rows2maps(rows)
 }
 
@@ -1955,6 +1967,7 @@ func (session *Session) innerInsertMulti(rowsSlicePtr interface{}) (int64, error
 		strings.Join(colMultiPlaces, "),("))
 
 	res, err := session.exec(statement, args...)
+
 	if err != nil {
 		return 0, err
 	}