Skip to content

SCP 2364 Add time tracing for profiling #3577

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.

Sign up for GitHub

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

Jump to bottom
Closed
wants to merge 6 commits into from
Closed

SCP 2364 Add time tracing for profiling #3577

wants to merge 6 commits into from

Conversation

@thealmarty
Copy link
Contributor

@thealmarty thealmarty commented Jul 19, 2021

Pre-submit checklist:

  • Branch
    • Commit sequence broadly makes sense
    • Key commits have useful messages
    • Relevant tickets are mentioned in commit messages
    • Formatting, materialized Nix files, PNG optimization, etc. are updated
  • PR
    • Self-reviewed the diff
    • Useful pull request description
    • Reviewer requested

Pre-merge checklist:

  • Someone approved it
  • Commits have useful messages
  • Review clarifications made it into the code
  • History is moderately tidy; or going to squash-merge

@thealmarty thealmarty force-pushed the thealmarty/scp-2364-add-trace-time branch from be3f972 to aadebd9 Compare July 19, 2021 15:32
@thealmarty
Copy link
Contributor Author

thealmarty commented Jul 19, 2021

/benchmark

1 similar comment
@thealmarty
Copy link
Contributor Author

thealmarty commented Jul 19, 2021

/benchmark

@iohk-devops
Copy link

iohk-devops commented Jul 19, 2021

Comparing benchmark results of '9437522ba24e8168caa1e6e03f4b45a682f49a10' (base) and '9437522ba24e8168caa1e6e03f4b45a682f49a10' (PR)

