Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Performance] OpenTracing to OpenTelemetry migration #2823

Merged
merged 6 commits into from
Jul 26, 2022
Merged

Conversation

SaveTheRbtz
Copy link
Contributor

@SaveTheRbtz SaveTheRbtz commented Jul 19, 2022

Issue: #2796

OpenTracing spec is deprecated: opentracing/specification#163. Switching to the supported OpenTelemetry implementation.

Note that new tracing code would honor OTEL env vars instead of JAEGER ones, e.g.:
JAEGER_ENDPOINT -> OTEL_EXPORTER_OTLP_TRACES_ENDPOINT, OTEL_EXPORTER_OTLP_TRACES_INSECURE, etc

(cc: @sjonpaulbrown @haroldsphinx)

New API is slightly slower and consumes more memory but does substantially less allocs (~ -50%):

name                              old time/op    new time/op    delta
StartSpanFromParent-8                485ns ± 6%     639ns ± 1%  +31.71%  (p=0.000 n=10+9)
StartTransactionSpan/cacheHit-8      993ns ± 4%     927ns ± 3%   -6.69%  (p=0.000 n=10+10)
StartTransactionSpan/cacheMiss-8    2.24µs ± 1%    2.19µs ± 1%   -2.42%  (p=0.000 n=10+10)

name                              old alloc/op   new alloc/op   delta
StartSpanFromParent-8                 577B ± 0%      864B ± 0%  +49.74%  (p=0.000 n=10+10)
StartTransactionSpan/cacheHit-8       776B ± 1%      944B ± 0%  +21.65%  (p=0.000 n=10+8)
StartTransactionSpan/cacheMiss-8    2.16kB ± 1%    2.39kB ± 0%  +10.62%  (p=0.000 n=10+10)

name                              old allocs/op  new allocs/op  delta
StartSpanFromParent-8                 7.00 ± 0%      4.00 ± 0%  -42.86%  (p=0.000 n=10+10)
StartTransactionSpan/cacheHit-8       10.3 ± 7%       6.0 ± 0%  -41.75%  (p=0.000 n=10+10)
StartTransactionSpan/cacheMiss-8      35.3 ± 2%      18.0 ± 0%  -49.01%  (p=0.000 n=10+10)

An example of both extensive tracing and cadence tracing enabled:
Screen Shot 2022-07-25 at 10 21 07 PM

@github-actions
Copy link
Contributor

github-actions bot commented Jul 19, 2022

FVM Benchstat comparison

This branch with compared with the base branch onflow:master commit 888b34b

The command (for i in {1..N}; do go test ./fvm --bench . --tags relic -shuffle=on --benchmem --run ^$; done) was used.

Bench tests were run a total of 10 times on each branch.

Collapsed results for better readability

old.txtnew.txt
time/opdelta
RuntimeTransaction/get_public_account-242.4ms ± 6%48.3ms ±20%+13.81%(p=0.013 n=9+10)
RuntimeTransaction/get_account_and_get_balance-2660ms ± 5%696ms ± 7%+5.46%(p=0.013 n=9+10)
RuntimeTransaction/load_and_save_empty_string_on_signers_address-248.0ms ± 3%50.2ms ± 7%+4.55%(p=0.017 n=9+10)
RuntimeTransaction/get_account_and_get_available_balance-2547ms ± 5%569ms ± 7%+4.02%(p=0.029 n=10+10)
RuntimeTransaction/call_empty_contract_function-242.7ms ± 3%44.1ms ± 9%+3.29%(p=0.023 n=10+10)
RuntimeNFTBatchTransfer-2152ms ± 4%153ms ± 9%~(p=0.931 n=9+9)
RuntimeTransaction/reference_tx-238.9ms ± 7%39.6ms ±11%~(p=0.604 n=10+9)
RuntimeTransaction/convert_int_to_string-241.1ms ±20%41.3ms ± 8%~(p=0.489 n=9+9)
RuntimeTransaction/convert_int_to_string_and_concatenate_it-241.7ms ± 4%43.5ms ± 9%~(p=0.055 n=8+10)
RuntimeTransaction/get_signer_address-242.5ms ±26%40.5ms ± 7%~(p=0.905 n=10+9)
RuntimeTransaction/get_account_and_get_storage_used-248.6ms ± 8%50.3ms ± 9%~(p=0.050 n=9+9)
RuntimeTransaction/get_account_and_get_storage_capacity-2526ms ±13%540ms ±11%~(p=0.280 n=10+10)
RuntimeTransaction/get_signer_vault-249.3ms ± 7%49.8ms ±11%~(p=0.796 n=10+10)
RuntimeTransaction/get_signer_receiver-263.5ms ± 7%62.4ms ± 8%~(p=0.222 n=9+9)
RuntimeTransaction/transfer_tokens-2244ms ± 6%249ms ± 8%~(p=0.247 n=10+10)
RuntimeTransaction/load_and_save_long_string_on_signers_address-2102ms ± 4%104ms ±10%~(p=0.971 n=10+10)
RuntimeTransaction/create_new_account-21.35s ± 6%1.38s ± 5%~(p=0.315 n=9+10)
RuntimeTransaction/emit_event-261.9ms ± 7%63.4ms ±10%~(p=0.247 n=10+10)
RuntimeTransaction/borrow_array_from_storage-2158ms ± 5%156ms ± 9%~(p=0.436 n=10+10)
RuntimeTransaction/copy_array_from_storage-2160ms ± 6%163ms ± 9%~(p=0.489 n=9+9)
 
