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

add time duration logging to runtime go code #2515

Merged
merged 2 commits into from
Nov 1, 2017
Merged

add time duration logging to runtime go code #2515

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
413069b
add time duration logging to runtime go code
nklincoln Nov 1, 2017
ca6fad2
Merge branch 'master' into add-perf-trace
nklincoln Nov 1, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 13 additions & 0 deletions packages/composer-runtime-hlfv1/chaincode.go
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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