support/db: Add round_trip_time_seconds metric

services/horizon/internal/actions_effects_test.go

@@ -104,7 +104,7 @@ func TestEffectActions_Index(t *testing.T) {
 		ht.ReapHistory(1)
 		w = ht.Get("/effects?order=desc&cursor=8589938689-1")
 		ht.Assert.Equal(410, w.Code)
-		ht.Logger.Error(w.Body.String())
+		ht.T.T.Log(w.Body.String())
 	})
 
 	t.Run("Effect resource props", func(t *testing.T) {

services/horizon/internal/app.go

@@ -462,8 +462,8 @@ func (a *App) init() error {
 	a.ctx, a.cancel = context.WithCancel(context.Background())
 
 	// log
-	log.DefaultLogger.Logger.Level = a.config.LogLevel
-	log.DefaultLogger.Logger.Hooks.Add(logmetrics.DefaultMetrics)
+	log.DefaultLogger.Logger.SetLevel(a.config.LogLevel)
+	log.DefaultLogger.Logger.AddHook(logmetrics.DefaultMetrics)
 
 	// sentry
 	initSentry(a)

services/horizon/internal/test/main.go

@@ -4,15 +4,13 @@
 package test
 
 import (
-	"bytes"
 	"context"
 	"net/http"
 	"net/http/httptest"
 	"testing"
 
 	"github.com/jmoiron/sqlx"
 	"github.com/sirupsen/logrus"
-	"github.com/stellar/go/services/horizon/internal/logmetrics"
 	tdb "github.com/stellar/go/services/horizon/internal/test/db"
 	"github.com/stellar/go/support/log"
 	"github.com/stretchr/testify/assert"
@@ -27,15 +25,12 @@ type StaticMockServer struct {
 
 // T provides a common set of functionality for each test in horizon
 type T struct {
-	T          *testing.T
-	Assert     *assert.Assertions
-	Require    *require.Assertions
-	Ctx        context.Context
-	HorizonDB  *sqlx.DB
-	CoreDB     *sqlx.DB
-	Logger     *log.Entry
-	LogMetrics *logmetrics.Metrics
-	LogBuffer  *bytes.Buffer
+	T         *testing.T
+	Assert    *assert.Assertions
+	Require   *require.Assertions
+	Ctx       context.Context
+	HorizonDB *sqlx.DB
+	CoreDB    *sqlx.DB
 }
 
 // Context provides a context suitable for testing in tests that do not create
@@ -63,25 +58,25 @@ func DatabaseURL() string {
 // OverrideLogger sets the default logger used by horizon to `l`.  This is used
 // by the testing system so that we can collect output from logs during test
 // runs.  Panics if the logger is already overridden.
-func OverrideLogger(l *log.Entry) {
-	if oldDefault != nil {
+func OverrideLogger() {
+	if endLogTest != nil {
 		panic("logger already overridden")
 	}
 
-	oldDefault = log.DefaultLogger
-	log.DefaultLogger = l
+	endLogTest = log.StartTest(log.DebugLevel)
 }
 
 // RestoreLogger restores the default horizon logger after it is overridden
 // using a call to `OverrideLogger`.  Panics if the default logger is not
 // presently overridden.
-func RestoreLogger() {
-	if oldDefault == nil {
+func RestoreLogger() []logrus.Entry {
+	if endLogTest == nil {
 		panic("logger not overridden, cannot restore")
 	}
 
-	log.DefaultLogger = oldDefault
-	oldDefault = nil
+	entries := endLogTest()
+	endLogTest = nil
+	return entries
 }
 
 // Start initializes a new test helper object and conceptually "starts" a new
@@ -90,15 +85,10 @@ func Start(t *testing.T) *T {
 	result := &T{}
 
 	result.T = t
-	result.LogBuffer = new(bytes.Buffer)
-	result.Logger, result.LogMetrics = logmetrics.New()
-	result.Logger.Logger.Out = result.LogBuffer
-	result.Logger.Logger.Formatter.(*logrus.TextFormatter).DisableColors = true
-	result.Logger.Logger.Level = logrus.DebugLevel
 
-	OverrideLogger(result.Logger)
+	OverrideLogger()
 
-	result.Ctx = log.Set(context.Background(), result.Logger)
+	result.Ctx = log.Set(context.Background(), log.DefaultLogger)
 	result.HorizonDB = Database(t)
 	result.CoreDB = StellarCoreDatabase(t)
 	result.Assert = assert.New(t)
@@ -122,4 +112,4 @@ func StellarCoreDatabaseURL() string {
 	return tdb.StellarCoreURL()
 }
 
-var oldDefault *log.Entry = nil
+var endLogTest func() []logrus.Entry = nil

services/horizon/internal/test/t.go

@@ -26,11 +26,16 @@ func (t *T) CoreSession() *db.Session {
 // Finish finishes the test, logging any accumulated horizon logs to the logs
 // output
 func (t *T) Finish() {
-	RestoreLogger()
+	logEntries := RestoreLogger()
 	operationfeestats.ResetState()
 
-	if t.LogBuffer.Len() > 0 {
-		t.T.Log("\n" + t.LogBuffer.String())
+	for _, entry := range logEntries {
+		logString, err := entry.String()
+		if err != nil {
+			t.T.Logf("Error from entry.String: %v", err)
+		} else {
+			t.T.Log(logString)
+		}
 	}
 }
 

support/db/metrics.go

@@ -42,6 +42,7 @@ func contextRoute(ctx context.Context) string {
 
 type SessionWithMetrics struct {
 	SessionInterface
+
 	registry                 *prometheus.Registry
 	queryCounter             *prometheus.CounterVec
 	queryDurationSummary     *prometheus.SummaryVec
@@ -54,6 +55,8 @@ type SessionWithMetrics struct {
 	maxIdleClosedCounter     prometheus.CounterFunc
 	maxIdleTimeClosedCounter prometheus.CounterFunc
 	maxLifetimeClosedCounter prometheus.CounterFunc
+	roundTripProbe           *roundTripProbe
+	roundTripTimeSummary     prometheus.Summary
 }
 
 func RegisterMetrics(base *Session, namespace string, sub Subservice, registry *prometheus.Registry) SessionInterface {
@@ -221,10 +224,28 @@ func RegisterMetrics(base *Session, namespace string, sub Subservice, registry *
 	)
 	registry.MustRegister(s.maxLifetimeClosedCounter)
 
+	s.roundTripTimeSummary = prometheus.NewSummary(
+		prometheus.SummaryOpts{
+			Namespace:   namespace,
+			Subsystem:   "db",
+			Name:        "round_trip_time_seconds",
+			Help:        "time required to run `select 1` query in a DB - effectively measures round trip time",
+			ConstLabels: prometheus.Labels{"subservice": string(sub)},
+		},
+	)
+	registry.MustRegister(s.roundTripTimeSummary)
+
+	s.roundTripProbe = &roundTripProbe{
+		session:              base.Clone(),
+		roundTripTimeSummary: s.roundTripTimeSummary,
+	}
+	s.roundTripProbe.start()
 	return s
 }
 
 func (s *SessionWithMetrics) Close() error {
+	s.roundTripProbe.close()
+
 	s.registry.Unregister(s.queryCounter)
 	s.registry.Unregister(s.queryDurationSummary)
 	// s.registry.Unregister(s.txnCounter)
@@ -270,7 +291,12 @@ func (s *SessionWithMetrics) TruncateTables(ctx context.Context, tables []string
 
 func (s *SessionWithMetrics) Clone() SessionInterface {
 	return &SessionWithMetrics{
-		SessionInterface:     s.SessionInterface.Clone(),
+		SessionInterface: s.SessionInterface.Clone(),
+
+		// Note that clonned Session will point at the same roundTripProbe
+		// to avoid starting multiple go routines.
+		roundTripProbe: s.roundTripProbe,
+
 		registry:             s.registry,
 		queryCounter:         s.queryCounter,
 		queryDurationSummary: s.queryDurationSummary,

support/db/round_trip_probe.go

@@ -0,0 +1,47 @@
+package db
+
+import (
+	"context"
+	"sync"
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+)
+
+type roundTripProbe struct {
+	session              SessionInterface
+	roundTripTimeSummary prometheus.Summary
+
+	closeChan chan struct{}
+	closeOnce sync.Once
+}
+
+func (p *roundTripProbe) start() {
+	p.closeChan = make(chan struct{})
+	// session must be cloned because will be used concurrently in a
+	// separate go routine in roundTripProbe
+	p.session = p.session.Clone()
+
+	go func() {
+		for {
+			select {
+			case <-time.After(time.Second):
+				ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+				startTime := time.Now()
+				_, err := p.session.ExecRaw(ctx, "select 1")
+				if err == nil {
+					p.roundTripTimeSummary.Observe(time.Since(startTime).Seconds())
+				}
+				cancel()
+			case <-p.closeChan:
+				return
+			}
+		}
+	}()
+}
+
+func (p *roundTripProbe) close() {
+	p.closeOnce.Do(func() {
+		close(p.closeChan)
+	})
+}

support/log/entry.go

@@ -142,17 +142,17 @@ func (e *Entry) StartTest(level logrus.Level) func() []logrus.Entry {
 	e.isTesting = true
 
 	hook := &test.Hook{}
-	e.Logger.Hooks.Add(hook)
+	e.Logger.AddHook(hook)
 
 	old := e.Logger.Out
 	e.Logger.Out = ioutil.Discard
 
-	oldLevel := e.Logger.Level
-	e.Logger.Level = level
+	oldLevel := e.Logger.GetLevel()
+	e.Logger.SetLevel(level)
 
 	return func() []logrus.Entry {
-		e.Logger.Level = oldLevel
-		e.Logger.Out = old
+		e.Logger.SetLevel(oldLevel)
+		e.Logger.SetOutput(old)
 		e.removeHook(hook)
 		e.isTesting = false
 		return hook.Entries