alloc/opdelta
RuntimeTransaction/create_new_account-2264MB ± 0%267MB ± 0%+1.37%(p=0.000 n=10+10)
RuntimeTransaction/get_account_and_get_storage_capacity-2143MB ± 0%145MB ± 0%+1.28%(p=0.000 n=10+10)
RuntimeTransaction/get_account_and_get_available_balance-2148MB ± 0%150MB ± 0%+1.26%(p=0.000 n=9+10)
RuntimeTransaction/load_and_save_long_string_on_signers_address-225.6MB ± 1%25.8MB ± 0%+1.02%(p=0.000 n=10+10)
RuntimeTransaction/call_empty_contract_function-210.6MB ± 0%10.7MB ± 1%+0.98%(p=0.000 n=10+10)
RuntimeTransaction/get_account_and_get_balance-2198MB ± 0%200MB ± 0%+0.92%(p=0.000 n=10+10)
RuntimeTransaction/convert_int_to_string_and_concatenate_it-210.7MB ± 1%10.8MB ± 1%+0.92%(p=0.000 n=10+10)
RuntimeTransaction/reference_tx-29.74MB ± 1%9.83MB ± 1%+0.87%(p=0.003 n=10+10)
RuntimeTransaction/get_account_and_get_storage_used-212.6MB ± 0%12.7MB ± 1%+0.85%(p=0.000 n=9+10)
RuntimeTransaction/convert_int_to_string-210.2MB ± 1%10.3MB ± 1%+0.81%(p=0.000 n=10+10)
RuntimeTransaction/load_and_save_empty_string_on_signers_address-211.4MB ± 1%11.5MB ± 0%+0.73%(p=0.001 n=10+10)
RuntimeTransaction/get_public_account-211.4MB ± 1%11.5MB ± 0%+0.69%(p=0.002 n=10+10)
RuntimeTransaction/get_signer_address-210.0MB ± 0%10.0MB ± 1%+0.66%(p=0.000 n=8+10)
RuntimeTransaction/get_signer_receiver-215.8MB ± 0%15.9MB ± 0%+0.46%(p=0.000 n=10+10)
RuntimeTransaction/emit_event-214.9MB ± 0%15.0MB ± 1%+0.41%(p=0.009 n=10+10)
RuntimeTransaction/copy_array_from_storage-247.0MB ± 0%47.1MB ± 0%+0.25%(p=0.000 n=7+8)
RuntimeTransaction/transfer_tokens-250.9MB ± 0%51.0MB ± 0%+0.22%(p=0.004 n=10+9)
RuntimeNFTBatchTransfer-227.6MB ± 1%27.8MB ± 0%~(p=0.400 n=10+9)
RuntimeTransaction/get_signer_vault-212.0MB ± 1%12.0MB ± 1%~(p=0.278 n=9+10)
RuntimeTransaction/borrow_array_from_storage-236.0MB ± 0%36.0MB ± 0%~(p=0.796 n=10+10)
 