Script 9437522 9437522 Change
crowdfunding/crowdfunding-success-1 646.7 μs 645.7 μs -0.2%
crowdfunding/crowdfunding-success-2 649.3 μs 646.3 μs -0.5%
crowdfunding/crowdfunding-success-3 648.7 μs 646.7 μs -0.3%
currency/currency-1 584.1 μs 579.8 μs -0.7%
currency/currency-2 808.3 μs 799.2 μs -1.1%
escrow/escrow-redeem_1-1 951.8 μs 941.2 μs -1.1%
escrow/escrow-redeem_1-2 951.3 μs 940.5 μs -1.1%
escrow/escrow-redeem_2-1 1.085 ms 1.072 ms -1.2%
escrow/escrow-redeem_2-2 1.085 ms 1.072 ms -1.2%
escrow/escrow-redeem_2-3 1.084 ms 1.072 ms -1.1%
escrow/escrow-refund-1 445.5 μs 443.0 μs -0.6%
future/future-increase-margin-1 583.6 μs 581.5 μs -0.4%
future/future-increase-margin-2 803.9 μs 803.1 μs -0.1%
future/future-increase-margin-3 1.367 ms 1.363 ms -0.3%
future/future-increase-margin-4 1.366 ms 1.365 ms -0.1%
future/future-increase-margin-5 1.407 ms 1.409 ms +0.1%
future/future-increase-margin-6 1.840 ms 1.843 ms +0.2%
future/future-pay-out-1 582.2 μs 581.5 μs -0.1%
future/future-pay-out-2 803.7 μs 800.3 μs -0.4%
future/future-pay-out-3 1.367 ms 1.362 ms -0.4%
future/future-pay-out-4 1.372 ms 1.363 ms -0.7%
future/future-pay-out-5 1.920 ms 1.899 ms -1.1%
future/future-settle-early-1 585.2 μs 581.2 μs -0.7%
future/future-settle-early-2 809.6 μs 800.9 μs -1.1%
future/future-settle-early-3 1.377 ms 1.362 ms -1.1%
future/future-settle-early-4 1.378 ms 1.360 ms -1.3%
future/future-settle-early-5 1.536 ms 1.519 ms -1.1%
game-sm/game-sm-success-1 1.012 ms 1.004 ms -0.8%
game-sm/game-sm-success-2 608.5 μs 601.4 μs -1.2%
game-sm/game-sm-success-3 1.459 ms 1.449 ms -0.7%
game-sm/game-sm-success-4 726.4 μs 717.4 μs -1.2%
game-sm/game-sm-success_2-1 1.011 ms 1.002 ms -0.9%
game-sm/game-sm-success_2-2 608.9 μs 603.2 μs -0.9%
game-sm/game-sm-success_2-3 1.465 ms 1.457 ms -0.5%
game-sm/game-sm-success_2-4 725.3 μs 721.5 μs -0.5%
game-sm/game-sm-success_2-5 1.457 ms 1.455 ms -0.1%
game-sm/game-sm-success_2-6 724.9 μs 721.9 μs -0.4%
multisig-sm/multisig-sm-01 1.059 ms 1.055 ms -0.4%
multisig-sm/multisig-sm-02 1.067 ms 1.059 ms -0.7%
multisig-sm/multisig-sm-03 1.083 ms 1.073 ms -0.9%
multisig-sm/multisig-sm-04 1.097 ms 1.087 ms -0.9%
multisig-sm/multisig-sm-05 1.290 ms 1.275 ms -1.2%
multisig-sm/multisig-sm-06 1.064 ms 1.053 ms -1.0%
multisig-sm/multisig-sm-07 1.066 ms 1.056 ms -0.9%
multisig-sm/multisig-sm-08 1.079 ms 1.071 ms -0.7%
multisig-sm/multisig-sm-09 1.096 ms 1.084 ms -1.1%
multisig-sm/multisig-sm-10 1.280 ms 1.271 ms -0.7%
ping-pong/ping-pong-1 802.8 μs 791.5 μs -1.4%
ping-pong/ping-pong-2 801.2 μs 791.9 μs -1.2%
ping-pong/ping-pong_2-1 492.7 μs 487.2 μs -1.1%
prism/prism-1 473.6 μs 471.2 μs -0.5%
prism/prism-2 1.080 ms 1.073 ms -0.6%
prism/prism-3 982.8 μs 980.3 μs -0.3%
pubkey/pubkey-1 413.9 μs 413.2 μs -0.2%
stablecoin/stablecoin_1-1 2.103 ms 2.095 ms -0.4%
stablecoin/stablecoin_1-2 600.9 μs 595.0 μs -1.0%
stablecoin/stablecoin_1-3 2.378 ms 2.362 ms -0.7%
stablecoin/stablecoin_1-4 652.4 μs 646.7 μs -0.9%
stablecoin/stablecoin_1-5 3.011 ms 2.987 ms -0.8%
stablecoin/stablecoin_1-6 838.1 μs 830.4 μs -0.9%
stablecoin/stablecoin_2-1 2.106 ms 2.086 ms -0.9%
stablecoin/stablecoin_2-2 601.0 μs 594.4 μs -1.1%
stablecoin/stablecoin_2-3 2.377 ms 2.359 ms -0.8%
stablecoin/stablecoin_2-4 650.0 μs 645.1 μs -0.8%
token-account/token-account-1 555.1 μs 551.2 μs -0.7%
token-account/token-account-2 664.5 μs 658.9 μs -0.8%
token-account/token-account-3 902.2 μs 893.9 μs -0.9%
uniswap/uniswap-1 646.9 μs 640.5 μs -1.0%
uniswap/uniswap-2 1.107 ms 1.096 ms -1.0%
uniswap/uniswap-3 713.1 μs 710.5 μs -0.4%
uniswap/uniswap-4 827.8 μs 819.2 μs -1.0%
uniswap/uniswap-5 3.845 ms 3.790 ms -1.4%
uniswap/uniswap-6 1.107 ms 1.110 ms +0.3%
uniswap/uniswap-7 2.783 ms 2.769 ms -0.5%
uniswap/uniswap-8 1.048 ms 1.051 ms +0.3%
vesting/vesting-1 889.4 μs 886.2 μs -0.4%
marlowe/trustfund/trustfund-1 2.078 ms 2.049 ms -1.4%
marlowe/trustfund/trustfund-2 1.519 ms 1.506 ms -0.9%
marlowe/zerocoupon/zerocoupon-1 2.175 ms 2.152 ms -1.1%
marlowe/zerocoupon/zerocoupon-2 1.325 ms 1.312 ms -1.0%

