feat: iavl, db & disk stats logging

CHANGELOG.md

@@ -3,6 +3,7 @@
 ## [Unreleased]
 
 ### Features
+* (feat) [\#352] (https://github.com/line/lbm-sdk/pull/352) iavl, db & disk stats logging
 
 ### Improvements
 * (slashing) [\#347](https://github.com/line/lbm-sdk/pull/347) Introduce VoterSetCounter 

baseapp/abci.go

@@ -327,6 +327,9 @@ func (app *BaseApp) Commit() (res abci.ResponseCommit) {
 	commitID := app.cms.Commit()
 	app.logger.Info("commit synced", "commit", fmt.Sprintf("%X", commitID))
 
+	// iavl, db & disk stats
+	logIoStats(app.logger)
+
 	// empty/reset the deliver state
 	app.deliverState = nil
 

baseapp/iostats.go

@@ -0,0 +1,114 @@
+// +build linux
+
+package baseapp
+
+import (
+	"bufio"
+	"io"
+	"os"
+	"regexp"
+	"strconv"
+	"strings"
+	"time"
+
+	iavltree "github.com/line/iavl/v2"
+	"github.com/line/ostracon/libs/log"
+)
+
+// log iavl, db & disk stats if IAVL_DEV env. var. is set
+var (
+	logIoDevNop                                                  string  = " nop"
+	logIoDev                                                     *string = nil
+	tStats                                                       time.Time
+	iavlSetCount, iavlSetBytes, iavlDelCount                     uint64
+	diskReadCount, diskReadBytes, diskWriteCount, diskWriteBytes uint64
+)
+
+// read disk io stats from /proc/diskstats in linux
+func getDeviceIoStats(device string) (readCount, readBytes, writeCount, writeBytes uint64, err error) {
+	inf, err := os.Open("/proc/diskstats")
+	if err != nil {
+		return
+	}
+	defer inf.Close()
+
+	in := bufio.NewReader(inf)
+	r := regexp.MustCompile(`\s+`)
+	for {
+		line, err2 := in.ReadString('\n')
+		if err2 != nil {
+			if err2 == io.EOF {
+				break
+			}
+			err = err2
+			return
+		}
+		parts := r.Split(strings.TrimSpace(line), -1)
+		if len(parts) < 10 {
+			continue
+		}
+		if len(device) > 0 && device != parts[2] {
+			continue
+		} else if len(device) == 0 && parts[1] != "0" {
+			continue
+		}
+
+		rCount, e1 := strconv.ParseUint(parts[3], 10, 64)
+		rSectors, e2 := strconv.ParseUint(parts[5], 10, 64)
+		wCount, e3 := strconv.ParseUint(parts[7], 10, 64)
+		wSectors, e4 := strconv.ParseUint(parts[9], 10, 64)
+		if e1 != nil || e2 != nil || e3 != nil || e4 != nil {
+			continue
+		}
+
+		readCount += rCount
+		readBytes += rSectors * 512
+		writeCount += wCount
+		writeBytes += wSectors * 512
+	}
+	return readCount, readBytes, writeCount, writeBytes, err
+}
+
+func logIoStats(logger log.Logger) {
+	if logIoDev == &logIoDevNop {
+		return
+	} else if logIoDev == nil {
+		// not set yet
+		if dev := os.Getenv("IAVL_DEV"); len(dev) > 0 {
+			logIoDev = &dev
+		} else {
+			logIoDev = &logIoDevNop
+			return
+		}
+	}
+
+	now := time.Now()
+	dt := now.Sub(tStats)
+	tStats = now
+
+	newSetCount, newSetBytes, newDelCount := iavltree.GetDBStats()
+	newReadCount, newReadBytes, newWriteCount, newWriteBytes, _ := getDeviceIoStats(*logIoDev)
+	diffSetCount, diffSetBytes, diffDelCount := newSetCount-iavlSetCount, newSetBytes-iavlSetBytes, newDelCount-iavlDelCount
+	_, diffReadBytes, _, diffWriteBytes := newReadCount-diskReadCount, newReadBytes-diskReadBytes, newWriteCount-diskWriteCount, newWriteBytes-diskWriteBytes
+	iavlSetCount, iavlSetBytes, iavlDelCount = newSetCount, newSetBytes, newDelCount
+	diskReadCount, diskReadBytes, diskWriteCount, diskWriteBytes = newReadCount, newReadBytes, newWriteCount, newWriteBytes
+
+	// read & write bytes per second
+	rps, wps := int64(0), int64(0)
+	if dt.Milliseconds() > 0 && dt.Seconds() < 1000 {
+		rps = int64(diffReadBytes) * 1000 / dt.Milliseconds()
+		wps = int64(diffWriteBytes) * 1000 / dt.Milliseconds()
+	}
+
+	// write amplification factors
+	wampf := float64(0)
+	if diffSetBytes > 0 {
+		wampf = float64(diffWriteBytes*1000/diffSetBytes) / 1000.0
+	}
+
+	logger.Info("io_stats", "set_count", diffSetCount,
+		"set_bytes", diffSetBytes, "del_count", diffDelCount,
+		"read-bytes", diffReadBytes, "rps", rps,
+		"write_bytes", diffWriteBytes, "wps", wps,
+		"write_amp_f", wampf, "ellapsed", float64(dt.Milliseconds())/1000.0)
+}

baseapp/iostats_nop.go

@@ -0,0 +1,7 @@
+// +build !linux
+
+package baseapp
+
+func logIoStats(logger log.Logger) {
+	return
+}

go.mod

@@ -27,7 +27,7 @@ require (
 	github.com/gorilla/mux v1.8.0
 	github.com/grpc-ecosystem/go-grpc-middleware v1.3.0
 	github.com/grpc-ecosystem/grpc-gateway v1.16.0
-	github.com/line/iavl/v2 v2.0.0-init.1.0.20210602045707-fddfe1f85001
+	github.com/line/iavl/v2 v2.0.0-init.1.0.20211019080724-001e2272a25d
 	github.com/line/ostracon v0.34.9-0.20210930060702-30b70e254d83
 	github.com/line/tm-db/v2 v2.0.0-init.1.0.20210824011847-fcfa67dd3c70
 	github.com/line/wasmvm v0.14.0-0.8.0

go.sum

@@ -473,8 +473,8 @@ github.com/lightstep/lightstep-tracer-common/golang/gogo v0.0.0-20190605223551-b
 github.com/lightstep/lightstep-tracer-go v0.18.1/go.mod h1:jlF1pusYV4pidLvZ+XD0UBX0ZE6WURAspgAczcDHrL4=
 github.com/line/gorocksdb v0.0.0-20210406043732-d4bea34b6d55 h1:cXVtMiJkvQ4kn0pxM2svH1ncJbFgQsLHtnFC9qJj2VM=
 github.com/line/gorocksdb v0.0.0-20210406043732-d4bea34b6d55/go.mod h1:DHRJroSL7NaRkpvocRx3OtRsleXVsYSxBI9SfHFlTQ0=
-github.com/line/iavl/v2 v2.0.0-init.1.0.20210602045707-fddfe1f85001 h1:c2URk0zxM1vRgaRfIFoWkLzvj17nl/To9Q3NUVwY4+g=
-github.com/line/iavl/v2 v2.0.0-init.1.0.20210602045707-fddfe1f85001/go.mod h1:0Xz+0i1nlB9lrjUDEwpDRhcmjfEAkOjd20dRb40FBso=
+github.com/line/iavl/v2 v2.0.0-init.1.0.20211019080724-001e2272a25d h1:mXlamMU/uWGrW+7BJCUroZYo8mZ2q2zYS88dmsS0Ous=
+github.com/line/iavl/v2 v2.0.0-init.1.0.20211019080724-001e2272a25d/go.mod h1:0Xz+0i1nlB9lrjUDEwpDRhcmjfEAkOjd20dRb40FBso=
 github.com/line/ostracon v0.34.9-0.20210429084710-ef4fe0a40c7d/go.mod h1:ttnbq+yQJMQ9a2MT5SEisOoa/+pOgh2KenTiK/rVdiw=
 github.com/line/ostracon v0.34.9-0.20210930060702-30b70e254d83 h1:WuIvAw43Jhcr/F8ZcLFBf8jGPGPA8MxIf5fo4sHhqnM=
 github.com/line/ostracon v0.34.9-0.20210930060702-30b70e254d83/go.mod h1:elTiUFLvBz6Yaze+ZZLlbUnhqKWLJ7cMy/P9rSabafQ=