Skip to content

Commit f0b23d6

Browse files
iluhinskyiluhinsky
authored
Reorganised logging in acronis-db-bench (acronis#35)
* Removed logging levels from db loggers * Reworked configuration of db logger * Added logging of query params * Added function for logging db context statistics * Added operations time logging to sql adapter * Made cleanup operation more safe * Added ability to explicitly create system connection * Added logging of DDL and db describe queries in sql adapter * Added logging configuration for system connection in acronis-db-bench * Moved tenant cache connection from workerData * Reworked query logging in es adapter * Added readRows logger to es adapter * Fixed calculating of read rows timings in db adapters * Enabled logging of read rows for system connection in acronis-db-bench * Added support of selecting values without table indication in sql adapters * Added support of SELECT 1 in es adapters * Fixed select 1 test * Fixed logging requests without index specification in es adapter * Added configurable wrapper that logs all http requests in es adapter * Fixed connection leak after initialising tenant cache * Minor adjusment of es search request formatting
1 parent 0336efb commit f0b23d6

36 files changed

+913
-453
lines changed

‎acronis-db-bench/README.md‎

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -73,10 +73,6 @@ Note: If both the `--connection-string` command-line option and the `ACRONIS_DB_
7373
--enable-query-string-interpolation enable query string interpolation
7474
--dry-run do not execute any INSERT/UPDATE/DELETE queries on DB-side
7575
--explain prepend the test queries by EXPLAIN ANALYZE
76-
--log-queries log all queries
77-
--log-read-rows log all read rows
78-
--log-query-time log query time
79-
--log-system-operations log system operations
8076
--dont-cleanup do not cleanup DB content before/after the test in '-t all' mode
8177
--use-truncate use TRUNCATE instead of DROP TABLE in cleanup procedure
8278
```

‎acronis-db-bench/engine/db.go‎

Lines changed: 48 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -25,11 +25,6 @@ type DatabaseOpts struct {
2525
DryRun bool `long:"dry-run" description:"do not execute any INSERT/UPDATE/DELETE queries on DB-side" required:"false"`
2626
Explain bool `long:"explain" description:"prepend the test queries by EXPLAIN ANALYZE" required:"false"`
2727

28-
LogQueries bool `long:"log-queries" description:"log queries" required:"false"`
29-
LogReadRows bool `long:"log-read-rows" description:"log read rows" required:"false"`
30-
LogQueryTime bool `long:"log-query-time" description:"log query time" required:"false"`
31-
LogSystemOps bool `long:"log-system-operations" description:"log system operations on database side" required:"false"`
32-
3328
DontCleanup bool `long:"dont-cleanup" description:"do not cleanup DB content before/after the test in '-t all' mode" required:"false"`
3429
UseTruncate bool `long:"use-truncate" description:"use TRUNCATE instead of DROP TABLE in cleanup procedure" required:"false"`
3530
}
@@ -155,17 +150,13 @@ func connectionsChecker(conn *DBConnector) {
155150

156151
// DBWorkerData is a structure to store all the worker data
157152
type DBWorkerData struct {
158-
workingConn *DBConnector
159-
tenantsCache *DBConnector
153+
workingConn *DBConnector
160154
}
161155

162156
func (d *DBWorkerData) release() {
163157
if d.workingConn != nil {
164158
d.workingConn.Release()
165159
}
166-
if d.tenantsCache != nil {
167-
d.tenantsCache.Release()
168-
}
169160
}
170161

171162
/*
@@ -184,38 +175,53 @@ type DBConnector struct {
184175
}
185176

186177
// NewDBConnector creates a new DBConnector
187-
func NewDBConnector(dbOpts *DatabaseOpts, workerID int, l logger.Logger, retryAttempts int) (*DBConnector, error) {
178+
func NewDBConnector(dbOpts *DatabaseOpts, workerID int, systemConnect bool, l logger.Logger, retryAttempts int) (*DBConnector, error) {
188179
c := connPool.take(dbOpts, workerID)
189180
if c != nil {
190181
return c, nil
191182
}
192183

193-
var queryLogger, readRowsLogger, explainLogger, systemLogger logger.Logger
194-
if dbOpts.LogQueries {
195-
queryLogger = l.Clone()
196-
queryLogger.SetLevel(logger.LevelInfo)
197-
}
184+
var logOperationTime bool
185+
var queryLogger, readRowsLogger, explainLogger, systemLogger db.Logger
198186

199-
if dbOpts.LogReadRows {
200-
readRowsLogger = l.Clone()
201-
readRowsLogger.SetLevel(logger.LevelInfo)
202-
}
187+
if systemConnect {
188+
if l.GetLevel() >= logger.LevelInfo {
189+
systemLogger = newDBLogger(l.Clone(), logger.LevelInfo)
190+
}
203191

204-
if dbOpts.Explain {
205-
explainLogger = l.Clone()
206-
explainLogger.SetLevel(logger.LevelInfo)
192+
if l.GetLevel() >= logger.LevelDebug {
193+
queryLogger = newDBLogger(l.Clone(), logger.LevelDebug)
194+
logOperationTime = true
195+
}
196+
197+
if l.GetLevel() >= logger.LevelTrace {
198+
readRowsLogger = newDBLogger(l.Clone(), logger.LevelTrace)
199+
}
200+
} else {
201+
if l.GetLevel() >= logger.LevelInfo {
202+
queryLogger = newDBLogger(l.Clone(), logger.LevelInfo)
203+
systemLogger = newDBLogger(l.Clone(), logger.LevelInfo)
204+
}
205+
206+
if l.GetLevel() >= logger.LevelDebug {
207+
logOperationTime = true
208+
}
209+
210+
if l.GetLevel() >= logger.LevelTrace {
211+
readRowsLogger = newDBLogger(l.Clone(), logger.LevelTrace)
212+
}
207213
}
208214

209-
if dbOpts.LogSystemOps {
210-
systemLogger = l.Clone()
211-
systemLogger.SetLevel(logger.LevelInfo)
215+
if dbOpts.Explain {
216+
explainLogger = newDBLogger(l.Clone(), l.GetLevel())
212217
}
213218

214219
var dbConn, err = db.Open(db.Config{
215220
ConnString: dbOpts.ConnString,
216221
MaxOpenConns: dbOpts.MaxOpenConns,
217222
QueryStringInterpolation: dbOpts.EnableQueryStringInterpolation,
218223
DryRun: dbOpts.DryRun,
224+
LogOperationsTime: logOperationTime,
219225
UseTruncate: dbOpts.UseTruncate,
220226

221227
QueryLogger: queryLogger,
@@ -277,3 +283,19 @@ func (c *DBConnector) Exit(fmts string, args ...interface{}) {
277283
fmt.Println()
278284
os.Exit(127)
279285
}
286+
287+
type dbLogger struct {
288+
l logger.Logger
289+
level logger.LogLevel
290+
}
291+
292+
func (l *dbLogger) Log(format string, args ...interface{}) {
293+
l.l.Log(l.level, format, args...)
294+
}
295+
296+
func newDBLogger(l logger.Logger, level logger.LogLevel) *dbLogger {
297+
return &dbLogger{
298+
l: l,
299+
level: level,
300+
}
301+
}

‎acronis-db-bench/engine/helpers.go‎

Lines changed: 21 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -68,7 +68,7 @@ func createTables(b *benchmark.Benchmark) {
6868
}
6969

7070
func DbConnector(b *benchmark.Benchmark) *DBConnector {
71-
var conn, err = NewDBConnector(&b.TestOpts.(*TestOpts).DBOpts, -1, b.Logger, 1)
71+
var conn, err = NewDBConnector(&b.TestOpts.(*TestOpts).DBOpts, -1, true, b.Logger, 1)
7272
if err != nil {
7373
FatalError(err.Error())
7474
}
@@ -87,22 +87,35 @@ func CleanupTables(b *benchmark.Benchmark) {
8787

8888
fmt.Printf("cleaning up the test tables ... ")
8989

90-
c := DbConnector(b)
90+
var c = DbConnector(b)
9191

9292
for tableName := range testRegistry.GetTables() {
93-
c.Database.DropTable(tableName)
93+
if err := c.Database.DropTable(tableName); err != nil {
94+
b.Exit("failed drop table: %s", err)
95+
}
9496
}
9597

9698
if b.Vault.(*DBTestData).TenantsCache == nil {
9799
b.Vault.(*DBTestData).TenantsCache = tenants.NewTenantsCache(b)
98100
}
99101

100-
b.Vault.(*DBTestData).TenantsCache.DropTables(c.Database)
101-
c.Database.DropSequence(SequenceName)
102-
c.Release()
102+
if err := b.Vault.(*DBTestData).TenantsCache.DropTables(c.Database); err != nil {
103+
b.Exit("failed drop table: %s", err)
104+
}
103105

104-
eb := events.NewEventBus(c.Database, b.Logger)
105-
eb.DropTables()
106+
if err := c.Database.DropSequence(SequenceName); err != nil {
107+
b.Exit("failed drop sequence: %s", err)
108+
}
109+
110+
if b.Vault.(*DBTestData).EventBus == nil {
111+
b.Vault.(*DBTestData).EventBus = events.NewEventBus(c.Database, b.Logger)
112+
}
113+
114+
if err := b.Vault.(*DBTestData).EventBus.DropTables(); err != nil {
115+
b.Exit("failed drop table: %s", err)
116+
}
117+
118+
c.Release()
106119

107120
fmt.Printf("done\n")
108121
}

‎acronis-db-bench/engine/main.go‎

Lines changed: 18 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -207,10 +207,6 @@ func Main() {
207207
workerData.workingConn.Close()
208208
}
209209

210-
if workerData.tenantsCache != nil {
211-
workerData.tenantsCache.Close()
212-
}
213-
214210
worker.Data = nil
215211
}
216212
}
@@ -262,13 +258,30 @@ func Main() {
262258
b.Vault.(*DBTestData).TenantsCache.SetTenantsWorkingSet(b.TestOpts.(*TestOpts).BenchOpts.TenantsWorkingSet)
263259
b.Vault.(*DBTestData).TenantsCache.SetCTIsWorkingSet(b.TestOpts.(*TestOpts).BenchOpts.CTIsWorkingSet)
264260

261+
var tenantCacheDBOpts = b.TestOpts.(*TestOpts).DBOpts
262+
if b.TestOpts.(*TestOpts).BenchOpts.TenantConnString != "" {
263+
tenantCacheDBOpts.ConnString = b.TestOpts.(*TestOpts).BenchOpts.TenantConnString
264+
}
265+
266+
var tenantCacheDatabase *DBConnector
267+
if tenantCacheDatabase, err = NewDBConnector(&tenantCacheDBOpts, -1, true, b.Logger, 1); err != nil {
268+
b.Exit("db: cannot create tenants cache connection: %v", err)
269+
return
270+
}
271+
272+
if err = b.Vault.(*DBTestData).TenantsCache.Init(tenantCacheDatabase.Database); err != nil {
273+
b.Exit("db: cannot initialize tenants cache: %v", err)
274+
}
275+
265276
if b.Logger.GetLevel() > logger.LevelInfo && !testOpts.BenchOpts.Info {
266277
b.Log(logger.LevelTrace, 0, getDBInfo(b, content))
267278
}
268279

280+
tenantCacheDatabase.Release()
281+
269282
if b.TestOpts.(*TestOpts).BenchOpts.Events {
270283
var workingConn *DBConnector
271-
if workingConn, err = NewDBConnector(&b.TestOpts.(*TestOpts).DBOpts, -1, b.Logger, 1); err != nil {
284+
if workingConn, err = NewDBConnector(&b.TestOpts.(*TestOpts).DBOpts, -1, true, b.Logger, 1); err != nil {
272285
return
273286
}
274287

‎acronis-db-bench/engine/workers.go‎

Lines changed: 1 addition & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -29,20 +29,10 @@ func initWorker(worker *benchmark.BenchmarkWorker, testDesc *TestDesc, rowsRequi
2929
var workerData DBWorkerData
3030
var err error
3131

32-
if workerData.workingConn, err = NewDBConnector(&b.TestOpts.(*TestOpts).DBOpts, workerID, worker.Logger, 1); err != nil {
32+
if workerData.workingConn, err = NewDBConnector(&b.TestOpts.(*TestOpts).DBOpts, workerID, false, worker.Logger, 1); err != nil {
3333
return
3434
}
3535

36-
if b.TestOpts.(*TestOpts).BenchOpts.TenantConnString != "" {
37-
var tenantCacheDBOpts = b.TestOpts.(*TestOpts).DBOpts
38-
tenantCacheDBOpts.ConnString = b.TestOpts.(*TestOpts).BenchOpts.TenantConnString
39-
40-
if workerData.tenantsCache, err = NewDBConnector(&tenantCacheDBOpts, workerID, b.Logger, 1); err != nil {
41-
workerData.release()
42-
b.Exit("db: cannot create tenants cache connection: %v", err)
43-
}
44-
}
45-
4636
worker.Data = &workerData
4737
}
4838

@@ -101,17 +91,6 @@ func initWorker(worker *benchmark.BenchmarkWorker, testDesc *TestDesc, rowsRequi
10191
}
10292
}
10393
}
104-
105-
var tenantCacheDatabase db.Database
106-
if worker.Data.(*DBWorkerData).tenantsCache != nil {
107-
tenantCacheDatabase = worker.Data.(*DBWorkerData).tenantsCache.Database
108-
} else {
109-
tenantCacheDatabase = conn.Database
110-
}
111-
112-
if err := testData.TenantsCache.Init(tenantCacheDatabase); err != nil {
113-
b.Exit("db: cannot initialize tenants cache: %v", err)
114-
}
11594
}
11695
worker.Logger.Trace("worker is initialized")
11796
}
@@ -148,9 +127,6 @@ func initCommon(b *benchmark.Benchmark, testDesc *TestDesc, rowsRequired uint64)
148127
if workerData.workingConn != nil {
149128
workerData.workingConn.Close()
150129
}
151-
if workerData.tenantsCache != nil {
152-
workerData.tenantsCache.Close()
153-
}
154130
}
155131
}
156132
}

‎acronis-db-bench/tenants-cache/tenant_generator.go‎

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -90,9 +90,11 @@ func NewTenantsCache(bench *benchmark.Benchmark) *TenantsCache {
9090
bench.CommonOpts.RandSeed = time.Now().UnixNano()
9191
}
9292

93-
bench.Randomizer.RegisterPlugin("tenant", tenantCache)
94-
for _, worker := range bench.Workers {
95-
worker.Randomizer.RegisterPlugin("tenant", tenantCache)
93+
if bench.Randomizer != nil {
94+
bench.Randomizer.RegisterPlugin("tenant", tenantCache)
95+
for _, worker := range bench.Workers {
96+
worker.Randomizer.RegisterPlugin("tenant", tenantCache)
97+
}
9698
}
9799

98100
return tenantCache
@@ -452,17 +454,20 @@ func (tc *TenantsCache) InitTables(database db.Database) {
452454
}
453455

454456
// DropTables drops all tables created by this test
455-
func (tc *TenantsCache) DropTables(database db.Database) {
457+
func (tc *TenantsCache) DropTables(database db.Database) error {
456458
tc.logger.Trace("drop tenant tables")
457459

458460
for _, table := range []string{TableNameTenants, TableNameTenantClosure, TableNameCtiEntities, TableNameCtiProvisioning} {
459-
if droppedErr := database.DropTable(table); droppedErr != nil {
460-
tc.logger.Error("error dropping table %s: %v", table, droppedErr)
461+
if err := database.DropTable(table); err != nil {
462+
return err
461463
}
462464
}
465+
463466
if database.UseTruncate() {
464467
tc.InitTables(database)
465468
}
469+
470+
return nil
466471
}
467472

468473
// PopulateUuidsFromDB populates uuids from DB table acronis_db_bench_cybercache_tenants

‎acronis-db-bench/test-groups/basic-scenarios/medium_test.go‎

Lines changed: 16 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,9 @@
11
package basic_scenarios
22

33
import (
4-
"github.com/acronis/perfkit/benchmark"
5-
64
"github.com/acronis/perfkit/acronis-db-bench/engine"
5+
tenants "github.com/acronis/perfkit/acronis-db-bench/tenants-cache"
6+
"github.com/acronis/perfkit/benchmark"
77
)
88

99
func (suite *TestingSuite) TestMediumTableTests() {
@@ -78,6 +78,20 @@ func (suite *TestingSuite) TestMediumTableTests() {
7878
d.Scores[s] = []benchmark.Score{}
7979
}
8080

81+
b.Init = func() {
82+
b.Vault.(*engine.DBTestData).TenantsCache = tenants.NewTenantsCache(b)
83+
84+
var tenantCacheDatabase, err = engine.NewDBConnector(&b.TestOpts.(*engine.TestOpts).DBOpts, -1, true, b.Logger, 1)
85+
if err != nil {
86+
b.Exit("db: cannot create tenants cache connection: %v", err)
87+
return
88+
}
89+
90+
if err = b.Vault.(*engine.DBTestData).TenantsCache.Init(tenantCacheDatabase.Database); err != nil {
91+
b.Exit("db: cannot initialize tenants cache: %v", err)
92+
}
93+
}
94+
8195
mediumTableTestSuite.Execute(b, &engine.TestOpts{
8296
DBOpts: engine.DatabaseOpts{ConnString: suite.ConnString},
8397
}, 1)

0 commit comments

Comments
 (0)