Merge "added performance benchmark example"

4 files changed, 180 insertions, 11 deletions

diff --git a/.gitignore b/.gitignore
index bfa4a36..ec02bba 100644
--- a/.gitignore
+++ b/.gitignore
@@ -2,3 +2,4 @@
 cmd/binapi-generator/binapi-generator
 examples/cmd/simple-client/simple-client
 examples/cmd/stats-client/stats-client
+examples/cmd/perf-bench/perf-bench
diff --git a/Makefile b/Makefile
index 44a203b..93cd052 100644
--- a/Makefile
+++ b/Makefile
@@ -2,6 +2,7 @@ build:
 	@cd cmd/binapi-generator && go build -v
 	@cd examples/cmd/simple-client && go build -v
 	@cd examples/cmd/stats-client && go build -v
+	@cd examples/cmd/perf-bench && go build -v
 
 test:
 	@cd cmd/binapi-generator && go test -cover .
@@ -15,6 +16,7 @@ clean:
 	@rm -f cmd/binapi-generator/binapi-generator
 	@rm -f examples/cmd/simple-client/simple-client
 	@rm -f examples/cmd/stats-client/stats-client
+	@rm -f examples/cmd/perf-bench/perf-bench
 
 generate:
 	@cd core && go generate ./...
diff --git a/core/request_handler.go b/core/request_handler.go
index f4f5e92..e0235b9 100644
--- a/core/request_handler.go
+++ b/core/request_handler.go
@@ -79,13 +79,15 @@ func (c *Connection) processRequest(ch *api.Channel, chMeta *channelMetadata, re
 		return error
 	}
 
-	// send the message
-	log.WithFields(logger.Fields{
-		"context":  chMeta.id,
-		"msg_id":   msgID,
-		"msg_size": len(data),
-	}).Debug("Sending a message to VPP.")
+	if log.Level == logger.DebugLevel { // for performance reasons - logrus does some processing even if debugs are disabled
+		log.WithFields(logger.Fields{
+			"context":  chMeta.id,
+			"msg_id":   msgID,
+			"msg_size": len(data),
+		}).Debug("Sending a message to VPP.")
+	}
 
+	// send the message
 	if req.Multipart {
 		// expect multipart response
 		atomic.StoreUint32(&chMeta.multipart, 1)
@@ -121,11 +123,13 @@ func msgCallback(context uint32, msgID uint16, data []byte) {
 		return
 	}
 
-	log.WithFields(logger.Fields{
-		"context":  context,
-		"msg_id":   msgID,
-		"msg_size": len(data),
-	}).Debug("Received a message from VPP.")
+	if log.Level == logger.DebugLevel { // for performance reasons - logrus does some processing even if debugs are disabled
+		log.WithFields(logger.Fields{
+			"context":  context,
+			"msg_id":   msgID,
+			"msg_size": len(data),
+		}).Debug("Received a message from VPP.")
+	}
 
 	if context == 0 || conn.isNotificationMessage(msgID) {
 		// process the message as a notification
diff --git a/examples/cmd/perf-bench/perf-bench.go b/examples/cmd/perf-bench/perf-bench.go
new file mode 100644
index 0000000..e414b20
--- /dev/null
+++ b/examples/cmd/perf-bench/perf-bench.go
@@ -0,0 +1,162 @@
+// Copyright (c) 2017 Cisco and/or its affiliates.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at:
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Binary simple-client is an example VPP management application that exercises the
+// govpp API on real-world use-cases.
+package main
+
+import (
+	"flag"
+	"fmt"
+	"log"
+	"os"
+	"sync"
+	"time"
+
+	"github.com/Sirupsen/logrus"
+	"github.com/pkg/profile"
+
+	"git.fd.io/govpp.git"
+	"git.fd.io/govpp.git/api"
+	"git.fd.io/govpp.git/core"
+	"git.fd.io/govpp.git/core/bin_api/vpe"
+)
+
+const (
+	defaultSyncRequestCount  = 1000
+	defaultAsyncRequestCount = 1000000
+)
+
+func main() {
+	// parse optional flags
+	var sync, prof bool
+	var cnt int
+	flag.BoolVar(&sync, "sync", false, "run synchronous perf test")
+	flag.IntVar(&cnt, "cnt", 0, "count of requests to be sent to VPP")
+	flag.BoolVar(&prof, "prof", false, "generate profile data")
+	flag.Parse()
+
+	if cnt == 0 {
+		// no specific count defined - use defaults
+		if sync {
+			cnt = defaultSyncRequestCount
+		} else {
+			cnt = defaultAsyncRequestCount
+		}
+	}
+
+	if prof {
+		defer profile.Start().Stop()
+	}
+
+	// log only errors
+	core.SetLogger(&logrus.Logger{Level: logrus.ErrorLevel})
+
+	// connect to VPP
+	conn, err := govpp.Connect()
+	if err != nil {
+		log.Println("Error:", err)
+		os.Exit(1)
+	}
+	defer conn.Disconnect()
+
+	// create an API channel
+	ch, err := conn.NewAPIChannelBuffered(cnt, cnt)
+	if err != nil {
+		log.Println("Error:", err)
+		os.Exit(1)
+	}
+	defer ch.Close()
+
+	// run the test & measure the time
+	start := time.Now()
+
+	if sync {
+		// run synchronous test
+		syncTest(ch, cnt)
+	} else {
+		// run asynchronous test
+		asyncTest(ch, cnt)
+	}
+
+	elapsed := time.Since(start)
+	fmt.Println("Test took:", elapsed)
+	fmt.Printf("Requests per second: %.0f\n", float64(cnt)/elapsed.Seconds())
+}
+
+func syncTest(ch *api.Channel, cnt int) {
+	fmt.Printf("Running synchronous perf test with %d requests...\n", cnt)
+
+	for i := 0; i < cnt; i++ {
+		req := &vpe.ControlPing{}
+		reply := &vpe.ControlPingReply{}
+
+		err := ch.SendRequest(req).ReceiveReply(reply)
+		if err != nil {
+			log.Println("Error in reply:", err)
+			os.Exit(1)
+		}
+	}
+}
+
+func asyncTest(ch *api.Channel, cnt int) {
+	fmt.Printf("Running asynchronous perf test with %d requests...\n", cnt)
+
+	// start a new go routine that reads the replies
+	var wg sync.WaitGroup
+	wg.Add(1)
+	go readAsyncReplies(ch, cnt, &wg)
+
+	// send asynchronous requests
+	sendAsyncRequests(ch, cnt)
+
+	// wait until all replies are recieved
+	wg.Wait()
+}
+
+func sendAsyncRequests(ch *api.Channel, cnt int) {
+	for i := 0; i < cnt; i++ {
+		ch.ReqChan <- &api.VppRequest{
+			Message: &vpe.ControlPing{},
+		}
+	}
+}
+
+func readAsyncReplies(ch *api.Channel, expectedCnt int, wg *sync.WaitGroup) {
+	cnt := 0
+
+	for {
+		// receive a reply
+		reply := <-ch.ReplyChan
+		if reply.Error != nil {
+			log.Println("Error in reply:", reply.Error)
+			os.Exit(1)
+		}
+
+		// decode the message
+		msg := &vpe.ControlPingReply{}
+		err := ch.MsgDecoder.DecodeMsg(reply.Data, msg)
+		if reply.Error != nil {
+			log.Println("Error by decoding:", err)
+			os.Exit(1)
+		}
+
+		// count and return if done
+		cnt++
+		if cnt >= expectedCnt {
+			wg.Done()
+			return
+		}
+	}
+}