diff --git a/CHANGELOG.md b/CHANGELOG.md index 0710288d4f..8e5dfd6ce8 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/baseapp/abci.go b/baseapp/abci.go index d30d7377ad..818e0a3161 100644 --- a/baseapp/abci.go +++ b/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 diff --git a/baseapp/iostats.go b/baseapp/iostats.go new file mode 100644 index 0000000000..347e7e3bbf --- /dev/null +++ b/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) +} diff --git a/baseapp/iostats_nop.go b/baseapp/iostats_nop.go new file mode 100644 index 0000000000..802ec1b4c8 --- /dev/null +++ b/baseapp/iostats_nop.go @@ -0,0 +1,7 @@ +// +build !linux + +package baseapp + +func logIoStats(logger log.Logger) { + return +} diff --git a/go.mod b/go.mod index fd86bc22c3..50ace1d83f 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 160f3e7ff0..0fa47087d7 100644 --- a/go.sum +++ b/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=