added ability to log slow searches

closes blevesearch#88
abhishekdas29 · Dec 29, 2014 · 5978f50 · 5978f50
1 parent 0ddfa77
commit 5978f50
Show file tree

Hide file tree

Showing 3 changed files with 59 additions and 7 deletions.
diff --git a/config.go b/config.go
@@ -111,10 +111,11 @@ import (
 var bleveExpVar = expvar.NewMap("bleve")
 
 type configuration struct {
-	Cache              *registry.Cache
-	DefaultHighlighter string
-	DefaultKVStore     string
-	analysisQueue      upside_down.AnalysisQueue
+	Cache                  *registry.Cache
+	DefaultHighlighter     string
+	DefaultKVStore         string
+	SlowSearchLogThreshold time.Duration
+	analysisQueue          upside_down.AnalysisQueue
 }
 
 func newConfiguration() *configuration {
@@ -168,6 +169,6 @@ var logger = log.New(ioutil.Discard, "bleve", log.LstdFlags)
 
 // SetLog sets the logger used for logging
 // by default log messages are sent to ioutil.Discard
-func SetLog(logger *log.Logger) {
-	logger = logger
+func SetLog(l *log.Logger) {
+	logger = l
 }
diff --git a/index_impl.go b/index_impl.go
@@ -482,7 +482,12 @@ func (i *indexImpl) Search(req *SearchRequest) (*SearchResult, error) {
 	}
 
 	atomic.AddUint64(&i.stats.searches, 1)
-	atomic.AddUint64(&i.stats.searchTime, uint64(time.Since(searchStart)))
+	searchDuration := time.Since(searchStart)
+	atomic.AddUint64(&i.stats.searchTime, uint64(searchDuration))
+
+	if searchDuration > Config.SlowSearchLogThreshold {
+		logger.Printf("slow search took %s - %s", searchDuration, req)
+	}
 
 	return &SearchResult{
 		Request:  req,

diff --git a/index_test.go b/index_test.go
@@ -11,8 +11,10 @@ package bleve
 
 import (
 	"io/ioutil"
+	"log"
 	"os"
 	"testing"
+	"time"
 )
 
 func TestCrud(t *testing.T) {
@@ -279,3 +281,47 @@ func TestClosedIndex(t *testing.T) {
 		t.Errorf("expected error index closed, got %v", err)
 	}
 }
+
+func TestSlowSearch(t *testing.T) {
+	defer os.RemoveAll("testidx")
+
+	defer func() {
+		// reset logger back to normal
+		SetLog(log.New(ioutil.Discard, "bleve", log.LstdFlags))
+	}()
+	// set custom logger
+	var sdw sawDataWriter
+	SetLog(log.New(&sdw, "bleve", log.LstdFlags))
+
+	index, err := New("testidx", NewIndexMapping())
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer index.Close()
+
+	Config.SlowSearchLogThreshold = 1 * time.Minute
+
+	query := NewTermQuery("water")
+	req := NewSearchRequest(query)
+	index.Search(req)
+
+	if sdw.sawData {
+		t.Errorf("expected to not see slow query logged, but did")
+	}
+
+	Config.SlowSearchLogThreshold = 1 * time.Microsecond
+	index.Search(req)
+
+	if !sdw.sawData {
+		t.Errorf("expected to see slow query logged, but didn't")
+	}
+}
+
+type sawDataWriter struct {
+	sawData bool
+}
+
+func (s *sawDataWriter) Write(p []byte) (n int, err error) {
+	s.sawData = true
+	return len(p), nil
+}