@iohk-devops
Copy link

iohk-devops commented Jul 19, 2021

Comparing benchmark results of '9437522ba24e8168caa1e6e03f4b45a682f49a10' (base) and '9437522ba24e8168caa1e6e03f4b45a682f49a10' (PR)

Script 9437522 9437522 Change
crowdfunding/crowdfunding-success-1 646.6 μs 644.0 μs -0.4%
crowdfunding/crowdfunding-success-2 646.9 μs 644.0 μs -0.4%
crowdfunding/crowdfunding-success-3 646.6 μs 644.0 μs -0.4%
currency/currency-1 581.9 μs 577.9 μs -0.7%
currency/currency-2 808.8 μs 797.1 μs -1.4%
escrow/escrow-redeem_1-1 952.2 μs 945.2 μs -0.7%
escrow/escrow-redeem_1-2 952.5 μs 944.5 μs -0.8%
escrow/escrow-redeem_2-1 1.086 ms 1.078 ms -0.7%
escrow/escrow-redeem_2-2 1.089 ms 1.079 ms -0.9%
escrow/escrow-redeem_2-3 1.087 ms 1.079 ms -0.7%
escrow/escrow-refund-1 447.1 μs 443.3 μs -0.8%
future/future-increase-margin-1 586.8 μs 580.9 μs -1.0%
future/future-increase-margin-2 805.8 μs 800.0 μs -0.7%
future/future-increase-margin-3 1.371 ms 1.359 ms -0.9%
future/future-increase-margin-4 1.371 ms 1.361 ms -0.7%
future/future-increase-margin-5 1.414 ms 1.404 ms -0.7%
future/future-increase-margin-6 1.846 ms 1.831 ms -0.8%
future/future-pay-out-1 582.8 μs 579.9 μs -0.5%
future/future-pay-out-2 805.0 μs 800.2 μs -0.6%
future/future-pay-out-3 1.367 ms 1.359 ms -0.6%
future/future-pay-out-4 1.366 ms 1.358 ms -0.6%
future/future-pay-out-5 1.908 ms 1.890 ms -0.9%
future/future-settle-early-1 583.2 μs 579.3 μs -0.7%
future/future-settle-early-2 808.8 μs 797.6 μs -1.4%
future/future-settle-early-3 1.378 ms 1.357 ms -1.5%
future/future-settle-early-4 1.378 ms 1.358 ms -1.5%
future/future-settle-early-5 1.534 ms 1.523 ms -0.7%
game-sm/game-sm-success-1 1.013 ms 1.007 ms -0.6%
game-sm/game-sm-success-2 610.6 μs 602.6 μs -1.3%
game-sm/game-sm-success-3 1.463 ms 1.456 ms -0.5%
game-sm/game-sm-success-4 727.7 μs 721.7 μs -0.8%
game-sm/game-sm-success_2-1 1.011 ms 1.006 ms -0.5%
game-sm/game-sm-success_2-2 610.9 μs 603.1 μs -1.3%
game-sm/game-sm-success_2-3 1.464 ms 1.455 ms -0.6%
game-sm/game-sm-success_2-4 726.0 μs 719.8 μs -0.9%
game-sm/game-sm-success_2-5 1.458 ms 1.451 ms -0.5%
game-sm/game-sm-success_2-6 725.7 μs 719.1 μs -0.9%
multisig-sm/multisig-sm-01 1.057 ms 1.051 ms -0.6%
multisig-sm/multisig-sm-02 1.062 ms 1.055 ms -0.7%
multisig-sm/multisig-sm-03 1.080 ms 1.067 ms -1.2%
multisig-sm/multisig-sm-04 1.103 ms 1.080 ms -2.1%
multisig-sm/multisig-sm-05 1.293 ms 1.269 ms -1.9%
multisig-sm/multisig-sm-06 1.064 ms 1.048 ms -1.5%
multisig-sm/multisig-sm-07 1.065 ms 1.051 ms -1.3%
multisig-sm/multisig-sm-08 1.081 ms 1.065 ms -1.5%
multisig-sm/multisig-sm-09 1.098 ms 1.089 ms -0.8%
multisig-sm/multisig-sm-10 1.284 ms 1.276 ms -0.6%
ping-pong/ping-pong-1 802.8 μs 794.6 μs -1.0%
ping-pong/ping-pong-2 803.6 μs 794.6 μs -1.1%
ping-pong/ping-pong_2-1 493.8 μs 490.2 μs -0.7%
prism/prism-1 475.0 μs 473.9 μs -0.2%
prism/prism-2 1.081 ms 1.075 ms -0.6%
prism/prism-3 983.3 μs 977.7 μs -0.6%
pubkey/pubkey-1 414.1 μs 412.6 μs -0.4%
stablecoin/stablecoin_1-1 2.091 ms 2.087 ms -0.2%
stablecoin/stablecoin_1-2 597.1 μs 593.7 μs -0.6%
stablecoin/stablecoin_1-3 2.362 ms 2.354 ms -0.3%
stablecoin/stablecoin_1-4 650.1 μs 643.7 μs -1.0%
stablecoin/stablecoin_1-5 3.005 ms 2.974 ms -1.0%
stablecoin/stablecoin_1-6 835.9 μs 827.6 μs -1.0%
stablecoin/stablecoin_2-1 2.100 ms 2.081 ms -0.9%
stablecoin/stablecoin_2-2 600.1 μs 592.0 μs -1.3%
stablecoin/stablecoin_2-3 2.380 ms 2.351 ms -1.2%
stablecoin/stablecoin_2-4 651.7 μs 643.9 μs -1.2%
token-account/token-account-1 555.7 μs 551.7 μs -0.7%
token-account/token-account-2 665.0 μs 660.7 μs -0.6%
token-account/token-account-3 901.9 μs 899.1 μs -0.3%
uniswap/uniswap-1 648.2 μs 645.2 μs -0.5%
uniswap/uniswap-2 1.105 ms 1.104 ms -0.1%
uniswap/uniswap-3 714.8 μs 715.5 μs +0.1%
uniswap/uniswap-4 828.6 μs 824.8 μs -0.5%
uniswap/uniswap-5 3.850 ms 3.814 ms -0.9%
uniswap/uniswap-6 1.109 ms 1.109 ms 0.0%
uniswap/uniswap-7 2.782 ms 2.764 ms -0.6%
uniswap/uniswap-8 1.049 ms 1.049 ms 0.0%
vesting/vesting-1 889.6 μs 884.7 μs -0.6%
marlowe/trustfund/trustfund-1 2.062 ms 2.046 ms -0.8%
marlowe/trustfund/trustfund-2 1.509 ms 1.500 ms -0.6%
marlowe/zerocoupon/zerocoupon-1 2.156 ms 2.143 ms -0.6%
marlowe/zerocoupon/zerocoupon-2 1.321 ms 1.307 ms -1.1%

