Small technology | let Go SQL behavior be clear at a glance (on)

The author once shared two articles, respectively on the construction of distributed link tracking based on GORM V2 and XORM. Since then, some netizens occasionally contacted the author for communication, mainly about the project using GORM V1 or native SQL. Minimize intrusion into business code for logging database operations, error monitoring, and link tracing.

This series of articles provides solutions to the problems of SQL operation log output, monitoring, and link tracing on all Go services.

Mount hook functions on SQl. Driver using SQLHooks.
ORM, SQL, and SQLX practices.
Prometheus collects DB operation indicators.
Opentracing link Tracing.

This article mainly covers the first and second steps of Prometheus and Opentracing, which will be updated in the future. All the code used in this article has been opened source. If you have any questions, please refer to Github – SQLlinks-example.

Custom driver

It is well known that the Database/SQL native library provides the interface{} interface definition, and the operation of the database is usually carried out with the help of driver. driver and driver.conn. Read the Go Language Design and Implementation – Database content for this section.

In this case, we only need to wrap a layer over Diver and Conn to achieve full SQL log printing and monitoring.

On the premise of avoiding building wheels as much as possible, I implemented it using Github open source project SQLHooks. It is worth noting that if you need to apply to a production environment, refer to the open source project packaging.

Driver.Driver, which calls Exec, Query, and Prepare from the developer.

// Driver implements a database/sql/driver.Driver
type Driver struct {
	driver.Driver
	hooks Hooks
}

// Hooks instances may be passed to Wrap() to define an instrumented driver
type Hooks interface {
	Before(ctx context.Context, query string, args ...interface{}) (context.Context, error)
	After(ctx context.Context, query string, args ...interface{}) (context.Context, error)
}
Copy the code

At this point, experienced Gopher had noticed that the methods of the Hooks interface all take context. context, and most likely guessed what would happen next.

For example, to print the full SQL and Args parameters, we can define a structure that includes a log print object that implements the Hooks interface.

To make this work better, the practice of this article includes SQL time, which is usually implemented in the database and presented to dbAs for queries, but we developers generally need this metric to determine SQL quality as well.

First we define the zapHook structure, which contains a Zap Logger object and a Boolean value to enable SQL time calculation.

// make sure zapHook implement all sqlhooks interface.
var _ interface {
	sqlhooks.Hooks
	sqlhooks.OnErrorer
} = (*zapHook)(nil)

// zapHook using zap log sql query and args.
type zapHook struct {
	*zap.Logger

	// Whether to print the SQL takes time
	IsPrintSQLDuration bool
}

// sqlDurationKey is context.valueCtx Key.
type sqlDurationKey struct{}
Copy the code

Next we need to define two things that the Before function needs to do.

The logs of Query commands and parameters used to execute SQL are displayed.
Inject the start time object for executing SQL into the context.

func buildQueryArgsFields(query string, args ...interface{}) []zap.Field {
	if len(args) == 0 {
		return []zap.Field{zap.String("query", query)}
	}
	return []zap.Field{zap.String("query", query), zap.Any("args", args)}
}

func (z *zapHook) Before(ctx context.Context, query string, args ...interface{}) (context.Context, error) {
	if z == nil || z.Logger == nil {
		return ctx, nil
	}
	z.Info("log before sql exec", buildQueryArgsFields(query, args...) ...).if z.IsPrintSQLDuration {
		ctx = context.WithValue(ctx, (*sqlDurationKey)(nil), time.Now())
	}
	return ctx, nil
}
Copy the code

Following the same flow, we need to define the flow that the After function needs to do.

Try to get the start time object for SQL execution from the context.
Output the Query and parameter logs after executing the SQL (normally output only once in the Before function, but this article practices twice for effect).

func (z *zapHook) After(ctx context.Context, query string, args ...interface{}) (context.Context, error) {
	if z == nil || z.Logger == nil {
		return ctx, nil
	}

	var durationField = zap.Skip()
	if v, ok := ctx.Value((*sqlDurationKey)(nil)).(time.Time); ok {
		durationField = zap.Duration("duration", time.Now().Sub(v))
	}

	z.With(durationField).Info("log after sql exec", buildQueryArgsFields(query, args...) ...).return ctx, nil
}
Copy the code

We also need to improve the hook function when OnError occurs, which is usually necessary to log or report metrics and causes after SQL execution fails.

func (z *zapHook) OnError(_ context.Context, err error, query string, args ...interface{}) error {
	if z == nil || z.Logger == nil {
		return nil
	}
	z.With(zap.Error(err)).Error("log after err happened", buildQueryArgsFields(query, args...) ...).return nil
}
Copy the code

Now that we have implemented all of the SQLHooks interfaces, the final step is to use the Wrap method provided by the SQLHooks library to create a new Driver registered with the global Driver.

// Most MySQL operations use go-sqL-driver as the driver.
import (
	"database/sql"
  
	"github.com/go-sql-driver/mysql"
)

// Overwriting the driver name of mysql will cause panic, so you need to create a new driver.
//
// database/sql/sql.go:51
const driverName = "mysql-zap"

func initZapHook(log *zap.Logger) {
	if log == nil {
		log = zap.L()
	}
	hook := &zapHook{Logger: log, IsPrintSQLDuration: true}
	sql.Register(zapDriverName, sqlhooks.Wrap(new(mysql.MySQLDriver), hook))
}
Copy the code

We can then use this hook function to output a log of all the SQL generated by the DB framework.

Business practices

Before proceeding with this practice, you need to understand that this article is based on the following environment.

Go to 1.17
Go – SQL – driver v1.6.0
SQLX 1.3.4
GORM 1.22.3
TiDB 5.2.2

The following will be divided into four stages for practice.

Define the test table structure and Go structure.
View Go native SQL execution and query results.
View the SQLX framework execution and query results.
View GORM framework execution and query results.

Define the test table structure and Go structure

First, the author manually defines a simple database table structure and creates it.

CREATE TABLE `test_table`
(
    `id`        bigint(20) NOT NULL AUTO_INCREMENT,
    `score`     bigint(20) NOT NULL,
    `create_at` timestamp  NOT NULL DEFAULT CURRENT_TIMESTAMP,
    `update_at` timestamp  NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP.PRIMARY KEY (`id`)
) ENGINE = InnoDB
  DEFAULT CHARSET = utf8mb4
  COLLATE = utf8mb4_bin
  AUTO_INCREMENT = 30001;
Copy the code

The next step is to write the corresponding structure in Go code, which can be simplified by various SQL transstruct tools.

import "gorm.io/gorm/schema"

// Implement GORM table name interface
var _ schema.Tabler = (*testTable)(nil)

type testTable struct {
	ID       uint      `db:"id"`
	Score    int64     `db:"score"`
	CreateAt time.Time `db:"create_at" gorm:"<-:false"`
	UpdateAt time.Time `db:"update_at" gorm:"<-:false"`
}

func (*testTable) TableName(a) string { return "test_table" }

type testTableSlice []*testTable

// GoString outputs human-readable logs
func (t testTableSlice) GoString(a) string {
	var output strings.Builder
	for _, v := range t {
		output.WriteString(fmt.Sprintf("- id: %d, score: %d, createAt: %s, updateAt: %s\n", v.ID, v.Score, v.CreateAt.String(), v.UpdateAt.String()))
	}
	return output.String()
}

Copy the code

Before writing the business code, we need to go through the necessary initialization process.

var ctx = context.Background()

var dsn = os.Getenv("DSN")

func init(a) {
	initZapHook(setupZapLogging(zap.InfoLevel))
	rand.Seed(time.Now().UnixNano())
}
Copy the code

Now that the preparation is complete, we need to write the business code according to the corresponding framework. The unified process is query after insert.

Go native library SQL

Native library SQL is a common database operation library for Go development.

Because native library-based bulk inserts require string concatenation, the native library practice shows only a single insert to simplify the process.

// database/sql
func rawSQLExample(a) {
	log.Println("going using database/sql exec sql")

	// Create a database connection object
	connRaw, err := sql.Open(zapDriverName, dsn)
	iferr ! =nil {
		log.Fatalln(err)
	}

	// Insert operations need to be preprocessed before execution
	const rawInsertSQL = `INSERT INTO test_table (score) VALUES (?) `
	stmt, err := connRaw.PrepareContext(ctx, rawInsertSQL)
	iferr ! =nil {
		log.Fatalln(err)
	}
	if_, err = stmt.ExecContext(ctx, rand.Int63()); err ! =nil {
		log.Fatalln(err)
	}
	
	// Query operation
	resQuery, err := connRaw.QueryContext(ctx, "SELECT * FROM test_table")
	iferr ! =nil {
		log.Fatalln(err)
	}
	defer func(a) { _ = resQuery.Close() }()
	var res testTableSlice
	for resQuery.Next() {
		tmp := new(testTable)
		iferr = resQuery.Scan(&tmp.ID, &tmp.Score, &tmp.CreateAt, &tmp.UpdateAt); err ! =nil {
			log.Fatalln(err)
		}
		res = append(res, tmp)
	}
	log.Printf("%#v", res)
}
Copy the code

After writing the business code, we can run unit tests to verify the effect.