allocs/opdelta
RuntimeTransaction/load_and_save_long_string_on_signers_address-2299k ± 0%303k ± 0%+1.35%(p=0.000 n=9+9)
RuntimeTransaction/create_new_account-24.39M ± 0%4.43M ± 0%+0.91%(p=0.000 n=10+10)
RuntimeNFTBatchTransfer-2388k ± 1%391k ± 0%+0.89%(p=0.000 n=10+9)
RuntimeTransaction/get_account_and_get_storage_capacity-22.50M ± 0%2.52M ± 0%+0.75%(p=0.000 n=10+10)
RuntimeTransaction/get_account_and_get_available_balance-22.65M ± 0%2.67M ± 0%+0.68%(p=0.000 n=9+10)
RuntimeTransaction/call_empty_contract_function-2172k ± 0%173k ± 0%+0.57%(p=0.000 n=10+9)
RuntimeTransaction/reference_tx-2155k ± 0%156k ± 0%+0.57%(p=0.000 n=9+10)
RuntimeTransaction/get_signer_address-2160k ± 0%161k ± 0%+0.55%(p=0.000 n=10+10)
RuntimeTransaction/convert_int_to_string-2169k ± 0%170k ± 0%+0.52%(p=0.000 n=8+9)
RuntimeTransaction/get_account_and_get_balance-23.28M ± 0%3.30M ± 0%+0.51%(p=0.000 n=8+10)
RuntimeTransaction/convert_int_to_string_and_concatenate_it-2184k ± 0%184k ± 0%+0.48%(p=0.000 n=9+10)
RuntimeTransaction/load_and_save_empty_string_on_signers_address-2206k ± 0%207k ± 0%+0.47%(p=0.000 n=9+10)
RuntimeTransaction/get_signer_vault-2208k ± 0%209k ± 0%+0.47%(p=0.000 n=10+10)
RuntimeTransaction/get_public_account-2192k ± 0%192k ± 0%+0.46%(p=0.000 n=10+9)
RuntimeTransaction/get_signer_receiver-2297k ± 0%298k ± 0%+0.35%(p=0.000 n=10+10)
RuntimeTransaction/emit_event-2219k ± 0%219k ± 0%~(p=0.897 n=10+10)
RuntimeTransaction/get_account_and_get_storage_used-2215k ± 0%214k ± 0%−0.05%(p=0.000 n=9+10)
RuntimeTransaction/transfer_tokens-21.07M ± 0%1.07M ± 0%−0.18%(p=0.000 n=10+10)
RuntimeTransaction/borrow_array_from_storage-2450k ± 0%446k ± 0%−0.87%(p=0.000 n=10+10)
RuntimeTransaction/copy_array_from_storage-2406k ± 0%402k ± 0%−0.96%(p=0.000 n=9+9)
 
computationdelta
RuntimeTransaction/reference_tx-2202 ± 0%202 ± 0%~(all equal)
RuntimeTransaction/convert_int_to_string-2402 ± 0%402 ± 0%~(all equal)
RuntimeTransaction/convert_int_to_string_and_concatenate_it-2502 ± 0%502 ± 0%~(all equal)
RuntimeTransaction/get_signer_address-2302 ± 0%302 ± 0%~(all equal)
RuntimeTransaction/get_public_account-2402 ± 0%402 ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_balance-21.00k ± 0%1.00k ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_available_balance-22.50k ± 0%2.50k ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_storage_used-2402 ± 0%402 ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_storage_capacity-21.30k ± 0%1.30k ± 0%~(all equal)
RuntimeTransaction/get_signer_vault-2402 ± 0%402 ± 0%~(all equal)
RuntimeTransaction/get_signer_receiver-2602 ± 0%602 ± 0%~(all equal)
RuntimeTransaction/transfer_tokens-23.50k ± 0%3.50k ± 0%~(all equal)
RuntimeTransaction/load_and_save_empty_string_on_signers_address-2602 ± 0%602 ± 0%~(all equal)
RuntimeTransaction/load_and_save_long_string_on_signers_address-2602 ± 0%602 ± 0%~(all equal)
RuntimeTransaction/create_new_account-2202 ± 0%202 ± 0%~(all equal)
RuntimeTransaction/call_empty_contract_function-2402 ± 0%402 ± 0%~(all equal)
RuntimeTransaction/emit_event-2602 ± 0%602 ± 0%~(all equal)
RuntimeTransaction/borrow_array_from_storage-22.60k ± 0%2.60k ± 0%~(all equal)
RuntimeTransaction/copy_array_from_storage-22.60k ± 0%2.60k ± 0%~(all equal)
 
