Expand interpreter tracing for composite, array and dictionary types #1450

ramtinms · 2022-02-25T21:37:14Z

Description

This PR expands tracing functionality inside cadence for composite, array and dictionary types. these open traces are disabled by default and upon enabling it, they would be passed to the interface's recordTrace method for further aggregation. These traces are great tools for analyzing the performance of the interpreter when handling these types.

Targeted PR against master branch
Linked to Github issue with discussion and accepted design OR link to spec that describes this work
Code follows the standards mentioned here
Updated relevant documentation
Re-reviewed Files changed in the Github PR explorer
Added appropriate labels

github-actions · 2022-02-25T21:50:01Z

Cadence Benchstat comparison

This branch with compared with the base branch onflow:master commit 3705ef1
The command for i in {1..N}; do go test ./... -run=XXX -bench=. -shuffle=on; done was used.
Bench tests were run a total of 7 times on each branch.

Results

	old.txt	new.txt
	time/op		delta
InterpretRecursionFib-2	2.89ms ± 4%	3.24ms ± 6%	+12.17%	(p=0.001 n=7+7)
ParseFungibleToken-2	235µs ± 3%	249µs ± 5%	+6.29%	(p=0.005 n=6+7)
RuntimeResourceDictionaryValues-2	16.9ms ± 6%	17.5ms ± 3%	~	(p=0.051 n=7+6)
RuntimeFungibleTokenTransfer-2	1.34ms ±33%	1.46ms ±26%	~	(p=0.165 n=7+7)
ParseInfix-2	10.3µs ± 7%	10.1µs ± 2%	~	(p=0.445 n=7+6)
ParseArray-2	15.5ms ± 2%	15.4ms ± 2%	~	(p=0.589 n=6+6)
ParseDeploy/byte_array-2	23.9ms ± 2%	23.5ms ± 4%	~	(p=0.101 n=7+6)
ParseDeploy/decode_hex-2	1.47ms ± 1%	1.45ms ± 2%	~	(p=0.065 n=6+6)
QualifiedIdentifierCreation/One_level-2	3.42ns ± 2%	3.45ns ± 4%	~	(p=0.598 n=7+7)
QualifiedIdentifierCreation/Three_levels-2	181ns ± 5%	181ns ± 6%	~	(p=1.000 n=7+7)
CheckContractInterfaceFungibleTokenConformance-2	176µs ± 3%	178µs ± 3%	~	(p=0.628 n=7+6)
ContractInterfaceFungibleToken-2	50.2µs ± 5%	51.1µs ± 9%	~	(p=0.535 n=7+7)
NewInterpreter/new_interpreter-2	1.35µs ±10%	1.35µs ± 3%	~	(p=0.318 n=7+7)
NewInterpreter/new_sub-interpreter-2	2.62µs ± 7%	2.61µs ± 5%	~	(p=0.535 n=7+7)

	alloc/op		delta
InterpretRecursionFib-2	1.24MB ± 0%	1.26MB ± 0%	+1.57%	(p=0.001 n=7+6)
RuntimeFungibleTokenTransfer-2	272kB ± 0%	272kB ± 0%	~	(p=0.128 n=7+7)
QualifiedIdentifierCreation/One_level-2	0.00B	0.00B	~	(all equal)
QualifiedIdentifierCreation/Three_levels-2	64.0B ± 0%	64.0B ± 0%	~	(all equal)
CheckContractInterfaceFungibleTokenConformance-2	66.2kB ± 0%	66.2kB ± 0%	~	(all equal)
ContractInterfaceFungibleToken-2	26.6kB ± 0%	26.6kB ± 0%	~	(p=0.385 n=7+6)
NewInterpreter/new_interpreter-2	768B ± 0%	768B ± 0%	~	(all equal)
NewInterpreter/new_sub-interpreter-2	1.24kB ± 0%	1.24kB ± 0%	~	(all equal)
RuntimeResourceDictionaryValues-2	4.05MB ± 0%	4.05MB ± 0%	−0.01%	(p=0.012 n=6+7)

	allocs/op		delta
