s/Bytes recv/Bytes sent/; allow all queries to be fingerprinted

This commit is contained in:
Kamil Dziedzic
2017-10-14 18:25:08 +02:00
parent 7106e78796
commit 6cbfd363f3
3 changed files with 164 additions and 84 deletions

View File

@@ -18,7 +18,7 @@ var (
type Profiler interface {
GetLastError() error
QueriesChan() chan stats.Queries
TimeoutsChan() <-chan time.Time
FlushQueries()
Start()
Stop()
}
@@ -93,13 +93,6 @@ func (p *Profile) Stop() {
}
}
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)
@@ -108,8 +101,7 @@ MAIN_GETDATA_LOOP:
for {
select {
case <-p.ticker:
p.queriesChan <- p.stats.Queries()
p.stats.Reset()
p.FlushQueries()
case <-p.stopChan:
// Close the iterator to break the loop on getDocs
p.iterator.Close()
@@ -120,6 +112,9 @@ MAIN_GETDATA_LOOP:
}
func (p *Profile) getDocs() {
defer p.Stop()
defer p.FlushQueries()
var doc proto.SystemProfile
for p.iterator.Next(&doc) || p.iterator.Timeout() {
@@ -139,10 +134,11 @@ func (p *Profile) getDocs() {
if !valid {
continue
}
if doc.Query.Len() > 0 {
p.stats.Add(doc)
}
p.stats.Add(doc)
}
p.queriesChan <- p.stats.Queries()
p.Stop()
}
func (p *Profile) FlushQueries() {
p.queriesChan <- p.stats.Queries()
p.stats.Reset()
}

View File

@@ -62,7 +62,7 @@ func main() {
opts, err := getOptions()
if err != nil {
log.Errorf("error processing commad line arguments: %s", err)
log.Errorf("error processing command line arguments: %s", err)
os.Exit(1)
}
if opts == nil && err == nil {
@@ -136,7 +136,7 @@ func main() {
filters = append(filters, filter.NewFilterByCollection(opts.SkipCollections))
}
query := bson.M{"op": bson.M{"$nin": []string{"getmore", "delete"}}}
query := bson.M{"op": bson.M{"$nin": []string{"getmore"}}}
i := session.DB(di.Database).C("system.profile").Find(query).Sort("-$natural").Iter()
fp := fingerprinter.NewFingerprinter(fingerprinter.DEFAULT_KEY_FILTERS)
@@ -327,9 +327,9 @@ func getQueryTemplate() string {
# Exec Time ms {{printf "% 4.0f" .QueryTime.Pct}} {{printf "% 7.0f " .QueryTime.Total}} {{printf "% 7.0f " .QueryTime.Min}} {{printf "% 7.0f " .QueryTime.Max}} {{printf "% 7.0f " .QueryTime.Avg}} {{printf "% 7.0f " .QueryTime.Pct95}} {{printf "% 7.0f " .QueryTime.StdDev}} {{printf "% 7.0f " .QueryTime.Median}}
# Docs Scanned {{printf "% 4.0f" .Scanned.Pct}} {{Format .Scanned.Total 7.2}} {{Format .Scanned.Min 7.2}} {{Format .Scanned.Max 7.2}} {{Format .Scanned.Avg 7.2}} {{Format .Scanned.Pct95 7.2}} {{Format .Scanned.StdDev 7.2}} {{Format .Scanned.Median 7.2}}
# Docs Returned {{printf "% 4.0f" .Returned.Pct}} {{Format .Returned.Total 7.2}} {{Format .Returned.Min 7.2}} {{Format .Returned.Max 7.2}} {{Format .Returned.Avg 7.2}} {{Format .Returned.Pct95 7.2}} {{Format .Returned.StdDev 7.2}} {{Format .Returned.Median 7.2}}
# Bytes recv {{printf "% 4.0f" .ResponseLength.Pct}} {{Format .ResponseLength.Total 7.2}} {{Format .ResponseLength.Min 7.2}} {{Format .ResponseLength.Max 7.2}} {{Format .ResponseLength.Avg 7.2}} {{Format .ResponseLength.Pct95 7.2}} {{Format .ResponseLength.StdDev 7.2}} {{Format .ResponseLength.Median 7.2}}
# Bytes sent {{printf "% 4.0f" .ResponseLength.Pct}} {{Format .ResponseLength.Total 7.2}} {{Format .ResponseLength.Min 7.2}} {{Format .ResponseLength.Max 7.2}} {{Format .ResponseLength.Avg 7.2}} {{Format .ResponseLength.Pct95 7.2}} {{Format .ResponseLength.StdDev 7.2}} {{Format .ResponseLength.Median 7.2}}
# String:
# Namespaces {{.Namespace}}
# Namespace {{.Namespace}}
# Operation {{.Operation}}
# Fingerprint {{.Fingerprint}}
# Query {{.Query}}
@@ -347,7 +347,7 @@ func getTotalsTemplate() string {
# Exec Time ms {{printf "% 4.0f" .QueryTime.Pct}} {{printf "% 7.0f " .QueryTime.Total}} {{printf "% 7.0f " .QueryTime.Min}} {{printf "% 7.0f " .QueryTime.Max}} {{printf "% 7.0f " .QueryTime.Avg}} {{printf "% 7.0f " .QueryTime.Pct95}} {{printf "% 7.0f " .QueryTime.StdDev}} {{printf "% 7.0f " .QueryTime.Median}}
# Docs Scanned {{printf "% 4.0f" .Scanned.Pct}} {{Format .Scanned.Total 7.2}} {{Format .Scanned.Min 7.2}} {{Format .Scanned.Max 7.2}} {{Format .Scanned.Avg 7.2}} {{Format .Scanned.Pct95 7.2}} {{Format .Scanned.StdDev 7.2}} {{Format .Scanned.Median 7.2}}
# Docs Returned {{printf "% 4.0f" .Returned.Pct}} {{Format .Returned.Total 7.2}} {{Format .Returned.Min 7.2}} {{Format .Returned.Max 7.2}} {{Format .Returned.Avg 7.2}} {{Format .Returned.Pct95 7.2}} {{Format .Returned.StdDev 7.2}} {{Format .Returned.Median 7.2}}
# Bytes recv {{printf "% 4.0f" .ResponseLength.Pct}} {{Format .ResponseLength.Total 7.2}} {{Format .ResponseLength.Min 7.2}} {{Format .ResponseLength.Max 7.2}} {{Format .ResponseLength.Avg 7.2}} {{Format .ResponseLength.Pct95 7.2}} {{Format .ResponseLength.StdDev 7.2}} {{Format .ResponseLength.Median 7.2}}
# Bytes sent {{printf "% 4.0f" .ResponseLength.Pct}} {{Format .ResponseLength.Total 7.2}} {{Format .ResponseLength.Min 7.2}} {{Format .ResponseLength.Max 7.2}} {{Format .ResponseLength.Avg 7.2}} {{Format .ResponseLength.Pct95 7.2}} {{Format .ResponseLength.StdDev 7.2}} {{Format .ResponseLength.Median 7.2}}
#
`
return t

View File

@@ -15,9 +15,13 @@ import (
"testing"
"time"
"bytes"
"text/template"
"github.com/pborman/getopt/v2"
"github.com/percona/percona-toolkit/src/go/lib/profiling"
"github.com/percona/percona-toolkit/src/go/lib/tutil"
"github.com/percona/percona-toolkit/src/go/mongolib/stats"
"github.com/percona/pmgo"
"gopkg.in/mgo.v2/dbtest"
)
@@ -184,6 +188,10 @@ func TestPTMongoDBQueryDigest(t *testing.T) {
// Clean up system.profile
var err error
data.url = "127.0.0.1/test"
err = profiling.Disable(data.url)
if err != nil {
t.Error(err)
}
err = profiling.Drop(data.url)
if err != nil {
t.Error(err)
@@ -261,8 +269,12 @@ func testAllOperationsTemplate(t *testing.T, data Data) {
if err != nil {
t.Fatalf("cannot execute query '%s': %s", dir+file.Name(), err)
}
}
// disable profiling so pt-mongodb-query digest reads rows from `system.profile`
profiling.Disable(data.url)
// run profiler
cmd := exec.Command(
data.bin,
data.url,
@@ -273,91 +285,163 @@ func testAllOperationsTemplate(t *testing.T, data Data) {
t.Error(err)
}
expected := `pt-mongodb-query-digest .+
expected := `Profiler is disabled for the "test" database but there are 125 documents in the system.profile collection.
Using those documents for the stats
pt-mongodb-query-digest .+
Host: ` + data.url + `
Skipping profiled queries on these collections: \[system\.profile\]
# Totals
# Ratio 0.00 \(docs scanned/returned\)
# Ratio [0-9\.]+ \(docs scanned/returned\)
# Attribute pct total min max avg 95% stddev median
# ================== === ======== ======== ======== ======== ======== ======= ========
# Count \(docs\) 111\s
# Count \(docs\) 125\s
# Exec Time ms (\s*[0-9]+){8}\s
# Docs Scanned (\s*[0-9\.]+){8}\s
# Docs Returned (\s*[0-9\.]+){8}\s
# Bytes recv (\s*[0-9\.K]+){8}\s
# Bytes sent (\s*[0-9\.K]+){8}(K|\s)
#\s
`
# Query 1: 0.00 QPS, ID a7ce8dee16beadb767484112e6b29af3
# Ratio 0.00 \(docs scanned/returned\)
queries := []stats.QueryStats{
{
ID: "a7ce8dee16beadb767484112e6b29af3",
Namespace: "test.coll",
Operation: "insert",
Fingerprint: "INSERT coll",
Query: `{"ns":"test.coll","op":"insert","query":{"insert":"coll","documents":\[{"_id":{"\$oid":".*"},"a":9}\],"ordered":true}}`,
},
{
ID: "7e6e9af8a1754a065b323acdddbee4b5",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "DROP coll drop",
Query: `{"ns":"test.coll","op":"command","command":{"drop":"coll"}}`,
},
{
ID: "bab52c8aa977c96ecd148c015ae07c42",
Namespace: "test.coll",
Operation: "remove",
Fingerprint: "REMOVE coll a,b",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"remove","query":{"a":{"$gte":2},"b":{"$gte":2}}}`),
},
{
ID: "11e1b6f695d43b1b5a2f7e6de2ad8305",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "AGGREGATE coll a",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"aggregate":"coll","pipeline":[{"$match":{"a":{"$gte":2}}}],"cursor":{}}}`),
},
{
ID: "a4be6ed97c946182af7e30cf818afdac",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "DISTINCT coll a,b",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"distinct":"coll","key":"a","query":{"b":{"$gte":5}}}}`),
},
{
ID: "e2f53c6824c5cbe454e33e128b350d1e",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "EXPLAIN",
Query: `{"ns":"test.coll","op":"command","command":{"explain":{"find":"coll","filter":{}},"verbosity":"queryPlanner"}}`,
},
{
ID: "9423eaa90c222686d092c04f001fb369",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "FINDANDMODIFY coll a",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"findandmodify":"coll","query":{"a":2},"update":{"$inc":{"b":1}}},"updateobj":{"$inc":{"b":1}}}`),
},
{
ID: "dd20c739baef5a3fd9352c350c7e69f1",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "GEONEAR coll",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"geoNear":"coll","near":{"type":"Point","coordinates":[1,1]},"spherical":true}}`),
},
{
ID: "018a055f724d418b80e66b98bfdb25a5",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "GROUP coll a,b",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"group":{"key":{"a":1,"b":1},"cond":{"b":3},"initial":{},"ns":"coll","$reduce":{"Code":"function () {}","Scope":null}}}}`),
},
{
ID: "130827f5b7afe1369f619ccd5cd61ec4",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "MAPREDUCE coll a",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"mapreduce":"coll","map":{"Code":"function () {\n emit(this.a, this.b);\n}","Scope":null},"reduce":{"Code":"function (a, b) {\n return Array.sum(b);\n}","Scope":null},"query":{"a":{"$gte":0}},"out":{"inline":1}}}`),
},
{
ID: "71b3d6aa44d34aaa02cd65bad3e25f49",
Namespace: "test",
Operation: "command",
Fingerprint: "EVAL",
Query: regexp.QuoteMeta(`{"ns":"test","op":"command","command":{"$eval":"db"}}`),
},
{
ID: "2300d7f2d372205544f249b010e9b8ad",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "COUNT coll a",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"command","command":{"count":"coll","query":{"a":{"$gt":5}},"fields":{}}}`),
},
{
ID: "ffd83008fd6affc7c07053f583dea3e0",
Namespace: "test.system.js",
Operation: "query",
Fingerprint: "FIND system.js find",
Query: `{"ns":"test.system.js","op":"query","query":{"find":"system.js"}}`,
},
{
ID: "29701e3d37e0adb35ebd70b7ef2b3f3d",
Namespace: "test.coll",
Operation: "command",
Fingerprint: "COUNT coll",
Query: `{"ns":"test.coll","op":"command","command":{"count":"coll","query":{},"fields":{}}}`,
},
{
ID: "27cb39e62745b1ff4121b4bf6f21fb12",
Namespace: "test.coll",
Operation: "update",
Fingerprint: "UPDATE coll a",
Query: regexp.QuoteMeta(`{"ns":"test.coll","op":"update","query":{"a":{"$gte":2}},"updateobj":{"$set":{"c":1},"$inc":{"a":-10}}}`),
},
}
queryTpl := `
# Query [0-9]+: 0.00 QPS, ID {{.ID}}
# Ratio [0-9\.]+ \(docs scanned/returned\)
# Time range: .* to .*
# Attribute pct total min max avg 95% stddev median
# ================== === ======== ======== ======== ======== ======== ======= ========
# Count \(docs\) 107\s
# Count \(docs\) (\s*[0-9]+)\s
# Exec Time ms (\s*[0-9]+){8}\s
# Docs Scanned (\s*[0-9\.]+){8}\s
# Docs Returned (\s*[0-9\.]+){8}\s
# Bytes recv (\s*[0-9\.K]+){8}\s
# Bytes sent (\s*[0-9\.K]+){8}(K|\s)
# String:
# Namespaces test.coll
# Operation insert
# Fingerprint INSERT coll
# Query {"ns":"test.coll","op":"insert","query":{"insert":"coll","documents":\[{"_id":{"\$oid":".+"},"a":9}\],"ordered":true}}
# Query 2: 0.00 QPS, ID bab52c8aa977c96ecd148c015ae07c42
# Ratio 0.00 \(docs scanned/returned\)
# Time range: .* to .*
# Attribute pct total min max avg 95% stddev median
# ================== === ======== ======== ======== ======== ======== ======= ========
# Count \(docs\) 2\s
# Exec Time ms (\s*[0-9]+){8}\s
# Docs Scanned (\s*[0-9\.]+){8}\s
# Docs Returned (\s*[0-9\.]+){8}\s
# Bytes recv (\s*[0-9\.K]+){8}\s
# String:
# Namespaces test.coll
# Operation remove
# Fingerprint REMOVE coll a,b
# Query {"ns":"test.coll","op":"remove","query":{"a":{"\$gte":2},"b":{"\$gte":2}}}
# Query 3: 0.00 QPS, ID ffd83008fd6affc7c07053f583dea3e0
# Ratio 0.00 \(docs scanned/returned\)
# Time range: .* to .*
# Attribute pct total min max avg 95% stddev median
# ================== === ======== ======== ======== ======== ======== ======= ========
# Count \(docs\) 1\s
# Exec Time ms (\s*[0-9]+){8}\s
# Docs Scanned (\s*[0-9\.]+){8}\s
# Docs Returned (\s*[0-9\.]+){8}\s
# Bytes recv (\s*[0-9\.K]+){8}\s
# String:
# Namespaces test.system.js
# Operation query
# Fingerprint FIND system.js find
# Query {"ns":"test.system.js","op":"query","query":{"find":"system.js"}}
# Query 4: 0.00 QPS, ID 27cb39e62745b1ff4121b4bf6f21fb12
# Ratio 0.00 \(docs scanned/returned\)
# Time range: .* to .*
# Attribute pct total min max avg 95% stddev median
# ================== === ======== ======== ======== ======== ======== ======= ========
# Count \(docs\) 1\s
# Exec Time ms (\s*[0-9]+){8}\s
# Docs Scanned (\s*[0-9\.]+){8}\s
# Docs Returned (\s*[0-9\.]+){8}\s
# Bytes recv (\s*[0-9\.K]+){8}\s
# String:
# Namespaces test.coll
# Operation update
# Fingerprint UPDATE coll a
# Query {"ns":"test.coll","op":"update","query":{"a":{"\$gte":2}},"updateobj":{"\$set":{"c":1},"\$inc":{"a":-10}}}
# Namespace {{.Namespace}}
# Operation {{.Operation}}
# Fingerprint {{.Fingerprint}}
# Query {{.Query}}
`
tpl, _ := template.New("query").Parse(queryTpl)
for _, query := range queries {
buf := bytes.Buffer{}
err := tpl.Execute(&buf, query)
if err != nil {
t.Error(err)
}
expected += buf.String()
}
assertRegexpLines(t, expected, string(output))
}