Merge "[FAB-12030] Improve INFO log for block processing" into releas…

…e-1.2
hyperledger · Sep 25, 2018 · 3cd00d1 · 3cd00d1
2 parents 935ce5d + 5ab38e1
commit 3cd00d1
Show file tree

Hide file tree

Showing 12 changed files with 166 additions and 92 deletions.
diff --git a/core/committer/txvalidator/txvalidator_test.go b/core/committer/txvalidator/txvalidator_test.go
@@ -52,7 +52,7 @@ func testValidationWithNTXes(t *testing.T, ledger ledger2.PeerLedger, gbHash []b
 		*mocktxvalidator.Support
 		*semaphore.Weighted
 	}{&mocktxvalidator.Support{LedgerVal: ledger, ACVal: &config.MockApplicationCapabilities{}}, semaphore.NewWeighted(10)}
-	tValidator := &TxValidator{vcs, mockVsccValidator}
+	tValidator := &TxValidator{"", vcs, mockVsccValidator}
 
 	bcInfo, _ := ledger.GetBlockchainInfo()
 	testutil.AssertEquals(t, bcInfo, &common.BlockchainInfo{
@@ -127,7 +127,7 @@ func TestBlockValidationDuplicateTXId(t *testing.T) {
 		*mocktxvalidator.Support
 		*semaphore.Weighted
 	}{&mocktxvalidator.Support{LedgerVal: ledger, ACVal: acv}, semaphore.NewWeighted(10)}
-	tValidator := &TxValidator{vcs, mockVsccValidator}
+	tValidator := &TxValidator{"", vcs, mockVsccValidator}
 
 	bcInfo, _ := ledger.GetBlockchainInfo()
 	testutil.AssertEquals(t, bcInfo, &common.BlockchainInfo{
@@ -214,7 +214,7 @@ func TestTxValidationFailure_InvalidTxid(t *testing.T) {
 		*mocktxvalidator.Support
 		*semaphore.Weighted
 	}{&mocktxvalidator.Support{LedgerVal: ledger, ACVal: &config.MockApplicationCapabilities{}}, semaphore.NewWeighted(10)}
-	tValidator := &TxValidator{vcs, &validator.MockVsccValidator{}}
+	tValidator := &TxValidator{"", vcs, &validator.MockVsccValidator{}}
 
 	mockSigner, err := mspmgmt.GetLocalMSP().GetDefaultSigningIdentity()
 	assert.NoError(t, err)

diff --git a/core/committer/txvalidator/validator.go b/core/committer/txvalidator/validator.go
@@ -8,6 +8,7 @@ package txvalidator
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric/common/channelconfig"
@@ -71,6 +72,7 @@ type vsccValidator interface {
 // reference to the ledger to enable tx simulation
 // and execution of vscc
 type TxValidator struct {
+	ChainID string
 	Support Support
 	Vscc    vsccValidator
 }
@@ -98,12 +100,13 @@ type blockValidationResult struct {
 }
 
 // NewTxValidator creates new transactions validator
-func NewTxValidator(support Support, sccp sysccprovider.SystemChaincodeProvider, pm PluginMapper) *TxValidator {
+func NewTxValidator(chainID string, support Support, sccp sysccprovider.SystemChaincodeProvider, pm PluginMapper) *TxValidator {
 	// Encapsulates interface implementation
 	pluginValidator := NewPluginValidator(pm, support.Ledger(), &dynamicDeserializer{support: support}, &dynamicCapabilities{support: support})
 	return &TxValidator{
+		ChainID: chainID,
 		Support: support,
-		Vscc:    newVSCCValidator(support, sccp, pluginValidator)}
+		Vscc:    newVSCCValidator(chainID, support, sccp, pluginValidator)}
 }
 
 func (v *TxValidator) chainExists(chain string) bool {
@@ -135,8 +138,9 @@ func (v *TxValidator) Validate(block *common.Block) error {
 	var err error
 	var errPos int
 
-	logger.Debug("START Block Validation")
-	defer logger.Debug("END Block Validation")
+	startValidation := time.Now() // timer to log Validate block duration
+	logger.Debugf("[%s] START Block Validation for block [%d]", v.ChainID, block.Header.Number)
+
 	// Initialize trans as valid here, then set invalidation reason code upon invalidation below
 	txsfltr := ledgerUtil.NewTxValidationFlags(len(block.Data.Data))
 	// txsChaincodeNames records all the invoked chaincodes by tx in a block
@@ -228,6 +232,9 @@ func (v *TxValidator) Validate(block *common.Block) error {
 
 	block.Metadata.Metadata[common.BlockMetadataIndex_TRANSACTIONS_FILTER] = txsfltr
 
+	elapsedValidation := time.Since(startValidation) / time.Millisecond // duration in ms
+	logger.Infof("[%s] Validated block [%d] in %dms", v.ChainID, block.Header.Number, elapsedValidation)
+
 	return nil
 }
 
@@ -287,8 +294,8 @@ func (v *TxValidator) validateTx(req *blockValidationRequest, results chan<- *bl
 		// chain binding proposal to endorsements to tx holds. We do
 		// NOT check the validity of endorsements, though. That's a
 		// job for VSCC below
-		logger.Debugf("validateTx starts for block %p env %p txn %d", block, env, tIdx)
-		defer logger.Debugf("validateTx completes for block %p env %p txn %d", block, env, tIdx)
+		logger.Debugf("[%s] validateTx starts for block %p env %p txn %d", v.ChainID, block, env, tIdx)
+		defer logger.Debugf("[%s] validateTx completes for block %p env %p txn %d", v.ChainID, block, env, tIdx)
 		var payload *common.Payload
 		var err error
 		var txResult peer.TxValidationCode