InterpretRecursionFib-2	25.0k ± 0%	26.2k ± 0%	+4.88%	(p=0.001 n=7+7)
RuntimeFungibleTokenTransfer-2	4.52k ± 0%	4.52k ± 0%	~	(p=0.592 n=7+7)
QualifiedIdentifierCreation/One_level-2	0.00	0.00	~	(all equal)
QualifiedIdentifierCreation/Three_levels-2	2.00 ± 0%	2.00 ± 0%	~	(all equal)
CheckContractInterfaceFungibleTokenConformance-2	1.07k ± 0%	1.07k ± 0%	~	(all equal)
ContractInterfaceFungibleToken-2	458 ± 0%	458 ± 0%	~	(all equal)
NewInterpreter/new_interpreter-2	12.0 ± 0%	12.0 ± 0%	~	(all equal)
NewInterpreter/new_sub-interpreter-2	38.0 ± 0%	38.0 ± 0%	~	(all equal)
RuntimeResourceDictionaryValues-2	102k ± 0%	102k ± 0%	−0.00%	(p=0.009 n=7+7)

codecov-commenter · 2022-02-25T22:33:56Z

Codecov Report

Merging #1450 (a0d9475) into master (3705ef1) will increase coverage by 0.48%.
The diff coverage is 84.55%.

@@            Coverage Diff             @@
##           master    #1450      +/-   ##
==========================================
+ Coverage   72.54%   73.02%   +0.48%     
==========================================
  Files         288      288              
  Lines       39456    39719     +263     
==========================================
+ Hits        28624    29006     +382     
+ Misses       9376     9245     -131     
- Partials     1456     1468      +12