interactionsdelta
RuntimeTransaction/reference_tx-247.8k ± 0%47.8k ± 0%~(all equal)
RuntimeTransaction/convert_int_to_string-247.8k ± 0%47.8k ± 0%~(all equal)
RuntimeTransaction/convert_int_to_string_and_concatenate_it-247.8k ± 0%47.8k ± 0%~(all equal)
RuntimeTransaction/get_signer_address-247.8k ± 0%47.8k ± 0%~(all equal)
RuntimeTransaction/get_public_account-247.8k ± 0%47.8k ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_balance-216.8M ± 0%16.8M ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_available_balance-25.34M ± 0%5.34M ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_storage_used-251.4k ± 0%51.4k ± 0%~(all equal)
RuntimeTransaction/get_account_and_get_storage_capacity-25.34M ± 0%5.34M ± 0%~(all equal)
RuntimeTransaction/get_signer_vault-249.0k ± 0%49.0k ± 0%~(all equal)
RuntimeTransaction/get_signer_receiver-249.4k ± 0%49.4k ± 0%~(all equal)
RuntimeTransaction/transfer_tokens-250.2k ± 0%50.2k ± 0%~(all equal)
RuntimeTransaction/load_and_save_empty_string_on_signers_address-251.2k ± 0%51.2k ± 0%~(all equal)
RuntimeTransaction/load_and_save_long_string_on_signers_address-256.2k ± 0%56.2k ± 0%~(all equal)
RuntimeTransaction/create_new_account-28.49M ± 0%8.49M ± 0%~(all equal)
RuntimeTransaction/call_empty_contract_function-248.0k ± 0%48.0k ± 0%~(all equal)
RuntimeTransaction/emit_event-248.0k ± 0%48.0k ± 0%~(all equal)
RuntimeTransaction/borrow_array_from_storage-254.1k ± 0%54.1k ± 0%~(all equal)
RuntimeTransaction/copy_array_from_storage-254.1k ± 0%54.1k ± 0%~(all equal)
 

@SaveTheRbtz SaveTheRbtz force-pushed the rbtz/OTEL1 branch 2 times, most recently from aa4cc0f to 804e281 Compare July 20, 2022 19:31
fvm/errors/errors.go Outdated Show resolved Hide resolved
go.mod Outdated Show resolved Hide resolved
integration/go.mod Outdated Show resolved Hide resolved
module/trace/trace.go Show resolved Hide resolved
@SaveTheRbtz SaveTheRbtz marked this pull request as ready for review July 20, 2022 19:32
@SaveTheRbtz SaveTheRbtz changed the title [WIP] OpenTracing to OpenTelemetry migration [All] OpenTracing to OpenTelemetry migration Jul 20, 2022
Copy link
Contributor

@pattyshack pattyshack left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it's hard to review large sweeping changes to both api and implementation at the same time. next time use the bridge pattern to decouple the changes

engine/verification/assigner/engine.go Outdated Show resolved Hide resolved
fvm/scriptEnv.go Outdated Show resolved Hide resolved
fvm/contractFunctionInvoker.go Outdated Show resolved Hide resolved
attribute.Int64("tx_index", int64(txIndex)),
attribute.Int("col_index", collectionIndex),
)
defer txSpan.End()

var traceID string
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

traceID is uninitialized. rm this is logging below

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it is used down there on line 403

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logging an uninitialized traceId is pointless. just rm it from line 403 and rm the decl here (same with my other comment)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the goal here is twofold:

  • for traces that are sampled we want to log traceid, but for ones that are not we do not want to log 000000000000...
  • for traces that are not sampled, logging "" is cheaper than creating a whole new logger within an if isSampled {} block.