=== RUN Test_zapHook 2021-11-14T22:00:07.255+0800 INFO SQLhooks -exmaple/zap_example_test.go:41 going using database/ SQL Exec SQL 2021-11-14T22:00:07.256+0800 INFO SQLhooks -exmaple/zap.go:54 log before SQL EXEC {"query": "INSERT INTO test_table (score) VALUES (?) ", "args": [6720357018880391204]} 2021-11-14T22:00:07.261+0800 INFO SQLhooks -exmaple/zap.go:72 log after SQL exec {"duration": "4.728028ms", "query": "INSERT INTO test_table (score) VALUES (? ", "args": [6720357018880391204]} 2021-11-14T22:00:07.261+0800 INFO SQLhooks -exmaple/zap.go:54 log before SQL exec {"query": "SELECT * FROM test_table"} 2021-11-14T22:00:07.262+0800 INFO SQLhooks -exmaple/zap. Go :72 log after SQL exec {"duration": "1.098115 ms", "query" : "SELECT * FROM test_table"} 2021-11-14T22:00:07.262+0800 INFO SQLhooks -exmaple/zap_example_test.go: 73-id: 30095, score: 6720357018880391204, createAt: 2021-11-14 22:00:07 +0800 CST, updateAt: 2021-11-14 22:00:07 +0800 CST -- PASS: Test_zapHook (0.01s) PASSCopy the code

In terms of the log output, it did exactly what we wanted — log output and SQL execution time.

SQLX framework

SQLX is a common database operation framework in Go business development. Currently, there is 11.1K STAR on Github.

SQLX supports named parameters, and named parameters support slicing, so I can demonstrate a batch insert scenario.

// jmoiron/sqlx
func sqlxExample(a) {
	log.Println("going using jmoiron/sqlx exec sql")

	// Create database link based on SQLX
	connSqlx, err := sqlx.ConnectContext(ctx, zapDriverName, dsn)
	iferr ! =nil {
		log.Fatalln(err)
	}

	// The insertion operation requires named parameter substitution and preprocessing
	const sqlxNameInsertSQL = `INSERT INTO test_table (score) VALUES (:score)`
	var valuesToInsert = []*testTable{{Score: rand.Int63()}, {Score: rand.Int63()}, {Score: rand.Int63()}}
	newInsertSQL, args, err := sqlx.Named(sqlxNameInsertSQL, valuesToInsert)
	iferr ! =nil {
		log.Fatalln(err)
	}
	stmt, err := connSqlx.PreparexContext(ctx, newInsertSQL)
	iferr ! =nil {
		log.Fatalln(err)
	}
	if_, err = stmt.ExecContext(ctx, args...) ; err ! =nil {
		log.Fatalln(err)
	}

	// The query operation can be scanned to the corresponding structure slice using the Select method
	var res testTableSlice
	if err = connSqlx.Select(&res, "SELECT * FROM test_table"); err ! =nil {
		log.Fatalln(err)
	}
	log.Printf("%#v", res)
}
Copy the code

We run the unit tests to get the corresponding output.

=== RUN Test_zapHook 2021-11-14T22:24:50.118+0800 INFO SQLhooks -exmaple/zap_example_test.go:78 going using jmoiron/ SQLX Exec SQL 2021-11-14T22:24:50.119+0800 INFO SQLhooks -exmaple/zap.go:54 log before SQL EXEC {"query": "INSERT INTO test_table (score) VALUES (?) , (?) , (?) ", "args": [415829244009450172346963816178078219712314461967]} 2021-11-14 T22:24:50. 124 + 0800 INFO Sqlhooks -exmaple/zap.go:72 log after SQL exec {"duration": "4.85822ms", "query": "INSERT INTO test_table (score) VALUES (?) , (?) , (?) ", "args": [415829244009450172346963816178078219712314461967]} 2021-11-14 T22:24:50. 124 + 0800 INFO sqlhooks-exmaple/zap.go:54 log before sql exec {"query": "SELECT * FROM test_table"} 2021-11-14T22:24:50.125+0800 INFO SQLhooks -exmaple/zap.go:72 log after SQL exec {"duration": "1.119153 ms", "query" : "SELECT * FROM test_table"} 2021-11-14T22:24:50.125+0800 INFO SQLhooks -exmaple/zap_example_test.go: 106-id: 30096, score: 415829244009450172, createAt: 2021-11-14 22:24:50 +0800 CST, updateAt: 2021-11-14 22:24:50 +0800 CST - id: 30097, score: 3465963981601780078, createAt: 2021-11-14 22:24:50 +0800 CST, updateAt: 2021-11-14 22:24:50 +0800 CST - id: 30098, score: 2197712931404613967, createAt: 2021-11-14 22:24:50 +0800 CST, updateAt: 2021-11-14 22:24:50 +0800 CST --- PASS: Test_zapHook (0.01 s)Copy the code

SQLX framework and native library SQL output effect is the same, the same can be executed SQL and time.

GORM framework

Highly encapsulated GORM frameworks can be difficult to obtain the corresponding SQL and execution time (especially V1 version), while the driver-based approach can smooth out the differences between libraries and frameworks, and capture the SQL information we need at the entry and exit of database operations.