Flag	Coverage Δ
unittests	`73.02% <84.55%> (+0.48%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
runtime/interpreter/value.go	`58.25% <83.68%> (+1.90%)`	⬆️
runtime/interpreter/interpreter_tracing.go	`91.66% <87.50%> (+91.66%)`	⬆️
runtime/interpreter/interpreter_expression.go	`83.11% <100.00%> (+1.04%)`	⬆️
runtime/interpreter/interpreter_import.go	`100.00% <100.00%> (+18.51%)`	⬆️
runtime/sema/simple_type.go	`92.85% <0.00%> (-3.58%)`	⬇️
runtime/sema/type.go	`88.50% <0.00%> (+0.07%)`	⬆️
runtime/sema/checker.go	`89.24% <0.00%> (+0.17%)`	⬆️
runtime/ast/type.go	`93.28% <0.00%> (+2.12%)`	⬆️
... and 5 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 3705ef1...a0d9475. Read the comment docs.

turbolent · 2022-02-28T23:51:49Z

Just realized: Tracing is disabled by default, so tests will not exercise any of this code.

Could you please add this after https://github.com/onflow/cadence/blob/master/runtime/tests/interpreter/interpreter_test.go#L97-L97:

			interpreter.WithOnRecordTraceHandler(
				func(
					_ *interpreter.Interpreter,
					_ string,
					_ time.Duration,
					_ []opentracing.LogRecord,
				) {
					// NO-OP
				},
			),
			interpreter.WithTracingEnabled(true),

turbolent · 2022-02-28T23:52:55Z

Please follow and fill out the checklist, thank you

turbolent

Looks good!

runtime/interpreter/interpreter_tracing_test.go

runtime/interpreter/value.go

turbolent · 2022-03-01T17:49:20Z

runtime/interpreter/interpreter_tracing_test.go

 	"github.com/onflow/cadence/runtime/tests/utils"
 )

+func setupInterpreterWithTracingCallBack(


turbolent

Looks good, nice work!

Seems like some tests fail.

Should we also port this to 0.23? (the next Cadence release)

turbolent · 2022-03-01T18:09:52Z

@ramtinms I looked at the failing tests. Transfer functions are bit tricky, OK if I fix the tracing calls?
Basically, the tracing is using a defer, and by the time the trace is reported, the value has already changed

ramtinms · 2022-03-01T18:15:39Z

its not a must-have for 0.23, but would make our life easier if its backported.

turbolent · 2022-03-01T19:08:28Z

@ramtinms In f9d8c81 I:

Removed the tracing from Clone calls. This is an internal function which is never called by the interpreter, it is only used by e.g. a state migration
Unified how the tracing information is prepared
Moved the preparation of the tracing information before the deferal (when possible), so it does not access potentially invalidated information/state (e.g. Transfer sets ArrayValue/DictionaryValue/CompositeValue's array/dictionary nil if it is a resource

ramtinms · 2022-03-01T19:11:07Z

changes looks great, thanks for taking care of it

turbolent · 2022-03-01T19:12:10Z

@SupunS Could you please have a second look?

SupunS

Looks good to me!

runtime/interpreter/value.go

Co-authored-by: Supun Setunga <[email protected]>

ramtinms added 3 commits February 25, 2022 12:46

expand interpreter tracing

045d486

init tests for tracing

fa4cf97

make linter happy

2a055c2

clean up

baa8a70

ramtinms added 3 commits February 25, 2022 14:42

improve tests

685f9f3

add test for array tracing

82749fd

add tests for dictionary tracing

427c329

ramtinms changed the title ~~[WIP] expand interpreter tracing~~ Expand interpreter tracing for composite, array and dictionary types Feb 25, 2022

ramtinms marked this pull request as ready for review February 25, 2022 23:06

ramtinms requested review from turbolent, SupunS and dsainati1 as code owners February 25, 2022 23:06

turbolent reviewed Feb 28, 2022

View reviewed changes

runtime/interpreter/interpreter_tracing_test.go Outdated Show resolved Hide resolved

runtime/interpreter/value.go Outdated Show resolved Hide resolved

apply PR's comments

3a0475c

ramtinms added the Improvement label Mar 1, 2022

ramtinms requested a review from turbolent March 1, 2022 07:29

ramtinms and others added 2 commits February 28, 2022 23:34

Merge branch 'master' into ramtin/expand-interpreter-tracing

7346eda

fix linter

4dcda33

turbolent reviewed Mar 1, 2022

View reviewed changes

turbolent approved these changes Mar 1, 2022

View reviewed changes

remove clone, prepare tracing info at right time, handle errors

f9d8c81

turbolent approved these changes Mar 1, 2022

View reviewed changes

SupunS approved these changes Mar 1, 2022

View reviewed changes

runtime/interpreter/value.go Outdated Show resolved Hide resolved

Update runtime/interpreter/value.go

a0d9475

Co-authored-by: Supun Setunga <[email protected]>

turbolent merged commit e5b31e1 into master Mar 1, 2022

turbolent deleted the ramtin/expand-interpreter-tracing branch March 1, 2022 21:38

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Expand interpreter tracing for composite, array and dictionary types #1450

Expand interpreter tracing for composite, array and dictionary types #1450

ramtinms commented Feb 25, 2022 •

edited

Loading

github-actions bot commented Feb 25, 2022 •

edited

Loading

codecov-commenter commented Feb 25, 2022 •

edited

Loading

turbolent commented Feb 28, 2022

turbolent commented Feb 28, 2022

turbolent left a comment

turbolent Mar 1, 2022

turbolent left a comment

turbolent commented Mar 1, 2022

ramtinms commented Mar 1, 2022

turbolent commented Mar 1, 2022

ramtinms commented Mar 1, 2022

turbolent commented Mar 1, 2022

SupunS left a comment

Expand interpreter tracing for composite, array and dictionary types #1450

Expand interpreter tracing for composite, array and dictionary types #1450

Conversation

ramtinms commented Feb 25, 2022 • edited Loading

Description

github-actions bot commented Feb 25, 2022 • edited Loading

Cadence Benchstat comparison

Results

codecov-commenter commented Feb 25, 2022 • edited Loading

Codecov Report

turbolent commented Feb 28, 2022

turbolent commented Feb 28, 2022

turbolent left a comment

Choose a reason for hiding this comment

turbolent Mar 1, 2022

Choose a reason for hiding this comment

turbolent left a comment

Choose a reason for hiding this comment

turbolent commented Mar 1, 2022

ramtinms commented Mar 1, 2022

turbolent commented Mar 1, 2022

ramtinms commented Mar 1, 2022

turbolent commented Mar 1, 2022

SupunS left a comment

Choose a reason for hiding this comment

ramtinms commented Feb 25, 2022 •

edited

Loading

github-actions bot commented Feb 25, 2022 •

edited

Loading

codecov-commenter commented Feb 25, 2022 •

edited

Loading