aboutsummaryrefslogtreecommitdiff
path: root/internal/sqlutil/trace.go
blob: ad0044559b9a0c437c28334f0390ac020ab0c2cc (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
// Copyright 2020 The Matrix.org Foundation C.I.C.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

package sqlutil

import (
	"context"
	"database/sql"
	"database/sql/driver"
	"fmt"
	"io"
	"os"
	"regexp"
	"runtime"
	"strconv"
	"strings"
	"sync"
	"time"

	"github.com/matrix-org/dendrite/setup/config"
	"github.com/ngrok/sqlmw"
	"github.com/sirupsen/logrus"
)

var tracingEnabled = os.Getenv("DENDRITE_TRACE_SQL") == "1"
var goidToWriter sync.Map

type traceInterceptor struct {
	sqlmw.NullInterceptor
}

func (in *traceInterceptor) StmtQueryContext(ctx context.Context, stmt driver.StmtQueryContext, query string, args []driver.NamedValue) (driver.Rows, error) {
	startedAt := time.Now()
	rows, err := stmt.QueryContext(ctx, args)

	trackGoID(query)

	logrus.WithField("duration", time.Since(startedAt)).WithField(logrus.ErrorKey, err).Debug("executed sql query ", query, " args: ", args)

	return rows, err
}

func (in *traceInterceptor) StmtExecContext(ctx context.Context, stmt driver.StmtExecContext, query string, args []driver.NamedValue) (driver.Result, error) {
	startedAt := time.Now()
	result, err := stmt.ExecContext(ctx, args)

	trackGoID(query)

	logrus.WithField("duration", time.Since(startedAt)).WithField(logrus.ErrorKey, err).Debug("executed sql query ", query, " args: ", args)

	return result, err
}

func (in *traceInterceptor) RowsNext(c context.Context, rows driver.Rows, dest []driver.Value) error {
	err := rows.Next(dest)
	if err == io.EOF {
		// For all cases, we call Next() n+1 times, the first to populate the initial dest, then eventually
		// it will io.EOF. If we log on each Next() call we log the last element twice, so don't.
		return err
	}
	cols := rows.Columns()
	logrus.Debug(strings.Join(cols, " | "))

	b := strings.Builder{}
	for i, val := range dest {
		b.WriteString(fmt.Sprintf("%q", val))
		if i+1 <= len(dest)-1 {
			b.WriteString(" | ")
		}
	}
	logrus.Debug(b.String())
	return err
}

func trackGoID(query string) {
	thisGoID := goid()
	if _, ok := goidToWriter.Load(thisGoID); ok {
		return // we're on a writer goroutine
	}

	q := strings.TrimSpace(query)
	if strings.HasPrefix(q, "SELECT") {
		return // SELECTs can go on other goroutines
	}
	logrus.Warnf("unsafe goid %d: SQL executed not on an ExclusiveWriter: %s", thisGoID, q)
}

// Open opens a database specified by its database driver name and a driver-specific data source name,
// usually consisting of at least a database name and connection information. Includes tracing driver
// if DENDRITE_TRACE_SQL=1
func Open(dbProperties *config.DatabaseOptions) (*sql.DB, error) {
	var err error
	var driverName, dsn string
	switch {
	case dbProperties.ConnectionString.IsSQLite():
		driverName = SQLiteDriverName()
		dsn, err = ParseFileURI(dbProperties.ConnectionString)
		if err != nil {
			return nil, fmt.Errorf("ParseFileURI: %w", err)
		}
	case dbProperties.ConnectionString.IsPostgres():
		driverName = "postgres"
		dsn = string(dbProperties.ConnectionString)
	default:
		return nil, fmt.Errorf("invalid database connection string %q", dbProperties.ConnectionString)
	}
	if tracingEnabled {
		// install the wrapped driver
		driverName += "-trace"
	}
	db, err := sql.Open(driverName, dsn)
	if err != nil {
		return nil, err
	}
	if driverName != SQLiteDriverName() {
		logrus.WithFields(logrus.Fields{
			"MaxOpenConns":    dbProperties.MaxOpenConns,
			"MaxIdleConns":    dbProperties.MaxIdleConns,
			"ConnMaxLifetime": dbProperties.ConnMaxLifetime,
			"dataSourceName":  regexp.MustCompile(`://[^@]*@`).ReplaceAllLiteralString(dsn, "://"),
		}).Debug("Setting DB connection limits")
		db.SetMaxOpenConns(dbProperties.MaxOpenConns())
		db.SetMaxIdleConns(dbProperties.MaxIdleConns())
		db.SetConnMaxLifetime(dbProperties.ConnMaxLifetime())
	}
	return db, nil
}

func init() {
	registerDrivers()
}

func goid() int {
	var buf [64]byte
	n := runtime.Stack(buf[:], false)
	idField := strings.Fields(strings.TrimPrefix(string(buf[:n]), "goroutine "))[0]
	id, err := strconv.Atoi(idField)
	if err != nil {
		panic(fmt.Sprintf("cannot get goroutine id: %v", err))
	}
	return id
}