Skip to content
This repository has been archived by the owner on Mar 8, 2020. It is now read-only.

Commit

Permalink
add time duration logging to runtime go code
Browse files Browse the repository at this point in the history 
Signed-off-by: Nick Lincoln <nkl199@yahoo.co.uk>
  • Loading branch information
@nklincoln
nklincoln committed Nov 1, 2017
1 parent 81afd3a commit a4fab97
Show file tree
Hide file tree
Showing 4 changed files with 167 additions and 0 deletions.
13 changes: 13 additions & 0 deletions packages/composer-runtime-hlfv1/chaincode.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ package main

import "github.com/hyperledger/fabric/core/chaincode/shim"
import pb "github.com/hyperledger/fabric/protos/peer"
import "time"



Expand All @@ -41,6 +42,10 @@ func (chaincode *Chaincode) Init(stub shim.ChaincodeStubInterface) (response pb.
//logging needs to be set here again as the fabric chaincode disables it
//even though it was enabled in main.
EnableLogging(stub)

start := time.Now()
defer func() { logger.Debug("@perf Chaincode.Init total duration for txnId [", stub.GetTxID(), "] : ", time.Now().Sub(start)) }()

logger.Debug("Entering Chaincode.Init", &stub)
defer func() {
logger.Debug("Exiting Chaincode.Init", response.Status, response.Message, string(response.Payload))
Expand All @@ -66,13 +71,20 @@ func (chaincode *Chaincode) Invoke(stub shim.ChaincodeStubInterface) (response p
//logging needs to be set here again as the fabric chaincode disables it
//even though it was enabled in main.
EnableLogging(stub)

start := time.Now()
defer func() { logger.Debug("@perf Chaincode.Invoke total duration for txnId [", stub.GetTxID(), "] : ", time.Now().Sub(start)) }()

logger.Debug("Entering Chaincode.Invoke", &stub)
defer func() {
logger.Debug("Exiting Chaincode.Invoke", response.Status, response.Message, string(response.Payload))
}()

// Get an instance of Composer from the pool, and ensure it's returned.
increment := time.Now()
composer := chaincode.ComposerPool.Get()
logger.Debug("@perf Chaincode.Invoke ComposerPool.Get() duration for txnId [", stub.GetTxID(), "] : ", time.Now().Sub(increment))
increment = time.Now();
defer chaincode.ComposerPool.Put(composer)

// Execute the invoke function.
Expand All @@ -81,5 +93,6 @@ func (chaincode *Chaincode) Invoke(stub shim.ChaincodeStubInterface) (response p
if err != nil {
return shim.Error(err.Error())
}
logger.Debug("@perf Chaincode.Invoke Invoke duration [", stub.GetTxID(), "] : ", time.Now().Sub(increment))
return shim.Success(payload)
}
14 changes: 14 additions & 0 deletions packages/composer-runtime-hlfv1/composer.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,8 @@ import (
duktape "gopkg.in/olebedev/go-duktape.v3"
)

import "time"

// Composer is the chaincode class. It is an implementation of the
// Chaincode interface.
type Composer struct {
Expand Down Expand Up @@ -50,6 +52,10 @@ func NewComposer() (result *Composer) {
// createJavaScript creates a new JavaScript virtual machine with the JavaScript code loaded.
func (composer *Composer) createJavaScript() {
logger.Debug("Entering Composer.createJavaScript")

start := time.Now()
defer func() { logger.Debug("@perf Composer.createJavaScript total duration :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting Composer.createJavaScript") }()

// Create a new JavaScript virtual machine.
Expand Down Expand Up @@ -117,6 +123,10 @@ func (composer *Composer) createJavaScript() {
// Init can read from and write to the world state.
func (composer *Composer) Init(stub shim.ChaincodeStubInterface, function string, arguments []string) (result []byte, err error) {
logger.Debug("Entering Composer.Init", &stub, function, arguments)

start := time.Now()
defer func() { logger.Debug("@perf Composer.Init total duration for [", stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting Composer.Init", string(result), err) }()

// Start a scope for locking the JavaScript virtual machine.
Expand Down Expand Up @@ -151,6 +161,10 @@ func (composer *Composer) Init(stub shim.ChaincodeStubInterface, function string
// Invoke can read from and write to the world state.
func (composer *Composer) Invoke(stub shim.ChaincodeStubInterface, function string, arguments []string) (result []byte, err error) {
logger.Debug("Entering Composer.Invoke", &stub, function, arguments)

start := time.Now()
defer func() { logger.Debug("@perf Composer.Invoke total duration for [", stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting Composer.Invoke", string(result), err) }()

// Start a scope for locking the JavaScript virtual machine.
Expand Down
81 changes: 81 additions & 0 deletions packages/composer-runtime-hlfv1/datacollection.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,8 @@ import (
"github.com/hyperledger/fabric/core/chaincode/shim"
)

import "time"

// DataCollection is a Go wrapper around an instance of the DataCollection JavaScript class.
type DataCollection struct {
VM *duktape.Context
Expand All @@ -30,6 +32,7 @@ type DataCollection struct {
// NewDataCollection creates a Go wrapper around a new instance of the DataCollection JavaScript class.
func NewDataCollection(vm *duktape.Context, dataService *DataService, stub shim.ChaincodeStubInterface, collectionID string) (result *DataCollection) {
logger.Debug("Entering NewDataCollection", vm, dataService, &stub)

defer func() { logger.Debug("Exiting NewDataCollection", result) }()

// Ensure the JavaScript stack is reset.
Expand Down Expand Up @@ -77,11 +80,17 @@ func NewDataCollection(vm *duktape.Context, dataService *DataService, stub shim.
// getAll retreieves all of the objects in this collection from the world state.
func (dataCollection *DataCollection) getAll(vm *duktape.Context) (result int) {
logger.Debug("Entering DataCollection.getAll", vm)

start := time.Now()
defer func() { logger.Debug("@perf DataCollection.getAll total duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting DataCollection.getAll", result) }()

// Validate the arguments from JavaScript.
vm.RequireFunction(0)

increment := time.Now();

// Create the composite key.
// The objects are stored with composite keys of collectionID + objectID.
iterator, err := dataCollection.Stub.GetStateByPartialCompositeKey(dataCollection.CollectionID, []string{})
Expand All @@ -94,6 +103,9 @@ func (dataCollection *DataCollection) getAll(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.getAll GetStateByPartialCompositeKey duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Must close iterator to free resources.
defer iterator.Close()

Expand Down Expand Up @@ -121,17 +133,27 @@ func (dataCollection *DataCollection) getAll(vm *duktape.Context) (result int) {

}

logger.Debug("@perf DataCollection.getAll key-iterator duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Call the callback.
vm.Dup(0)
vm.PushNull()
vm.Dup(arrIdx)
vm.Pcall(2)

logger.Debug("@perf DataCollection.getAll callback duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))

return 0
}

// get retrieves a specific object in this collection from the world state.
func (dataCollection *DataCollection) get(vm *duktape.Context) (result int) {
logger.Debug("Entering DataCollection.get", vm)

start := time.Now()
defer func() { logger.Debug("@perf DataCollection.get total duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting DataCollection.get", result) }()

// Validate the arguments from JavaScript.
Expand All @@ -150,6 +172,8 @@ func (dataCollection *DataCollection) get(vm *duktape.Context) (result int) {
return 0
}

increment = time.Now();

// Get the collection.
value, err := dataCollection.Stub.GetState(key)
if err != nil {
Expand All @@ -168,6 +192,9 @@ func (dataCollection *DataCollection) get(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.get GetState duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Parse the current value.
vm.PushString(string(value))
vm.JsonDecode(-1)
Expand All @@ -179,12 +206,18 @@ func (dataCollection *DataCollection) get(vm *duktape.Context) (result int) {
if vm.Pcall(2) == duktape.ExecError {
panic(vm.ToString(-1))
}

logger.Debug("@perf DataCollection.get callback duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
return 0
}

// exists checks to see if an object exists in this collection in the world state.
func (dataCollection *DataCollection) exists(vm *duktape.Context) (result int) {
logger.Debug("Entering DataCollection.exists", vm)

start := time.Now()
defer func() { logger.Debug("@perf DataCollection.exists total duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting DataCollection.exists", result) }()

// Validate the arguments from JavaScript.
Expand All @@ -203,6 +236,8 @@ func (dataCollection *DataCollection) exists(vm *duktape.Context) (result int) {
return 0
}

increment = time.Now();

// Get the object.
value, err := dataCollection.Stub.GetState(key)
if err != nil {
Expand All @@ -214,19 +249,28 @@ func (dataCollection *DataCollection) exists(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.get GetState duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Call the callback.
vm.Dup(1)
vm.PushNull()
vm.PushBoolean(value != nil)
if vm.Pcall(2) == duktape.ExecError {
panic(vm.ToString(-1))
}

logger.Debug("@perf DataCollection.get callback duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
return 0
}

// add adds an object to this collection in the world satte.
func (dataCollection *DataCollection) add(vm *duktape.Context) (result int) {
logger.Debug("Entering DataCollection.add", vm)

start := time.Now()
defer func() { logger.Debug("@perf DataCollection.add total duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting DataCollection.add", result) }()

// Validate the arguments from JavaScript.
Expand Down Expand Up @@ -272,6 +316,8 @@ func (dataCollection *DataCollection) add(vm *duktape.Context) (result int) {
}
}

increment = time.Now();

// Store the object in the collection.
err = dataCollection.Stub.PutState(key, []byte(value))
if err != nil {
Expand All @@ -283,18 +329,28 @@ func (dataCollection *DataCollection) add(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.get PutState duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Call the callback.
vm.Dup(3)
vm.PushNull()
if vm.Pcall(1) == duktape.ExecError {
panic(vm.ToString(-1))
}

logger.Debug("@perf DataCollection.get callback duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))

return 0
}

// update updates an existing object in this collection in the world state.
func (dataCollection *DataCollection) update(vm *duktape.Context) (result int) {
logger.Debug("Entering DataCollection.update", vm)

start := time.Now()
defer func() { logger.Debug("@perf DataCollection.update total duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting DataCollection.update", result) }()

// Validate the arguments from JavaScript.
Expand All @@ -319,6 +375,8 @@ func (dataCollection *DataCollection) update(vm *duktape.Context) (result int) {
return 0
}

increment = time.Now();

// Check to see if the object already exists.
existingValue, err := dataCollection.Stub.GetState(key)
if err != nil {
Expand All @@ -337,6 +395,9 @@ func (dataCollection *DataCollection) update(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.update GetState duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Store the object in the collection.
err = dataCollection.Stub.PutState(key, []byte(value))
if err != nil {
Expand All @@ -348,18 +409,27 @@ func (dataCollection *DataCollection) update(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.update PutState duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Call the callback.
vm.Dup(2)
vm.PushNull()
if vm.Pcall(1) == duktape.ExecError {
panic(vm.ToString(-1))
}

logger.Debug("@perf DataCollection.update callback duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
return 0
}

// remove removes an object from this collection in the world state.
func (dataCollection *DataCollection) remove(vm *duktape.Context) (result int) {
logger.Debug("Entering DataCollection.remove", vm)

start := time.Now()
defer func() { logger.Debug("@perf DataCollection.remove total duration for [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(start)) }()

defer func() { logger.Debug("Exiting DataCollection.remove", result) }()

// Validate the arguments from JavaScript.
Expand All @@ -378,6 +448,8 @@ func (dataCollection *DataCollection) remove(vm *duktape.Context) (result int) {
return 0
}

increment = time.Now();

// Check to see if the object already exists.
existingValue, err := dataCollection.Stub.GetState(key)
if err != nil {
Expand All @@ -396,6 +468,9 @@ func (dataCollection *DataCollection) remove(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.remove GetState duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Remove the object from the collection.
err = dataCollection.Stub.DelState(key)
if err != nil {
Expand All @@ -407,11 +482,17 @@ func (dataCollection *DataCollection) remove(vm *duktape.Context) (result int) {
return 0
}

logger.Debug("@perf DataCollection.remove DelState duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))
increment = time.Now();

// Call the callback.
vm.Dup(1)
vm.PushNull()
if vm.Pcall(1) == duktape.ExecError {
panic(vm.ToString(-1))
}

logger.Debug("@perf DataCollection.remove callback duration for collection [", dataCollection.CollectionID, "] and transaction [", dataCollection.Stub.GetTxID(),"] :", time.Now().Sub(increment))

return 0
}
Loading

0 comments on commit a4fab97

Please sign in to comment.