@@ -99,16 +98,14 @@ func (c *Core) OnBlockProposal(originID flow.Identifier, proposal *messages.Bloc

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

traceID is uninitialized. rm declaration and logging below

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it is used in the log line on line 124

Copy link
Contributor

@ramtinms ramtinms left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good to me, just some minor questions

module/trace/trace.go Outdated Show resolved Hide resolved
Comment on lines +225 to +222
ctx := trace.ContextWithSpan(context.Background(), parentSpan)
_, span := t.tracer.Start(ctx, string(operationName), opts...)
return span
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is ContextWithSpan automatically label the span relationship as children/parent ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yep!

Comment on lines +242 to +240
ctx := trace.ContextWithSpanContext(context.Background(), parentSpan.SpanContext())
opts = append(opts,
trace.WithAttributes(attrs...),
trace.WithTimestamp(start),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

same here how do we label it as FollowsFrom label.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

do we need to add this label? IIUC there should be no need for additional labels/links given that we have parent-child relationship here.

bors bot added a commit that referenced this pull request Jul 25, 2022
2853: [FVM] Update cadence to support Executor pattern r=SaveTheRbtz a=SaveTheRbtz

Factored out cadence update and test fixes out of #2837 so that we can break circular dependency on #2823

Co-authored-by: Janez Podhostnik <janez.podhostnik@gmail.com>

Co-authored-by: Alexey Ivanov <rbtz@dapperlabs.com>
bors bot added a commit that referenced this pull request Jul 25, 2022
2853: [FVM] Update cadence to support Executor pattern r=SaveTheRbtz a=SaveTheRbtz

Factored out cadence update and test fixes out of #2837 so that we can break circular dependency on #2823

Co-authored-by: Janez Podhostnik <janez.podhostnik@gmail.com>

2856: migrate environment to new span api r=pattyshack a=pattyshack



Co-authored-by: Alexey Ivanov <rbtz@dapperlabs.com>
Co-authored-by: Patrick Lee <patrick.lee@dapperlabs.com>
bors bot added a commit that referenced this pull request Jul 25, 2022
2853: [FVM] Update cadence to support Executor pattern r=SaveTheRbtz a=SaveTheRbtz

Factored out cadence update and test fixes out of #2837 so that we can break circular dependency on #2823

Co-authored-by: Janez Podhostnik <janez.podhostnik@gmail.com>

Co-authored-by: Alexey Ivanov <rbtz@dapperlabs.com>
bors bot added a commit that referenced this pull request Jul 26, 2022
2853: [FVM] Update cadence to support Executor pattern r=SaveTheRbtz a=SaveTheRbtz

Factored out cadence update and test fixes out of #2837 so that we can break circular dependency on #2823

Co-authored-by: Janez Podhostnik <janez.podhostnik@gmail.com>

2858: [FVM] cleanup and regenerate mocks r=SaveTheRbtz a=SaveTheRbtz



Co-authored-by: Alexey Ivanov <rbtz@dapperlabs.com>
bors bot added a commit that referenced this pull request Jul 26, 2022
2853: [FVM] Update cadence to support Executor pattern r=SaveTheRbtz a=SaveTheRbtz

Factored out cadence update and test fixes out of #2837 so that we can break circular dependency on #2823

Co-authored-by: Janez Podhostnik <janez.podhostnik@gmail.com>

Co-authored-by: Alexey Ivanov <rbtz@dapperlabs.com>
@codecov-commenter
Copy link

codecov-commenter commented Jul 26, 2022

Codecov Report

Merging #2823 (93370c8) into master (888b34b) will increase coverage by 0.03%.
The diff coverage is 29.02%.

@@            Coverage Diff             @@
##           master    #2823      +/-   ##
==========================================
+ Coverage   56.44%   56.48%   +0.03%     
==========================================
  Files         695      695              
  Lines       63211    63174      -37     
==========================================
+ Hits        35678    35681       +3     
+ Misses      24577    24538      -39     
+ Partials     2956     2955       -1     
Flag Coverage Δ
unittests 56.48% <29.02%> (+0.03%) ⬆️

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

Impacted Files Coverage Δ
engine/execution/provider/engine.go 45.21% <0.00%> (ø)
engine/execution/state/state.go 21.53% <0.00%> (ø)
fvm/contractFunctionInvocations.go 97.02% <ø> (ø)
fvm/transaction.go 69.35% <0.00%> (ø)
fvm/transactionEnv.go 66.92% <ø> (-0.07%) ⬇️
fvm/transactionSequenceNum.go 64.28% <0.00%> (ø)
fvm/transactionVerifier.go 79.11% <0.00%> (ø)
module/trace/log_tracer.go 0.00% <0.00%> (ø)
module/trace/noop.go 0.00% <0.00%> (ø)
module/trace/trace.go 0.00% <0.00%> (ø)
... and 28 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 888b34b...93370c8. Read the comment docs.

@SaveTheRbtz
Copy link
Contributor Author

bors merge

@bors
Copy link
Contributor

bors bot commented Jul 26, 2022

Build succeeded:

@bors bors bot merged commit f9c16a5 into master Jul 26, 2022
@bors bors bot deleted the rbtz/OTEL1 branch July 26, 2022 06:05
@SaveTheRbtz SaveTheRbtz changed the title [All] OpenTracing to OpenTelemetry migration [Performance] OpenTracing to OpenTelemetry migration Aug 8, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants