ended implementation of statistics for slowql-digest

cmd/slowql-digest/app.go

@@ -3,7 +3,6 @@ package main
 import (
 	"errors"
 	"sync"
-	"time"
 
 	"github.com/devops-works/slowql"
 	"github.com/devops-works/slowql/query"
@@ -62,10 +61,21 @@ func (a *app) digest(q query.Query, wg *sync.WaitGroup) error {
 		cur.Calls++
 		cur.CumBytesSent += q.BytesSent
 		cur.CumKilled += q.Killed
-		cur.CumLockTime += time.Duration(q.LockTime)
+		cur.CumLockTime += q.LockTime
 		cur.CumRowsExamined += q.RowsExamined
 		cur.CumRowsSent += q.RowsSent
-		s.CumQueryTime += time.Duration(q.QueryTime)
+		cur.CumQueryTime += q.QueryTime
+		cur.QueryTimes = append(cur.QueryTimes, q.QueryTime)
+
+		// update max time
+		if q.QueryTime > cur.MaxTime {
+			cur.MaxTime = q.QueryTime
+		}
+
+		// update min time
+		if q.QueryTime < cur.MinTime {
+			cur.MinTime = q.QueryTime
+		}
 
 		// update the entry in the map
 		a.res[s.Hash] = cur
@@ -74,10 +84,14 @@ func (a *app) digest(q query.Query, wg *sync.WaitGroup) error {
 		s.Calls++
 		s.CumBytesSent = q.BytesSent
 		s.CumKilled = q.Killed
-		s.CumLockTime = time.Duration(q.LockTime)
+		s.CumLockTime = q.LockTime
 		s.CumRowsExamined = q.RowsExamined
 		s.CumRowsSent = q.RowsSent
-		s.CumQueryTime = time.Duration(q.QueryTime)
+		s.CumQueryTime = q.QueryTime
+		s.MinTime = q.QueryTime
+		s.MaxTime = q.QueryTime
+		s.MeanTime = q.QueryTime
+		s.QueryTimes = append(s.QueryTimes, q.QueryTime)
 
 		// getting those values is done only once: same hash == same fingerprint & schema
 		s.Schema = q.Schema

cmd/slowql-digest/cache.go

@@ -9,9 +9,10 @@ import (
 
 // results is the datastrcucture that will be saved on disk
 type results struct {
-	File string       `json:"file"`
-	Date time.Time    `json:"date"`
-	Data []statistics `json:"data"`
+	File          string        `json:"file"`
+	Date          time.Time     `json:"date"`
+	TotalDuration time.Duration `json:"total_duration"`
+	Data          []statistics  `json:"data"`
 }
 
 // findCache looks a for a cache file stored in the same directory than the slow

cmd/slowql-digest/main.go

@@ -11,7 +11,6 @@ import (
 	"sync"
 	"time"
 
-	"github.com/cloudflare/cfssl/log"
 	"github.com/devops-works/slowql"
 	"github.com/devops-works/slowql/query"
 	. "github.com/logrusorgru/aurora"
@@ -46,22 +45,24 @@ type statistics struct {
 	Calls           int
 	CumErrored      int
 	CumKilled       int
-	CumQueryTime    time.Duration
-	CumLockTime     time.Duration
+	CumQueryTime    float64
+	CumLockTime     float64
 	CumRowsSent     int
 	CumRowsExamined int
 	CumBytesSent    int
 	Concurrency     float64
-	MinTime         time.Duration
-	MaxTime         time.Duration
-	MeanTime        time.Duration
-	P50Time         time.Duration
-	P95Time         time.Duration
-	StddevTime      time.Duration
+	MinTime         float64
+	MaxTime         float64
+	MeanTime        float64
+	P50Time         float64
+	P95Time         float64
+	StddevTime      float64
+	QueryTimes      []float64
 }
 
 var orders = []string{"random", "calls", "bytes_sent", "query_time", "lock_time",
-	"rows_sent", "rows_examined", "killed"}
+	"rows_sent", "rows_examined", "killed", "min_time", "max_time", "mean_time",
+	"p50", "p90", "concurrency"}
 
 func main() {
 	var o options
@@ -116,11 +117,16 @@ func main() {
 				}
 			}
 			a.logger.Infof("cache has timestamp: %s", res.Date)
-			showResults(cacheResults, o.order, o.top)
+			stats, err := computeStats(cacheResults, res.TotalDuration)
+			if err != nil {
+				a.logger.Errorf("cannot compute statistics: %s. This can lead to inacurrate stats")
+			}
+			showResults(stats, o.order, o.top, o.dec, res.TotalDuration)
 			return
 		}
 		a.logger.Info("cache will not be used")
 	}
+
 	a.fd, err = os.Open(o.logfile)
 	if err != nil {
 		a.logger.Fatalf("cannot open log file: %s", err)
@@ -143,6 +149,8 @@ func main() {
 
 	var q query.Query
 	var wg sync.WaitGroup
+	firstPass := true
+	var realStart, realEnd time.Time
 	a.p = slowql.NewParser(a.kind, a.fd)
 	a.logger.Debug("slowql parser created")
 	a.logger.Debug("query analysis started")
@@ -153,6 +161,11 @@ func main() {
 			a.logger.Debug("no more queries, breaking for loop")
 			break
 		}
+		if firstPass {
+			realStart = q.Time
+			firstPass = false
+		}
+		realEnd = q.Time
 		a.queriesNumber++
 		wg.Add(1)
 		go a.digest(q, &wg)
@@ -168,6 +181,12 @@ func main() {
 	for _, val := range a.res {
 		res = append(res, val)
 	}
+
+	realDuration := realEnd.Sub(realStart)
+	res, err = computeStats(res, realDuration)
+	if err != nil {
+		a.logger.Errorf("cannot compute statistics: %s. This can lead to inacurrate stats")
+	}
 	res, err = sortResults(res, o.order, o.dec)
 	if err != nil {
 		a.logger.Errorf("cannot sort results: %s", err)
@@ -178,23 +197,30 @@ func main() {
 		}
 	}
 
-	showResults(res, o.order, o.top)
+	fmt.Printf("real duration: %s\n", realDuration)
+	showResults(res, o.order, o.top, o.dec, realDuration)
+
 	if !o.nocache {
-		log.Info("saving results in cache file")
+		a.logger.Info("saving results in cache file")
 		cache := results{
-			File: o.logfile,
-			Date: time.Now(),
-			Data: res,
+			File:          o.logfile,
+			Date:          time.Now(),
+			TotalDuration: realDuration,
+			Data:          res,
 		}
 		if err := saveCache(cache); err != nil {
-			log.Errorf("cannot save results in cache file: %s", err)
+			a.logger.Errorf("cannot save results in cache file: %s", err)
 		}
 	}
 	a.logger.Debug("end of program, exiting")
 }
 
-func showResults(res []statistics, order string, count int) {
-	fmt.Printf("\nSorted by: %s\n", Bold(order))
+func showResults(res []statistics, order string, count int, dec bool, realDuration time.Duration) {
+	howTo := "increasing"
+	if dec {
+		howTo = "decreasing"
+	}
+	fmt.Printf("\nSorted by: %s, %s\n", Bold(order), Bold(howTo))
 	fmt.Printf("Showing top %d queries\n", Bold(count))
 	for i := 0; i < len(res); i++ {
 		if count == 0 {
@@ -203,29 +229,39 @@ func showResults(res []statistics, order string, count int) {
 
 		fmt.Printf(`
 %s%d
-Calls:             %d
-Hash:              %s
-Fingerprint:       %s
-Schema:            %s
-Cum Bytes sent:    %d
-Cum Rows Examined: %d
-Cum Rows Sent:     %d
-Cum Killed:        %d
-Cum Lock Time:     %s
-Cum Query Time:    %s
+Calls:                  %d
+Hash:                   %s
+Fingerprint:            %s
+Schema:                 %s
+Min/Max/Mean time:      %s/%s/%s
+p50/p95:                %s/%s
+Concurrency:            %2.2f%%
+Standard deviation:     %s
+Cum Query Time:         %s
+Cum Lock Time:          %s
+Cum Bytes sent:         %d
+Cum Rows Examined/Sent: %d/%d
+Cum Killed:             %d
 			`,
 			Bold(Underline("Query #")),
 			Bold(Underline(i+1)),
 			res[i].Calls,
 			res[i].Hash,
 			res[i].Fingerprint,
 			res[i].Schema,
+			fsecsToDuration(res[i].MinTime),
+			fsecsToDuration(res[i].MaxTime),
+			fsecsToDuration(res[i].MeanTime),
+			fsecsToDuration(res[i].P50Time),
+			fsecsToDuration(res[i].P95Time),
+			res[i].Concurrency,
+			fsecsToDuration(res[i].StddevTime),
+			fsecsToDuration(res[i].CumQueryTime),
+			fsecsToDuration(res[i].CumLockTime),
 			res[i].CumBytesSent,
 			res[i].CumRowsExamined,
 			res[i].CumRowsSent,
 			res[i].CumKilled,
-			res[i].CumLockTime,
-			res[i].CumQueryTime,
 		)
 
 		count--
@@ -251,7 +287,6 @@ func lineCounter(r io.Reader) (int, error) {
 }
 
 func sortResults(s []statistics, order string, dec bool) ([]statistics, error) {
-
 	switch order {
 	case "random":
 		break
@@ -283,6 +318,30 @@ func sortResults(s []statistics, order string, dec bool) ([]statistics, error) {
 		sort.SliceStable(s, func(i, j int) bool {
 			return s[i].CumKilled < s[j].CumKilled
 		})
+	case "min_time":
+		sort.SliceStable(s, func(i, j int) bool {
+			return s[i].MinTime < s[j].MinTime
+		})
+	case "max_time":
+		sort.SliceStable(s, func(i, j int) bool {
+			return s[i].MaxTime < s[j].MaxTime
+		})
+	case "mean_time":
+		sort.SliceStable(s, func(i, j int) bool {
+			return s[i].MeanTime < s[j].MeanTime
+		})
+	case "p50", "P50":
+		sort.SliceStable(s, func(i, j int) bool {
+			return s[i].P50Time < s[j].P50Time
+		})
+	case "p95", "P95":
+		sort.SliceStable(s, func(i, j int) bool {
+			return s[i].P95Time < s[j].P95Time
+		})
+	case "concurrency":
+		sort.SliceStable(s, func(i, j int) bool {
+			return s[i].Concurrency < s[j].Concurrency
+		})
 	default:
 		return nil, errors.New("unknown order, using 'random'")
 	}

cmd/slowql-digest/stats.go

@@ -4,7 +4,11 @@ import (
 	"crypto/md5"
 	"fmt"
 	"regexp"
+	"sort"
 	"strings"
+	"time"
+
+	"github.com/montanaflynn/stats"
 )
 
 var regexeps []replacements
@@ -82,3 +86,46 @@ func init() {
 
 	}
 }
+
+// fsecsToDuration converts float seconds to time.Duration
+// Since we have float64 seconds durations
+// We first convert to µs (* 1e6) then to duration
+func fsecsToDuration(d float64) time.Duration {
+	return time.Duration(d*1e6) * time.Microsecond
+}
+
+func computeStats(res []statistics, realDuration time.Duration) ([]statistics, error) {
+	var err error
+	ffactor := 100.0 * float64(time.Second) / float64(realDuration)
+	for i := 0; i < len(res); i++ {
+
+		// Mean time
+		res[i].MeanTime = res[i].CumQueryTime / float64(res[i].Calls)
+
+		// Compute percentiles
+		var arr []float64
+		arr = append(arr, res[i].QueryTimes...)
+		sort.Slice(arr, func(i, j int) bool {
+			return arr[i] < arr[j]
+		})
+		res[i].P95Time, err = stats.Percentile(arr, 95)
+		if err != nil {
+			return nil, err
+		}
+		res[i].P50Time, err = stats.Percentile(arr, 50)
+		if err != nil {
+			return nil, err
+		}
+
+		// compute stddev
+		res[i].StddevTime, err = stats.StandardDeviation(arr)
+		if err != nil {
+			return nil, err
+		}
+
+		// compute concurrency
+		res[i].Concurrency = res[i].CumQueryTime * ffactor
+	}
+
+	return res, nil
+}

go.mod

@@ -4,10 +4,12 @@ go 1.15
 
 require (
 	github.com/cheggaaa/pb/v3 v3.0.8
-	github.com/cloudflare/cfssl v1.5.0
 	github.com/go-sql-driver/mysql v1.5.0
+	github.com/kr/pretty v0.1.0 // indirect
 	github.com/logrusorgru/aurora v2.0.3+incompatible
+	github.com/montanaflynn/stats v0.6.5
 	github.com/sirupsen/logrus v1.8.0
+	github.com/stretchr/testify v1.4.0 // indirect
 	golang.org/x/term v0.0.0-20201117132131-f5c789dd3221
 	gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 // indirect
 	gopkg.in/yaml.v2 v2.3.0 // indirect