tools/tmbench: Improve accuracy with large tx sizes.

At larger tx sizes (e.g. > 10000) we were spending non-neglible
amounts of time in tx creation, due to making the final bytes random.
The slower the send loop, the less accurate it is at measuring the time
tendermint took. (As we can't reach the promised contract of the given rate)

There really isn't much need for that randomness, so this PR makes it
such that only the txNumber gets bumped between txs from the same
connection, thereby improving sendloop speed and accuracy.

tools/tm-bench/bench_test.go

@@ -1,18 +0,0 @@
-package main
-
-import (
-	"testing"
-	"time"
-)
-
-func BenchmarkTimingPerTx(b *testing.B) {
-	startTime := time.Now()
-	endTime := startTime.Add(time.Second)
-	for i := 0; i < b.N; i++ {
-		if i%20 == 0 {
-			if time.Now().After(endTime) {
-				continue
-			}
-		}
-	}
-}

tools/tm-bench/transacter.go

@@ -160,6 +160,11 @@ func (t *transacter) sendLoop(connIndex int) {
 		hostname = "127.0.0.1"
 	}
 	hostnameHash = md5.Sum([]byte(hostname))
+	// each transaction embeds connection index, tx number and hash of the hostname
+	// we update the tx number between successive txs
+	tx := generateTx(connIndex, txNumber, t.Size, hostnameHash)
+	txHex := make([]byte, len(tx)*2)
+	hex.Encode(txHex, tx)
 
 	for {
 		select {
@@ -172,17 +177,18 @@ func (t *transacter) sendLoop(connIndex int) {
 				started = true
 			}
 
+			now := time.Now()
 			for i := 0; i < t.Rate; i++ {
-				// each transaction embeds connection index, tx number and hash of the hostname
-				tx := generateTx(connIndex, txNumber, t.Size, hostnameHash)
-				paramsJSON, err := json.Marshal(map[string]interface{}{"tx": hex.EncodeToString(tx)})
+				// update tx number of the tx, and the corresponding hex
+				updateTx(tx, txHex, txNumber)
+				paramsJSON, err := json.Marshal(map[string]interface{}{"tx": txHex})
 				if err != nil {
 					fmt.Printf("failed to encode params: %v\n", err)
 					os.Exit(1)
 				}
 				rawParamsJSON := json.RawMessage(paramsJSON)
 
-				c.SetWriteDeadline(time.Now().Add(sendTimeout))
+				c.SetWriteDeadline(now.Add(sendTimeout))
 				err = c.WriteJSON(rpctypes.RPCRequest{
 					JSONRPC: "2.0",
 					ID:      "tm-bench",
@@ -197,9 +203,10 @@ func (t *transacter) sendLoop(connIndex int) {
 					return
 				}
 
-				// Time added here is 7.13 ns/op, not significant enough to worry about
-				if i%20 == 0 {
-					if time.Now().After(endTime) {
+				// cache the time.Now() reads to save time.
+				if i%5 == 0 {
+					now = time.Now()
+					if now.After(endTime) {
 						// Plus one accounts for sending this tx
 						numTxSent = i + 1
 						break
@@ -265,3 +272,13 @@ func generateTx(connIndex int, txNumber int, txSize int, hostnameHash [md5.Size]
 
 	return tx
 }
+
+// warning, mutates input byte slice
+func updateTx(tx []byte, txHex []byte, txNumber int) {
+	binary.PutUvarint(tx[8:16], uint64(txNumber))
+	hexUpdate := make([]byte, 16)
+	hex.Encode(hexUpdate, tx[8:16])
+	for i := 16; i < 32; i++ {
+		txHex[i] = hexUpdate[i-16]
+	}
+}

tools/tm-bench/transacter_test.go

@@ -0,0 +1,104 @@
+package main
+
+import (
+	"crypto/md5"
+	"encoding/hex"
+	"encoding/json"
+	"fmt"
+	"os"
+	"testing"
+	"time"
+
+	"github.com/pkg/errors"
+	"github.com/stretchr/testify/require"
+)
+
+// This test tests that the output of generate tx and update tx is consistent
+func TestGenerateTxUpdateTxConsistentency(t *testing.T) {
+	cases := []struct {
+		connIndex        int
+		startingTxNumber int
+		txSize           int
+		hostname         string
+		numTxsToTest     int
+	}{
+		{0, 0, 50, "localhost:26657", 1000},
+		{70, 300, 10000, "localhost:26657", 1000},
+		{0, 50, 100000, "localhost:26657", 1000},
+	}
+
+	for tcIndex, tc := range cases {
+		hostnameHash := md5.Sum([]byte(tc.hostname))
+		// Tx generated from update tx. This is defined outside of the loop, since we have
+		// to a have something initially to update
+		updatedTx := generateTx(tc.connIndex, tc.startingTxNumber, tc.txSize, hostnameHash)
+		updatedHex := make([]byte, len(updatedTx)*2)
+		hex.Encode(updatedHex, updatedTx)
+		for i := 0; i < tc.numTxsToTest; i++ {
+			expectedTx := generateTx(tc.connIndex, tc.startingTxNumber+i, tc.txSize, hostnameHash)
+			expectedHex := make([]byte, len(expectedTx)*2)
+			hex.Encode(expectedHex, expectedTx)
+
+			updateTx(updatedTx, updatedHex, tc.startingTxNumber+i)
+
+			// after first 32 bytes is 8 bytes of time, then purely random bytes
+			require.Equal(t, expectedTx[:32], updatedTx[:32],
+				"First 32 bytes of the txs differed. tc #%d, i #%d", tcIndex, i)
+			require.Equal(t, expectedHex[:64], updatedHex[:64],
+				"First 64 bytes of the hex differed. tc #%d, i #%d", tcIndex, i)
+			// Test the lengths of the txs are as expected
+			require.Equal(t, tc.txSize, len(expectedTx),
+				"Length of expected Tx differed. tc #%d, i #%d", tcIndex, i)
+			require.Equal(t, tc.txSize, len(updatedTx),
+				"Length of expected Tx differed. tc #%d, i #%d", tcIndex, i)
+			require.Equal(t, tc.txSize*2, len(expectedHex),
+				"Length of expected hex differed. tc #%d, i #%d", tcIndex, i)
+			require.Equal(t, tc.txSize*2, len(updatedHex),
+				"Length of updated hex differed. tc #%d, i #%d", tcIndex, i)
+		}
+	}
+}
+
+func BenchmarkIterationOfSendLoop(b *testing.B) {
+	var (
+		connIndex = 0
+		txSize    = 25000
+	)
+
+	now := time.Now()
+	// something too far away to matter
+	endTime := now.Add(time.Hour)
+	txNumber := 0
+	hostnameHash := md5.Sum([]byte{0})
+	tx := generateTx(connIndex, txNumber, txSize, hostnameHash)
+	txHex := make([]byte, len(tx)*2)
+	hex.Encode(txHex, tx)
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		updateTx(tx, txHex, txNumber)
+		paramsJSON, err := json.Marshal(map[string]interface{}{"tx": txHex})
+		if err != nil {
+			fmt.Printf("failed to encode params: %v\n", err)
+			os.Exit(1)
+		}
+		_ = json.RawMessage(paramsJSON)
+		_ = now.Add(sendTimeout)
+
+		if err != nil {
+			err = errors.Wrap(err,
+				fmt.Sprintf("txs send failed on connection #%d", connIndex))
+			logger.Error(err.Error())
+			return
+		}
+
+		// Cache the now operations
+		if i%5 == 0 {
+			now = time.Now()
+			if now.After(endTime) {
+				break
+			}
+		}
+
+		txNumber++
+	}
+}