Note that we only need to adjust the parameters when the DB object is created to call the desired Hooks function.

// GORM V2, need to focus driver name is zapDriverName.
func gormExample(a) {
	log.Println("going using gorm V2 exec sql")

	// To create a GORM link, modify the DriverName parameter
	dialector := mysql.New(mysql.Config{DSN: dsn, DriverName: zapDriverName})

	PrepareStmt must be enabled for GORM, otherwise driver.ErrSkip errors will be reported
	connGorm, err := gorm.Open(dialector, &gorm.Config{PrepareStmt: true})
	iferr ! =nil {
		log.Fatalln(err)
	}
	
	// Perform the insert operation by calling the API, which is very convenient, but there is no visual view of the actual SQL in effect
	valuesToCreate := []*testTable{{Score: rand.Int63()}, {Score: rand.Int63()}, {Score: rand.Int63()}}
	if err = connGorm.CreateInBatches(valuesToCreate, len(valuesToCreate)).Error; err ! =nil {
		log.Fatalln(err)
	}
	var res testTableSlice
	
	// The same is true for queries
	iferr = connGorm.Find(&res).Error; err ! =nil {
		log.Fatalln(err)
	}
	log.Printf("%#v", res)
}
Copy the code

By running the unit tests, we can get the output.

=== RUN Test_zapHook 2021-11-14T22:43:02.364+0800 INFO SQLhooks -exmaple/zap_example_test.go:111 going using GORm V2 exec SQL 2021-11-14T22:43:02.365+0800 INFO SQLhooks -exmaple/zap.go:54 log Before SQL EXEC {"query": "SELECT VERSION()"} 2021-11-14T22:43:02.366+0800 INFO SQLhooks -exmaple/zap.go:72 log after SQL exec {"duration": 274.358 (including "s", "query" : "SELECT VERSION()"} 2021-11-14T22:43:02.367+0800 INFO SQLhooks -exmaple/zap.go:54 log before SQL exec {"query": "INSERT INTO `test_table` (`score`) VALUES (?) , (?) , (?) ", "args": [6926252270182587172158531549671592640207774935629]} 2021-11-14 T22:43:02. 370 + 0800 INFO Sqlhooks -exmaple/zap.go:72 log after SQL exec {"duration": "3.442791ms", "query": "INSERT INTO `test_table` (`score`) VALUES (?) , (?) , (?) ", "args": [6926252270182587172158531549671592640207774935629]} 2021-11-14 T22:43:02. 437 + 0800 INFO sqlhooks-exmaple/zap.go:54 log before sql exec {"query": "SELECT * FROM 'test_table'} 2021-11-14T22:43:02.438+0800 INFO SQLhooks -exmaple/zap. Go :72 log after SQL exec {" duration ":" 1.187731 ms ", "query" : "SELECT * FROM 'test_table'} 2021-11-14T22:43:02.438+0800 INFO SQLhooks -exmaple/zap_example_test.go: 133-id: 30099, score: 6926252270182587172, createAt: 2021-11-14 22:43:02 +0800 CST, updateAt: 2021-11-14 22:43:02 +0800 CST - id: 30100, score: 1587531254996719592, createAt: 2021-11-14 22:43:02 +0800 CST, updateAt: 2021-11-14 22:43:02 +0800 CST - id: 30101, score: 6405207277469356629, createAt: 2021-11-14 22:43:02 +0800 CST, updateAt: 2021-11-14 22:43:02 +0800 CST --- PASS: PASS Test_zapHook (0.07 s)Copy the code

The log output has the same effect as expected. The ACTUAL SQL execution and time consumption can be displayed.

It is worth noting that the GORM framework still executes the SELECT VERSION() command during initialization, although we did not write anything extra.

Matters needing attention

The author thinks that the content of this paper is relatively basic, which can provide some students with ideas to solve problems. However, there are still matters needing attention.

This article is based on the SQLHooks open source library. It is worth noting that in a production environment, infrastructure projects should try to package themselves or provide configuration switches.
Output or collection are expensive work, can provide parameters to turn off or adjust the collection probability.
When conditions permit, the core business reduces or avoids the use of ORM, reducing the risk of human misoperation.

Thank you very much for reading, if you have better ideas or questions, please feel free to send me a message.

The resources

Github – sqlhooks-example
Github – SQLHooks
Go language design and implementation – database
Github – SQLX
GORM

Small technology | let Go SQL behavior be clear at a glance (on)

Custom driver

Business practices

Define the test table structure and Go structure

Go native library SQL

SQLX framework

GORM framework

Matters needing attention

The resources

Related Posts

Minimum production trees Prim and Kruskal

Springboot series (16): Integrated easyPOI to achieve Excel import and export

What design patterns does Spring use?