@thealmarty thealmarty force-pushed the thealmarty/scp-2364-add-trace-time branch 3 times, most recently from 1d67a86 to ba4dc62 Compare July 23, 2021 15:50
@thealmarty thealmarty force-pushed the thealmarty/scp-2364-add-trace-time branch from a4fdf21 to cfca891 Compare July 23, 2021 18:15
@michaelpj
Copy link
Contributor

michaelpj commented Jul 26, 2021

This looks plausible to me!

@michaelpj
Copy link
Contributor

michaelpj commented Jul 26, 2021

I think the remaining bit to do would be to enhance the argument that we pass to runCek (https://github.com/input-output-hk/plutus/blob/master/plutus-core/untyped-plutus-core/src/UntypedPlutusCore/Evaluation/Machine/Cek/Internal.hs#L775) to something more expressive than a bool, so that we can express NoEmit | Emit | EmitWithTimestamp.

@thealmarty thealmarty force-pushed the thealmarty/scp-2364-add-trace-time branch 2 times, most recently from eeaa326 to f712d98 Compare July 26, 2021 14:56
@thealmarty
Copy link
Contributor Author

thealmarty commented Jul 26, 2021

/benchmark

@iohk-devops
Copy link

iohk-devops commented Jul 26, 2021

Comparing benchmark results of 'e0b0fdd13e6316c3aa0c9b645647b4efc407d716' (base) and 'e0b0fdd13e6316c3aa0c9b645647b4efc407d716' (PR)

Script e0b0fdd e0b0fdd Change
crowdfunding/crowdfunding-success-1 648.5 μs 647.1 μs -0.2%
crowdfunding/crowdfunding-success-2 646.7 μs 646.6 μs -0.0%
crowdfunding/crowdfunding-success-3 647.4 μs 647.2 μs -0.0%
currency/currency-1 583.0 μs 584.2 μs +0.2%
currency/currency-2 809.6 μs 798.9 μs -1.3%
escrow/escrow-redeem_1-1 954.4 μs 942.6 μs -1.2%
escrow/escrow-redeem_1-2 954.8 μs 942.5 μs -1.3%
escrow/escrow-redeem_2-1 1.089 ms 1.079 ms -0.9%
escrow/escrow-redeem_2-2 1.088 ms 1.080 ms -0.7%
escrow/escrow-redeem_2-3 1.088 ms 1.081 ms -0.6%
escrow/escrow-refund-1 447.8 μs 447.4 μs -0.1%
future/future-increase-margin-1 585.0 μs 583.9 μs -0.2%
future/future-increase-margin-2 806.7 μs 801.1 μs -0.7%
future/future-increase-margin-3 1.373 ms 1.365 ms -0.6%
future/future-increase-margin-4 1.372 ms 1.365 ms -0.5%
future/future-increase-margin-5 1.411 ms 1.411 ms 0.0%
future/future-increase-margin-6 1.848 ms 1.841 ms -0.4%
future/future-pay-out-1 584.1 μs 585.2 μs +0.2%
future/future-pay-out-2 803.6 μs 801.4 μs -0.3%
future/future-pay-out-3 1.369 ms 1.366 ms -0.2%
future/future-pay-out-4 1.374 ms 1.363 ms -0.8%
future/future-pay-out-5 1.921 ms 1.894 ms -1.4%
future/future-settle-early-1 586.2 μs 584.3 μs -0.3%
future/future-settle-early-2 809.5 μs 799.7 μs -1.2%
future/future-settle-early-3 1.379 ms 1.362 ms -1.2%
future/future-settle-early-4 1.377 ms 1.363 ms -1.0%
future/future-settle-early-5 1.536 ms 1.528 ms -0.5%
game-sm/game-sm-success-1 1.015 ms 1.014 ms -0.1%
game-sm/game-sm-success-2 608.9 μs 611.7 μs +0.5%
game-sm/game-sm-success-3 1.460 ms 1.462 ms +0.1%
game-sm/game-sm-success-4 727.6 μs 729.2 μs +0.2%
game-sm/game-sm-success_2-1 1.008 ms 1.011 ms +0.3%
game-sm/game-sm-success_2-2 609.5 μs 611.4 μs +0.3%
game-sm/game-sm-success_2-3 1.462 ms 1.463 ms +0.1%
game-sm/game-sm-success_2-4 726.2 μs 728.3 μs +0.3%
game-sm/game-sm-success_2-5 1.457 ms 1.457 ms 0.0%
game-sm/game-sm-success_2-6 725.4 μs 728.1 μs +0.4%
multisig-sm/multisig-sm-01 1.064 ms 1.055 ms -0.8%
multisig-sm/multisig-sm-02 1.069 ms 1.060 ms -0.8%
multisig-sm/multisig-sm-03 1.083 ms 1.073 ms -0.9%
multisig-sm/multisig-sm-04 1.097 ms 1.087 ms -0.9%
multisig-sm/multisig-sm-05 1.292 ms 1.274 ms -1.4%
multisig-sm/multisig-sm-06 1.065 ms 1.053 ms -1.1%
multisig-sm/multisig-sm-07 1.066 ms 1.058 ms -0.8%
multisig-sm/multisig-sm-08 1.080 ms 1.079 ms -0.1%
multisig-sm/multisig-sm-09 1.096 ms 1.093 ms -0.3%
multisig-sm/multisig-sm-10 1.282 ms 1.279 ms -0.2%
ping-pong/ping-pong-1 802.1 μs 801.6 μs -0.1%
ping-pong/ping-pong-2 804.2 μs 801.3 μs -0.4%
ping-pong/ping-pong_2-1 493.6 μs 493.9 μs +0.1%
prism/prism-1 474.2 μs 477.9 μs +0.8%
prism/prism-2 1.083 ms 1.083 ms 0.0%
prism/prism-3 983.5 μs 980.9 μs -0.3%
pubkey/pubkey-1 414.1 μs 415.9 μs +0.4%
stablecoin/stablecoin_1-1 2.100 ms 2.097 ms -0.1%
stablecoin/stablecoin_1-2 602.2 μs 599.2 μs -0.5%
stablecoin/stablecoin_1-3 2.385 ms 2.365 ms -0.8%
stablecoin/stablecoin_1-4 651.8 μs 650.8 μs -0.2%
stablecoin/stablecoin_1-5 3.021 ms 2.979 ms -1.4%
stablecoin/stablecoin_1-6 838.4 μs 832.7 μs -0.7%
stablecoin/stablecoin_2-1 2.111 ms 2.089 ms -1.0%
stablecoin/stablecoin_2-2 602.3 μs 598.6 μs -0.6%
stablecoin/stablecoin_2-3 2.381 ms 2.377 ms -0.2%
stablecoin/stablecoin_2-4 650.5 μs 653.6 μs +0.5%
token-account/token-account-1 555.5 μs 557.6 μs +0.4%
token-account/token-account-2 664.3 μs 664.5 μs +0.0%
token-account/token-account-3 901.4 μs 902.1 μs +0.1%
uniswap/uniswap-1 648.6 μs 651.6 μs +0.5%
uniswap/uniswap-2 1.104 ms 1.105 ms +0.1%
uniswap/uniswap-3 714.5 μs 719.2 μs +0.7%
uniswap/uniswap-4 828.2 μs 828.5 μs +0.0%
uniswap/uniswap-5 3.846 ms 3.848 ms +0.1%
uniswap/uniswap-6 1.110 ms 1.112 ms +0.2%
uniswap/uniswap-7 2.785 ms 2.781 ms -0.1%
uniswap/uniswap-8 1.048 ms 1.049 ms +0.1%
vesting/vesting-1 889.4 μs 888.1 μs -0.1%
marlowe/trustfund/trustfund-1 2.076 ms 2.061 ms -0.7%
marlowe/trustfund/trustfund-2 1.520 ms 1.507 ms -0.9%
marlowe/zerocoupon/zerocoupon-1 2.180 ms 2.158 ms -1.0%
marlowe/zerocoupon/zerocoupon-2 1.325 ms 1.313 ms -0.9%

@thealmarty thealmarty mentioned this pull request Jul 26, 2021
Merged
11 tasks
@thealmarty thealmarty force-pushed the thealmarty/scp-2364-add-trace-time branch 3 times, most recently from 5930df3 to b34d3a2 Compare July 27, 2021 16:34
@thealmarty thealmarty force-pushed the thealmarty/scp-2364-add-trace-time branch from bc696a0 to 1a24b41 Compare July 28, 2021 14:32
@thealmarty thealmarty mentioned this pull request Jul 28, 2021
Merged
11 tasks
@thealmarty thealmarty deleted the thealmarty/scp-2364-add-trace-time branch August 18, 2021 14:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

Do not merge Don't look here yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@thealmarty @iohk-devops @michaelpj