From 64a5c6d8b68fb46c8e645c49defefc283f50c494 Mon Sep 17 00:00:00 2001 From: Carlos Salguero Date: Sun, 9 Apr 2017 23:21:27 -0300 Subject: [PATCH] New profiler and tests --- src/go/mongolib/profiler/profiler.go | 364 +++++++++++---- src/go/mongolib/profiler/profiler_test.go | 273 ++++++++++++ src/go/pt-mongodb-query-digest/main.go | 242 ++-------- .../test/sample/system.profile.json | 414 ------------------ src/go/tests/profiler_docs.json | 164 +++++++ 5 files changed, 735 insertions(+), 722 deletions(-) create mode 100644 src/go/mongolib/profiler/profiler_test.go delete mode 100644 src/go/pt-mongodb-query-digest/test/sample/system.profile.json create mode 100644 src/go/tests/profiler_docs.json diff --git a/src/go/mongolib/profiler/profiler.go b/src/go/mongolib/profiler/profiler.go index 02789f90..bebfd3d9 100644 --- a/src/go/mongolib/profiler/profiler.go +++ b/src/go/mongolib/profiler/profiler.go @@ -2,23 +2,30 @@ package profiler import ( "crypto/md5" + "encoding/json" "errors" "fmt" + "sync" "time" + "github.com/montanaflynn/stats" "github.com/percona/percona-toolkit/src/go/mongolib/fingerprinter" "github.com/percona/percona-toolkit/src/go/mongolib/proto" "github.com/percona/percona-toolkit/src/go/mongolib/util" "github.com/percona/percona-toolkit/src/go/pt-mongodb-query-digest/filter" - "github.com/prometheus/common/log" + "github.com/percona/pmgo" ) var ( - MAX_DEPTH_LEVEL = 10 - DOCS_BUFFER_SIZE = 100 - CANNOT_GET_QUERY_ERROR = errors.New("cannot get query field from the profile document (it is not a map)") + // MaxDepthLevel Max recursion level for the fingerprinter + MaxDepthLevel = 10 + // DocsBufferSize is the buffer size to store documents from the MongoDB profiler + DocsBufferSize = 100 + // ErrCannotGetQuery is the error returned if we cannot find a query into the profiler document + ErrCannotGetQuery = errors.New("cannot get query field from the profile document (it is not a map)") ) +// Times is an array of time.Time that implements the Sorter interface type Times []time.Time func (a Times) Len() int { return len(a) } @@ -31,64 +38,98 @@ type StatsGroupKey struct { Namespace string } -type Stat struct { - BlockedTime Times - Count int - Fingerprint string - FirstSeen time.Time - ID string - LastSeen time.Time - LockTime Times - NReturned []float64 - NScanned []float64 - Namespace string - Operation string - Query map[string]interface{} - QueryTime []float64 // in milliseconds - ResponseLength []float64 - TableScan bool -} - -type Iter interface { - All(result interface{}) error - Close() error - Err() error - For(result interface{}, f func() error) (err error) - Next(result interface{}) bool - Timeout() bool +type totalCounters struct { + Count int + Scanned float64 + Returned float64 + QueryTime float64 + Bytes float64 } type Profiler interface { GetLastError() error - StatsChan() chan []Stat + QueriesChan() chan []QueryInfoAndCounters + TimeoutsChan() <-chan time.Time Start() Stop() } type Profile struct { - filters []filter.Filter - iterator Iter - ticker chan time.Time - statsChan chan []Stat - stopChan chan bool - docsChan chan proto.SystemProfile - rawStats map[StatsGroupKey]*Stat - keyFilters []string - fingerprinter fingerprinter.Fingerprinter - running bool - lastError error + filters []filter.Filter + iterator pmgo.IterManager + ticker <-chan time.Time + queriesChan chan []QueryInfoAndCounters + stopChan chan bool + docsChan chan proto.SystemProfile + timeoutsChan chan time.Time + queriesInfoAndCounters map[StatsGroupKey]*QueryInfoAndCounters + keyFilters []string + fingerprinter fingerprinter.Fingerprinter + running bool + lastError error + stopWaitGroup sync.WaitGroup } -func NewProfiler(iterator Iter, filters []filter.Filter, ticker chan time.Time, fp fingerprinter.Fingerprinter) Profiler { +type QueryStats struct { + ID string + Namespace string + Operation string + Query string + Fingerprint string + FirstSeen time.Time + LastSeen time.Time + + Count int + QPS float64 + Rank int + Ratio float64 + QueryTime Statistics + ResponseLength Statistics + Returned Statistics + Scanned Statistics +} + +type QueryInfoAndCounters struct { + ID string + Namespace string + Operation string + Query map[string]interface{} + Fingerprint string + FirstSeen time.Time + LastSeen time.Time + TableScan bool + + Count int + BlockedTime Times + LockTime Times + NReturned []float64 + NScanned []float64 + QueryTime []float64 // in milliseconds + ResponseLength []float64 +} + +type Statistics struct { + Pct float64 + Total float64 + Min float64 + Max float64 + Avg float64 + Pct95 float64 + StdDev float64 + Median float64 +} + +func NewProfiler(iterator pmgo.IterManager, filters []filter.Filter, ticker <-chan time.Time, fp fingerprinter.Fingerprinter) Profiler { return &Profile{ - filters: filters, - fingerprinter: fp, - iterator: iterator, - ticker: ticker, - statsChan: make(chan []Stat), - docsChan: make(chan proto.SystemProfile, DOCS_BUFFER_SIZE), - rawStats: make(map[StatsGroupKey]*Stat), - keyFilters: []string{"^shardVersion$", "^\\$"}, + filters: filters, + fingerprinter: fp, + iterator: iterator, + ticker: ticker, + queriesChan: make(chan []QueryInfoAndCounters), + docsChan: make(chan proto.SystemProfile, DocsBufferSize), + timeoutsChan: nil, + queriesInfoAndCounters: make(map[StatsGroupKey]*QueryInfoAndCounters), + keyFilters: []string{"^shardVersion$", "^\\$"}, } } @@ -96,37 +137,54 @@ func (p *Profile) GetLastError() error { return p.lastError } -func (p *Profile) StatsChan() chan []Stat { - return p.statsChan +func (p *Profile) QueriesChan() chan []QueryInfoAndCounters { + return p.queriesChan } func (p *Profile) Start() { if !p.running { p.running = true + p.stopChan = make(chan bool) go p.getData() } } func (p *Profile) Stop() { if p.running { + select { + case p.stopChan <- true: + default: + } + close(p.timeoutsChan) + // Wait for getData to receive the stop signal + p.stopWaitGroup.Wait() p.iterator.Close() - close(p.stopChan) } } +func (p *Profile) TimeoutsChan() <-chan time.Time { + if p.timeoutsChan == nil { + p.timeoutsChan = make(chan time.Time) + } + return p.timeoutsChan +} + func (p *Profile) getData() { go p.getDocs() + p.stopWaitGroup.Add(1) + MAIN_GETDATA_LOOP: for { select { case <-p.ticker: - p.statsChan <- statsToArray(p.rawStats) - p.rawStats = make(map[StatsGroupKey]*Stat) // Reset stats + p.queriesChan <- mapToArray(p.queriesInfoAndCounters) + p.queriesInfoAndCounters = make(map[StatsGroupKey]*QueryInfoAndCounters) // Reset stats case <-p.stopChan: p.iterator.Close() break MAIN_GETDATA_LOOP } } + p.stopWaitGroup.Done() } func (p *Profile) getDocs() { @@ -134,6 +192,9 @@ func (p *Profile) getDocs() { for p.iterator.Next(&doc) || p.iterator.Timeout() { if p.iterator.Timeout() { + if p.timeoutsChan != nil { + p.timeoutsChan <- time.Now().UTC() + } continue } valid := true @@ -147,52 +208,161 @@ func (p *Profile) getDocs() { continue } if len(doc.Query) > 0 { - - fp, err := p.fingerprinter.Fingerprint(doc.Query) - if err != nil { - log.Errorf("cannot get fingerprint: %s", err.Error()) - continue - } - var s *Stat - var ok bool - key := StatsGroupKey{ - Operation: doc.Op, - Fingerprint: fp, - Namespace: doc.Ns, - } - if s, ok = p.rawStats[key]; !ok { - realQuery, _ := util.GetQueryField(doc.Query) - s = &Stat{ - ID: fmt.Sprintf("%x", md5.Sum([]byte(fmt.Sprintf("%s", key)))), - Operation: doc.Op, - Fingerprint: fp, - Namespace: doc.Ns, - TableScan: false, - Query: realQuery, - } - p.rawStats[key] = s - } - s.Count++ - s.NScanned = append(s.NScanned, float64(doc.DocsExamined)) - s.NReturned = append(s.NReturned, float64(doc.Nreturned)) - s.QueryTime = append(s.QueryTime, float64(doc.Millis)) - s.ResponseLength = append(s.ResponseLength, float64(doc.ResponseLength)) - var zeroTime time.Time - if s.FirstSeen == zeroTime || s.FirstSeen.After(doc.Ts) { - s.FirstSeen = doc.Ts - } - if s.LastSeen == zeroTime || s.LastSeen.Before(doc.Ts) { - s.LastSeen = doc.Ts - } + p.ProcessDoc(doc, p.queriesInfoAndCounters) } } - p.statsChan <- statsToArray(p.rawStats) - p.running = false - p.stopChan <- true + p.queriesChan <- mapToArray(p.queriesInfoAndCounters) + select { + case p.stopChan <- true: + default: + } } -func statsToArray(stats map[StatsGroupKey]*Stat) []Stat { - sa := []Stat{} +func (p *Profile) ProcessDoc(doc proto.SystemProfile, stats map[StatsGroupKey]*QueryInfoAndCounters) error { + + fp, err := p.fingerprinter.Fingerprint(doc.Query) + if err != nil { + return fmt.Errorf("cannot get fingerprint: %s", err.Error()) + } + var s *QueryInfoAndCounters + var ok bool + key := StatsGroupKey{ + Operation: doc.Op, + Fingerprint: fp, + Namespace: doc.Ns, + } + if s, ok = p.queriesInfoAndCounters[key]; !ok { + realQuery, _ := util.GetQueryField(doc.Query) + s = &QueryInfoAndCounters{ + ID: fmt.Sprintf("%x", md5.Sum([]byte(fmt.Sprintf("%s", key)))), + Operation: doc.Op, + Fingerprint: fp, + Namespace: doc.Ns, + TableScan: false, + Query: realQuery, + } + p.queriesInfoAndCounters[key] = s + } + s.Count++ + s.NScanned = append(s.NScanned, float64(doc.DocsExamined)) + s.NReturned = append(s.NReturned, float64(doc.Nreturned)) + s.QueryTime = append(s.QueryTime, float64(doc.Millis)) + s.ResponseLength = append(s.ResponseLength, float64(doc.ResponseLength)) + var zeroTime time.Time + if s.FirstSeen == zeroTime || s.FirstSeen.After(doc.Ts) { + s.FirstSeen = doc.Ts + } + if s.LastSeen == zeroTime || s.LastSeen.Before(doc.Ts) { + s.LastSeen = doc.Ts + } + + return nil + +} + +func CalcQueriesStats(queries []QueryInfoAndCounters, uptime int64) []QueryStats { + stats := []QueryStats{} + tc := calcTotalCounters(queries) + + for _, query := range queries { + queryStats := CountersToStats(query, uptime, tc) + stats = append(stats, queryStats) + } + + return stats +} + +func CalcTotalQueriesStats(queries []QueryInfoAndCounters, uptime int64) QueryStats { + tc := calcTotalCounters(queries) + + totalQueryInfoAndCounters := aggregateCounters(queries) + totalStats := CountersToStats(totalQueryInfoAndCounters, uptime, tc) + + return totalStats +} + +func CountersToStats(query QueryInfoAndCounters, uptime int64, tc totalCounters) QueryStats { + buf, _ := json.Marshal(query.Query) + queryStats := QueryStats{ + Count: query.Count, + ID: query.ID, + Operation: query.Operation, + Query: string(buf), + Fingerprint: query.Fingerprint, + Scanned: calcStats(query.NScanned), + Returned: calcStats(query.NReturned), + QueryTime: calcStats(query.QueryTime), + ResponseLength: calcStats(query.ResponseLength), + FirstSeen: query.FirstSeen, + LastSeen: query.LastSeen, + Namespace: query.Namespace, + QPS: float64(query.Count) / float64(uptime), + } + if tc.Scanned > 0 { + queryStats.Scanned.Pct = queryStats.Scanned.Total * 100 / tc.Scanned + } + if tc.Returned > 0 { + queryStats.Returned.Pct = queryStats.Returned.Total * 100 / tc.Returned + } + if tc.QueryTime > 0 { + queryStats.QueryTime.Pct = queryStats.QueryTime.Total * 100 / tc.QueryTime + } + if tc.Bytes > 0 { + queryStats.ResponseLength.Pct = queryStats.ResponseLength.Total / tc.Bytes + } + if queryStats.Returned.Total > 0 { + queryStats.Ratio = queryStats.Scanned.Total / queryStats.Returned.Total + } + + return queryStats +} + +func aggregateCounters(queries []QueryInfoAndCounters) QueryInfoAndCounters { + qt := QueryInfoAndCounters{} + for _, query := range queries { + qt.NScanned = append(qt.NScanned, query.NScanned...) + qt.NReturned = append(qt.NReturned, query.NReturned...) + qt.QueryTime = append(qt.QueryTime, query.QueryTime...) + qt.ResponseLength = append(qt.ResponseLength, query.ResponseLength...) + } + return qt +} + +func calcTotalCounters(queries []QueryInfoAndCounters) totalCounters { + tc := totalCounters{} + + for _, query := range queries { + tc.Count += query.Count + + scanned, _ := stats.Sum(query.NScanned) + tc.Scanned += scanned + + returned, _ := stats.Sum(query.NReturned) + tc.Returned += returned + + queryTime, _ := stats.Sum(query.QueryTime) + tc.QueryTime += queryTime + + bytes, _ := stats.Sum(query.ResponseLength) + tc.Bytes += bytes + } + return tc +} + +func calcStats(samples []float64) Statistics { + var s Statistics + s.Total, _ = stats.Sum(samples) + s.Min, _ = stats.Min(samples) + s.Max, _ = stats.Max(samples) + s.Avg, _ = stats.Mean(samples) + s.Pct95, _ = stats.PercentileNearestRank(samples, 95) + s.StdDev, _ = stats.StandardDeviation(samples) + s.Median, _ = stats.Median(samples) + return s +} + +func mapToArray(stats map[StatsGroupKey]*QueryInfoAndCounters) []QueryInfoAndCounters { + sa := []QueryInfoAndCounters{} for _, s := range stats { sa = append(sa, *s) } diff --git a/src/go/mongolib/profiler/profiler_test.go b/src/go/mongolib/profiler/profiler_test.go new file mode 100644 index 00000000..22cfc819 --- /dev/null +++ b/src/go/mongolib/profiler/profiler_test.go @@ -0,0 +1,273 @@ +package profiler + +import ( + "log" + "os" + "reflect" + "testing" + "time" + + "github.com/golang/mock/gomock" + "github.com/percona/percona-toolkit/src/go/lib/tutil" + "github.com/percona/percona-toolkit/src/go/mongolib/fingerprinter" + "github.com/percona/percona-toolkit/src/go/mongolib/proto" + "github.com/percona/percona-toolkit/src/go/pt-mongodb-query-digest/filter" + "github.com/percona/pmgo/pmgomock" +) + +const ( + samples = "/src/go/tests/" +) + +type testVars struct { + RootPath string +} + +var vars testVars + +func TestMain(m *testing.M) { + var err error + if vars.RootPath, err = tutil.RootPath(); err != nil { + log.Printf("cannot get root path: %s", err.Error()) + os.Exit(1) + } + os.Exit(m.Run()) +} + +func TestRegularIterator(t *testing.T) { + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + docs := []proto.SystemProfile{} + err := tutil.LoadJson(vars.RootPath+samples+"profiler_docs.json", &docs) + if err != nil { + t.Fatalf("cannot load samples: %s", err.Error()) + } + + iter := pmgomock.NewMockIterManager(ctrl) + gomock.InOrder( + iter.EXPECT().Next(gomock.Any()).SetArg(0, docs[0]).Return(true), + iter.EXPECT().Timeout().Return(false), + iter.EXPECT().Next(gomock.Any()).SetArg(0, docs[1]).Return(true), + iter.EXPECT().Timeout().Return(false), + iter.EXPECT().Next(gomock.Any()).Return(false), + iter.EXPECT().Timeout().Return(false), + iter.EXPECT().Close(), + ) + filters := []filter.Filter{} + fp := fingerprinter.NewFingerprinter(fingerprinter.DEFAULT_KEY_FILTERS) + prof := NewProfiler(iter, filters, nil, fp) + + firstSeen, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:19.914-03:00") + lastSeen, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:20.214-03:00") + want := []QueryInfoAndCounters{ + QueryInfoAndCounters{ + ID: "c6466139b21c392acd0699e863b50d81", + Namespace: "samples.col1", + Operation: "query", + Query: map[string]interface{}{ + "find": "col1", + "shardVersion": []interface{}{float64(0), "000000000000000000000000"}, + }, + Fingerprint: "find", + FirstSeen: firstSeen, + LastSeen: lastSeen, + TableScan: false, + Count: 2, + BlockedTime: Times(nil), + LockTime: Times(nil), + NReturned: []float64{50, 75}, + NScanned: []float64{100, 75}, + QueryTime: []float64{0, 1}, + ResponseLength: []float64{1.06123e+06, 1.06123e+06}, + }, + } + prof.Start() + select { + case queries := <-prof.QueriesChan(): + if !reflect.DeepEqual(queries, want) { + t.Errorf("invalid queries. \nGot: %#v,\nWant: %#v\n", queries, want) + } + case <-time.After(2 * time.Second): + t.Error("Didn't get any query") + } +} + +func TestIteratorTimeout(t *testing.T) { + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + docs := []proto.SystemProfile{} + err := tutil.LoadJson(vars.RootPath+samples+"profiler_docs.json", &docs) + if err != nil { + t.Fatalf("cannot load samples: %s", err.Error()) + } + + iter := pmgomock.NewMockIterManager(ctrl) + gomock.InOrder( + iter.EXPECT().Next(gomock.Any()).Return(true), + iter.EXPECT().Timeout().Return(true), + iter.EXPECT().Next(gomock.Any()).SetArg(0, docs[1]).Return(true), + iter.EXPECT().Timeout().Return(false), + iter.EXPECT().Next(gomock.Any()).Return(false), + iter.EXPECT().Timeout().Return(false), + // When there are no more docs, iterator will close + iter.EXPECT().Close(), + // And we are closing it again (to force the getData go-routine to end) + // at the profiler.Stop() method + iter.EXPECT().Close(), + ) + filters := []filter.Filter{} + + fp := fingerprinter.NewFingerprinter(fingerprinter.DEFAULT_KEY_FILTERS) + prof := NewProfiler(iter, filters, nil, fp) + + firstSeen, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:19.914-03:00") + lastSeen, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:19.914-03:00") + want := []QueryInfoAndCounters{ + QueryInfoAndCounters{ + ID: "c6466139b21c392acd0699e863b50d81", + Namespace: "samples.col1", + Operation: "query", + Query: map[string]interface{}{ + "find": "col1", + "shardVersion": []interface{}{float64(0), "000000000000000000000000"}, + }, + Fingerprint: "find", + FirstSeen: firstSeen, + LastSeen: lastSeen, + TableScan: false, + Count: 1, + BlockedTime: Times(nil), + LockTime: Times(nil), + NReturned: []float64{75}, + NScanned: []float64{75}, + QueryTime: []float64{1}, + ResponseLength: []float64{1.06123e+06}, + }, + } + + prof.Start() + gotTimeout := false + + // Get a timeout + select { + case <-prof.TimeoutsChan(): + gotTimeout = true + case <-prof.QueriesChan(): + t.Error("Got queries before timeout") + case <-time.After(2 * time.Second): + t.Error("Timeout checking timeout") + } + if !gotTimeout { + t.Error("Didn't get a timeout") + } + + // After the first document returned a timeout, we should still receive the second document + select { + case queries := <-prof.QueriesChan(): + if !reflect.DeepEqual(queries, want) { + t.Errorf("invalid queries. \nGot: %#v,\nWant: %#v\n", queries, want) + } + case <-time.After(2 * time.Second): + t.Error("Didn't get any query after 2 seconds") + } + + prof.Stop() +} + +func TestTailIterator(t *testing.T) { + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + docs := []proto.SystemProfile{} + err := tutil.LoadJson(vars.RootPath+samples+"profiler_docs.json", &docs) + if err != nil { + t.Fatalf("cannot load samples: %s", err.Error()) + } + + sleep := func(param interface{}) { + time.Sleep(1500 * time.Millisecond) + } + + iter := pmgomock.NewMockIterManager(ctrl) + gomock.InOrder( + iter.EXPECT().Next(gomock.Any()).SetArg(0, docs[0]).Return(true), + iter.EXPECT().Timeout().Return(false), + // A Tail iterator will wait if the are no available docs. + // Do a 1500 ms sleep before returning the second doc to simulate a tail wait + // and to let the ticker ticks + iter.EXPECT().Next(gomock.Any()).Do(sleep).SetArg(0, docs[1]).Return(true), + iter.EXPECT().Timeout().Return(false), + iter.EXPECT().Next(gomock.Any()).Return(false), + iter.EXPECT().Timeout().Return(false), + iter.EXPECT().Close(), + ) + + filters := []filter.Filter{} + ticker := time.NewTicker(time.Second) + fp := fingerprinter.NewFingerprinter(fingerprinter.DEFAULT_KEY_FILTERS) + prof := NewProfiler(iter, filters, ticker.C, fp) + + firstSeen, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:20.214-03:00") + lastSeen, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:20.214-03:00") + + firstSeen2, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:19.914-03:00") + lastSeen2, _ := time.Parse(time.RFC3339Nano, "2017-04-01T23:01:19.914-03:00") + + want := []QueryInfoAndCounters{ + QueryInfoAndCounters{ + ID: "c6466139b21c392acd0699e863b50d81", + Namespace: "samples.col1", + Operation: "query", + Query: map[string]interface{}{ + "find": "col1", + "shardVersion": []interface{}{float64(0), "000000000000000000000000"}, + }, + Fingerprint: "find", + FirstSeen: firstSeen, + LastSeen: lastSeen, + TableScan: false, + Count: 1, + BlockedTime: Times(nil), + LockTime: Times(nil), + NReturned: []float64{50}, + NScanned: []float64{100}, + QueryTime: []float64{0}, + ResponseLength: []float64{1.06123e+06}, + }, + QueryInfoAndCounters{ + ID: "c6466139b21c392acd0699e863b50d81", + Namespace: "samples.col1", + Operation: "query", + Query: map[string]interface{}{ + "find": "col1", + "shardVersion": []interface{}{float64(0), "000000000000000000000000"}, + }, + Fingerprint: "find", + FirstSeen: firstSeen2, + LastSeen: lastSeen2, + TableScan: false, + Count: 1, + BlockedTime: Times(nil), + LockTime: Times(nil), + NReturned: []float64{75}, + NScanned: []float64{75}, + QueryTime: []float64{1}, + ResponseLength: []float64{1.06123e+06}, + }, + } + prof.Start() + index := 0 + // Since the mocked iterator has a Sleep(1500 ms) between Next methods calls, + // we are going to have two ticker ticks and on every tick it will return one document. + for index < 2 { + select { + case queries := <-prof.QueriesChan(): + if !reflect.DeepEqual(queries, []QueryInfoAndCounters{want[index]}) { + t.Errorf("invalid queries. \nGot: %#v,\nWant: %#v\n", queries, want) + } + index++ + } + } +} diff --git a/src/go/pt-mongodb-query-digest/main.go b/src/go/pt-mongodb-query-digest/main.go index 093bd40a..b078a82c 100644 --- a/src/go/pt-mongodb-query-digest/main.go +++ b/src/go/pt-mongodb-query-digest/main.go @@ -1,7 +1,6 @@ package main import ( - "encoding/json" "fmt" "os" "sort" @@ -10,7 +9,6 @@ import ( "time" "github.com/howeyc/gopass" - "github.com/montanaflynn/stats" "github.com/pborman/getopt" "github.com/percona/percona-toolkit/src/go/lib/config" "github.com/percona/percona-toolkit/src/go/lib/versioncheck" @@ -59,41 +57,6 @@ type options struct { Version bool } -// This func receives a doc from the profiler and returns: -// true : the document must be considered -// false: the document must be skipped -type docsFilter func(proto.SystemProfile) bool - -type statistics struct { - Pct float64 - Total float64 - Min float64 - Max float64 - Avg float64 - Pct95 float64 - StdDev float64 - Median float64 -} - -type queryInfo struct { - Count int - Operation string - Query string - Fingerprint string - FirstSeen time.Time - ID string - LastSeen time.Time - Namespace string - NoVersionCheck bool - QPS float64 - QueryTime statistics - Rank int - Ratio float64 - ResponseLength statistics - Returned statistics - Scanned statistics -} - func main() { opts, err := getOptions() @@ -174,29 +137,28 @@ func main() { fp := fingerprinter.NewFingerprinter(fingerprinter.DEFAULT_KEY_FILTERS) prof := profiler.NewProfiler(i, filters, nil, fp) prof.Start() - queries := <-prof.StatsChan() - - queries = sortQueries(queries, opts.OrderBy) + queries := <-prof.QueriesChan() uptime := uptime(session) + queriesStats := profiler.CalcQueriesStats(queries, uptime) + sortedQueryStats := sortQueries(queriesStats, opts.OrderBy) printHeader(opts) - queryTotals := calcTotalQueryStats(queries, uptime) + queryTotals := profiler.CalcTotalQueriesStats(queries, uptime) tt, _ := template.New("query").Funcs(template.FuncMap{ "Format": format, }).Parse(getTotalsTemplate()) tt.Execute(os.Stdout, queryTotals) - queryStats := calcQueryStats(queries, uptime) t, _ := template.New("query").Funcs(template.FuncMap{ "Format": format, }).Parse(getQueryTemplate()) - if opts.Limit > 0 && len(queryStats) > opts.Limit { - queryStats = queryStats[:opts.Limit] + if opts.Limit > 0 && len(sortedQueryStats) > opts.Limit { + sortedQueryStats = sortedQueryStats[:opts.Limit] } - for _, qs := range queryStats { + for _, qs := range sortedQueryStats { t.Execute(os.Stdout, qs) } @@ -238,128 +200,6 @@ func uptime(session pmgo.SessionManager) int64 { return ss.Uptime } -func calcTotalQueryStats(queries []profiler.Stat, uptime int64) queryInfo { - qi := queryInfo{} - qs := profiler.Stat{} - _, totalScanned, totalReturned, totalQueryTime, totalBytes := calcTotals(queries) - for _, query := range queries { - qs.NScanned = append(qs.NScanned, query.NScanned...) - qs.NReturned = append(qs.NReturned, query.NReturned...) - qs.QueryTime = append(qs.QueryTime, query.QueryTime...) - qs.ResponseLength = append(qs.ResponseLength, query.ResponseLength...) - qi.Count += query.Count - } - - qi.Scanned = calcStats(qs.NScanned) - qi.Returned = calcStats(qs.NReturned) - qi.QueryTime = calcStats(qs.QueryTime) - qi.ResponseLength = calcStats(qs.ResponseLength) - - if totalScanned > 0 { - qi.Scanned.Pct = qi.Scanned.Total * 100 / totalScanned - } - if totalReturned > 0 { - qi.Returned.Pct = qi.Returned.Total * 100 / totalReturned - } - if totalQueryTime > 0 { - qi.QueryTime.Pct = qi.QueryTime.Total * 100 / totalQueryTime - } - if totalBytes > 0 { - qi.ResponseLength.Pct = qi.ResponseLength.Total / totalBytes - } - if qi.Returned.Total > 0 { - qi.Ratio = qi.Scanned.Total / qi.Returned.Total - } - - return qi -} - -func calcQueryStats(queries []profiler.Stat, uptime int64) []queryInfo { - queryStats := []queryInfo{} - _, totalScanned, totalReturned, totalQueryTime, totalBytes := calcTotals(queries) - for rank, query := range queries { - buf, _ := json.Marshal(query.Query) - qi := queryInfo{ - Rank: rank, - Count: query.Count, - ID: query.ID, - Operation: query.Operation, - Query: string(buf), - Fingerprint: query.Fingerprint, - Scanned: calcStats(query.NScanned), - Returned: calcStats(query.NReturned), - QueryTime: calcStats(query.QueryTime), - ResponseLength: calcStats(query.ResponseLength), - FirstSeen: query.FirstSeen, - LastSeen: query.LastSeen, - Namespace: query.Namespace, - QPS: float64(query.Count) / float64(uptime), - } - if totalScanned > 0 { - qi.Scanned.Pct = qi.Scanned.Total * 100 / totalScanned - } - if totalReturned > 0 { - qi.Returned.Pct = qi.Returned.Total * 100 / totalReturned - } - if totalQueryTime > 0 { - qi.QueryTime.Pct = qi.QueryTime.Total * 100 / totalQueryTime - } - if totalBytes > 0 { - qi.ResponseLength.Pct = qi.ResponseLength.Total / totalBytes - } - if qi.Returned.Total > 0 { - qi.Ratio = qi.Scanned.Total / qi.Returned.Total - } - queryStats = append(queryStats, qi) - } - return queryStats -} - -func getTotals(queries []profiler.Stat) profiler.Stat { - - qt := profiler.Stat{} - for _, query := range queries { - qt.NScanned = append(qt.NScanned, query.NScanned...) - qt.NReturned = append(qt.NReturned, query.NReturned...) - qt.QueryTime = append(qt.QueryTime, query.QueryTime...) - qt.ResponseLength = append(qt.ResponseLength, query.ResponseLength...) - } - return qt - -} - -func calcTotals(queries []profiler.Stat) (totalCount int, totalScanned, totalReturned, totalQueryTime, totalBytes float64) { - - for _, query := range queries { - totalCount += query.Count - - scanned, _ := stats.Sum(query.NScanned) - totalScanned += scanned - - returned, _ := stats.Sum(query.NReturned) - totalReturned += returned - - queryTime, _ := stats.Sum(query.QueryTime) - totalQueryTime += queryTime - - bytes, _ := stats.Sum(query.ResponseLength) - totalBytes += bytes - } - return -} - -func calcStats(samples []float64) statistics { - var s statistics - s.Total, _ = stats.Sum(samples) - s.Min, _ = stats.Min(samples) - s.Max, _ = stats.Max(samples) - s.Avg, _ = stats.Mean(samples) - s.Pct95, _ = stats.PercentileNearestRank(samples, 95) - s.StdDev, _ = stats.StandardDeviation(samples) - s.Median, _ = stats.Median(samples) - return s -} - func getOptions() (*options, error) { opts := &options{ Host: DEFAULT_HOST, @@ -505,15 +345,15 @@ func getTotalsTemplate() string { return t } -type lessFunc func(p1, p2 *profiler.Stat) bool +type lessFunc func(p1, p2 *profiler.QueryStats) bool type multiSorter struct { - queries []profiler.Stat + queries []profiler.QueryStats less []lessFunc } // Sort sorts the argument slice according to the less functions passed to OrderedBy. -func (ms *multiSorter) Sort(queries []profiler.Stat) { +func (ms *multiSorter) Sort(queries []profiler.QueryStats) { ms.queries = queries sort.Sort(ms) } @@ -562,82 +402,62 @@ func (ms *multiSorter) Less(i, j int) bool { return ms.less[k](p, q) } -func sortQueries(queries []profiler.Stat, orderby []string) []profiler.Stat { +func sortQueries(queries []profiler.QueryStats, orderby []string) []profiler.QueryStats { sortFuncs := []lessFunc{} for _, field := range orderby { var f lessFunc switch field { // case "count": - f = func(c1, c2 *profiler.Stat) bool { + f = func(c1, c2 *profiler.QueryStats) bool { return c1.Count < c2.Count } case "-count": - f = func(c1, c2 *profiler.Stat) bool { + f = func(c1, c2 *profiler.QueryStats) bool { return c1.Count > c2.Count } case "ratio": - f = func(c1, c2 *profiler.Stat) bool { - ns1, _ := stats.Max(c1.NScanned) - ns2, _ := stats.Max(c2.NScanned) - nr1, _ := stats.Max(c1.NReturned) - nr2, _ := stats.Max(c2.NReturned) - ratio1 := ns1 / nr1 - ratio2 := ns2 / nr2 + f = func(c1, c2 *profiler.QueryStats) bool { + ratio1 := c1.Scanned.Max / c1.Returned.Max + ratio2 := c2.Scanned.Max / c2.Returned.Max return ratio1 < ratio2 } case "-ratio": - f = func(c1, c2 *profiler.Stat) bool { - ns1, _ := stats.Max(c1.NScanned) - ns2, _ := stats.Max(c2.NScanned) - nr1, _ := stats.Max(c1.NReturned) - nr2, _ := stats.Max(c2.NReturned) - ratio1 := ns1 / nr1 - ratio2 := ns2 / nr2 + f = func(c1, c2 *profiler.QueryStats) bool { + ratio1 := c1.Scanned.Max / c1.Returned.Max + ratio2 := c2.Scanned.Max / c2.Returned.Max return ratio1 > ratio2 } // case "query-time": - f = func(c1, c2 *profiler.Stat) bool { - qt1, _ := stats.Max(c1.QueryTime) - qt2, _ := stats.Max(c2.QueryTime) - return qt1 < qt2 + f = func(c1, c2 *profiler.QueryStats) bool { + return c1.QueryTime.Max < c2.QueryTime.Max } case "-query-time": - f = func(c1, c2 *profiler.Stat) bool { - qt1, _ := stats.Max(c1.QueryTime) - qt2, _ := stats.Max(c2.QueryTime) - return qt1 > qt2 + f = func(c1, c2 *profiler.QueryStats) bool { + return c1.QueryTime.Max > c2.QueryTime.Max } // case "docs-scanned": - f = func(c1, c2 *profiler.Stat) bool { - ns1, _ := stats.Max(c1.NScanned) - ns2, _ := stats.Max(c2.NScanned) - return ns1 < ns2 + f = func(c1, c2 *profiler.QueryStats) bool { + return c1.Scanned.Max < c2.Scanned.Max } case "-docs-scanned": - f = func(c1, c2 *profiler.Stat) bool { - ns1, _ := stats.Max(c1.NScanned) - ns2, _ := stats.Max(c2.NScanned) - return ns1 > ns2 + f = func(c1, c2 *profiler.QueryStats) bool { + return c1.Scanned.Max > c2.Scanned.Max } // case "docs-returned": - f = func(c1, c2 *profiler.Stat) bool { - nr1, _ := stats.Max(c1.NReturned) - nr2, _ := stats.Max(c2.NReturned) - return nr1 < nr2 + f = func(c1, c2 *profiler.QueryStats) bool { + return c1.Returned.Max < c2.Scanned.Max } case "-docs-returned": - f = func(c1, c2 *profiler.Stat) bool { - nr1, _ := stats.Max(c1.NReturned) - nr2, _ := stats.Max(c2.NReturned) - return nr1 > nr2 + f = func(c1, c2 *profiler.QueryStats) bool { + return c1.Returned.Max > c2.Scanned.Max } } // count,query-time,docs-scanned, docs-returned. - in front of the field name denotes reverse order.") diff --git a/src/go/pt-mongodb-query-digest/test/sample/system.profile.json b/src/go/pt-mongodb-query-digest/test/sample/system.profile.json deleted file mode 100644 index f94abcfd..00000000 --- a/src/go/pt-mongodb-query-digest/test/sample/system.profile.json +++ /dev/null @@ -1,414 +0,0 @@ -[ - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 71, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 71, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 71, - "ResponseLength": 101, - "DocsExamined": 71, - "Millis": 19, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 72, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 72, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 72, - "ResponseLength": 102, - "DocsExamined": 72, - "Millis": 20, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 73, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 73, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 73, - "ResponseLength": 103, - "DocsExamined": 73, - "Millis": 21, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 74, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 74, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 74, - "ResponseLength": 104, - "DocsExamined": 74, - "Millis": 22, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 75, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 75, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 75, - "ResponseLength": 105, - "DocsExamined": 75, - "Millis": 23, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 76, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 76, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 76, - "ResponseLength": 106, - "DocsExamined": 76, - "Millis": 24, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 77, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 77, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 77, - "ResponseLength": 107, - "DocsExamined": 77, - "Millis": 25, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1" - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 78, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 78, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 78, - "ResponseLength": 108, - "DocsExamined": 78, - "Millis": 26, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1", - "limit": 2 - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 79, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 79, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 79, - "ResponseLength": 109, - "DocsExamined": 79, - "Millis": 27, - "NumYield": 2, - "User": "" - }, - { - "Query": { - "find": "col1", - "limit": 2 - }, - "Ts": "2016-11-08T13:46:27.000+00:00", - "Client": "127.0.0.1", - "ExecStats": { - "ExecutionTimeMillisEstimate": 0, - "IsEOF": 0, - "NReturned": 80, - "NeedTime": 1, - "RestoreState": 2, - "Works": 78, - "DocsExamined": 80, - "Direction": "forward", - "Invalidates": 0, - "NeedYield": 2, - "SaveState": 3, - "Stage": "COLLSCAN", - "Advanced": 70 - }, - "Ns": "samples.col1", - "Op": "query", - "WriteConflicts": 0, - "KeyUpdates": 0, - "KeysExamined": 0, - "Locks": { - "Global": "", - "MMAPV1Journal": "", - "Database": "", - "Collection": "", - "Metadata": "", - "Oplog": "" - }, - "Nreturned": 80, - "ResponseLength": 110, - "DocsExamined": 80, - "Millis": 28, - "NumYield": 2, - "User": "" - } -] diff --git a/src/go/tests/profiler_docs.json b/src/go/tests/profiler_docs.json new file mode 100644 index 00000000..b03f038e --- /dev/null +++ b/src/go/tests/profiler_docs.json @@ -0,0 +1,164 @@ +[ + { + "AllUsers": [], + "Client": "127.0.0.1", + "CursorExhausted": false, + "DocsExamined": 100, + "ExecStats": { + "Advanced": 75, + "ExecutionTimeMillisEstimate": 0, + "InputStage": { + "Advanced": 0, + "Direction": "", + "DocsExamined": 0, + "ExecutionTimeMillisEstimate": 0, + "Filter": { + "Date": { + "Eq": "" + } + }, + "Invalidates": 0, + "IsEOF": 0, + "NReturned": 0, + "NeedTime": 0, + "NeedYield": 0, + "RestoreState": 0, + "SaveState": 0, + "Stage": "", + "Works": 0 + }, + "Invalidates": 0, + "IsEOF": 0, + "LimitAmount": 0, + "NReturned": 50, + "NeedTime": 1, + "NeedYield": 0, + "RestoreState": 0, + "SaveState": 1, + "Stage": "COLLSCAN", + "Works": 76 + }, + "KeyUpdates": 0, + "KeysExamined": 0, + "Locks": { + "Collection": { + "AcquireCount": { + "R": 0 + } + }, + "Database": { + "AcquireCount": { + "R": 1 + } + }, + "Global": { + "AcquireCount": { + "R": 2 + } + }, + "MMAPV1Journal": { + "AcquireCount": { + "R": 0 + } + } + }, + "Millis": 0, + "Nreturned": 50, + "Ns": "samples.col1", + "NumYield": 0, + "Op": "query", + "Protocol": "op_command", + "Query": { + "find": "col1", + "shardVersion": [ + 0, + "000000000000000000000000" + ] + }, + "ResponseLength": 1061230, + "Ts": "2017-04-01T23:01:20.214-03:00", + "User": "", + "WriteConflicts": 0 + }, + { + "AllUsers": [], + "Client": "127.0.0.1", + "CursorExhausted": false, + "DocsExamined": 75, + "ExecStats": { + "Advanced": 75, + "ExecutionTimeMillisEstimate": 0, + "InputStage": { + "Advanced": 0, + "Direction": "", + "DocsExamined": 0, + "ExecutionTimeMillisEstimate": 0, + "Filter": { + "Date": { + "Eq": "" + } + }, + "Invalidates": 0, + "IsEOF": 0, + "NReturned": 0, + "NeedTime": 0, + "NeedYield": 0, + "RestoreState": 0, + "SaveState": 0, + "Stage": "", + "Works": 0 + }, + "Invalidates": 0, + "IsEOF": 0, + "LimitAmount": 0, + "NReturned": 75, + "NeedTime": 1, + "NeedYield": 0, + "RestoreState": 0, + "SaveState": 1, + "Stage": "COLLSCAN", + "Works": 76 + }, + "KeyUpdates": 0, + "KeysExamined": 0, + "Locks": { + "Collection": { + "AcquireCount": { + "R": 0 + } + }, + "Database": { + "AcquireCount": { + "R": 1 + } + }, + "Global": { + "AcquireCount": { + "R": 2 + } + }, + "MMAPV1Journal": { + "AcquireCount": { + "R": 0 + } + } + }, + "Millis": 1, + "Nreturned": 75, + "Ns": "samples.col1", + "NumYield": 0, + "Op": "query", + "Protocol": "op_command", + "Query": { + "find": "col1", + "shardVersion": [ + 0, + "000000000000000000000000" + ] + }, + "ResponseLength": 1061230, + "Ts": "2017-04-01T23:01:19.914-03:00", + "User": "", + "WriteConflicts": 0 + } +]