chore(prot): instrument timing to benchmark block internals [AC-1106]
Closes AC-1106. Initially looking at using the go benchmark tools, but given the nature of how the executor operates, it made more sense to add some internal timing hooks to provide the information we need in a useful format. The stress test benchmark sim will be expanded as part of AC-1107
For this task:
- instrumented finer resolution for timing internal components of the block executor
- created tabular timing log output for easy consumption by other tools for analysis
- added flags to enable the collection of timing logs from either config file or runtime node execution
Example timing log outputs. BVN0_accumulator_20220618_1611.dat
# height time_since_app_start block_time commit_time event_time ave_block_time est_tps txct
3 2.311468 0.018002 0.006730 0.000004 0.0180022160 55.5487168913 1
5 4.477125 0.022581 0.011387 0.000013 0.0225809730 44.2850713297 1
7 144.101503 0.017843 0.006233 0.000003 0.0178425880 56.0456812655 1
9 146.222059 0.018300 0.006753 0.000009 0.0091500335 109.2892173564 2
10 147.281158 0.017717 0.006676 0.000004 0.0029528402 338.6570025999 6
11 148.341193 0.019032 0.006835 0.000002 0.0023789965 420.3453010545 8
12 149.397899 0.022992 0.007779 0.000002 0.0017686455 565.4044172525 13
13 150.456751 0.024695 0.007676 0.000003 0.0017639529 566.9085516981 14
14 151.516255 0.026576 0.006598 0.000002 0.0017717623 564.4097863389 15
15 152.575345 0.024565 0.007299 0.000006 0.0018896221 529.2063488316 13
16 153.637444 0.027067 0.007970 0.000002 0.0018044992 554.1703759137 15
17 154.736503 0.063054 0.010928 0.000003 0.0045038464 222.0324408745 14
18 155.758831 0.027641 0.008496 0.000003 0.0019743919 506.4850710269 14
19 156.846696 0.051957 0.011326 0.000003 0.0034637983 288.7004158479 15
20 157.880556 0.025990 0.007221 0.000002 0.0019992188 500.1953840123 13
21 158.936813 0.027883 0.008165 0.000002 0.0019916436 502.0978725037 14
22 159.997949 0.028852 0.006912 0.000002 0.0020608794 485.2297620111 14
23 161.053054 0.025759 0.007059 0.000001 0.0019814793 504.6734508495 13
24 162.155475 0.064864 0.012059 0.000010 0.0054053042 185.0034621085 12
25 163.191630 0.038783 0.007867 0.000004 0.0055404640 180.4902982855 7
26 164.214576 0.018676 0.005953 0.000004 0.0037352188 267.7219337191 5
27 165.283179 0.022487 0.007269 0.000002 0.0224868440 44.4704468088 1
28 166.332292 0.013156 0.006384 0.000001 0.0131555740 76.0134069407 1
29 167.391753 0.014422 0.006563 0.000003 0.0144216330 69.3402751270 1
30 168.453569 0.014048 0.006613 0.000003 0.0140480100 71.1844595783 1
BVN0_executor_20220618_1611.dat
# height time_since_app_start syntheticWriteData_call_count syntheticWriteData_elapsed acmeFaucet_call_count acmeFaucet_elapsed addCredits_call_count addCredits_elapsed burnTokens_call_count burnTokens_elapsed syntheticCreateIdentity_call_count syntheticCreateIdentity_elapsed sendTokens_call_count sendTokens_elapsed writeDataTo_call_count writeDataTo_elapsed updateAccountAuth_call_count updateAccountAuth_elapsed syntheticDepositCredits_call_count syntheticDepositCredits_elapsed syntheticForwardTransaction_call_count syntheticForwardTransaction_elapsed createKeyBook_call_count createKeyBook_elapsed createToken_call_count createToken_elapsed createTokenAccount_call_count createTokenAccount_elapsed directoryAnchor_call_count directoryAnchor_elapsed syntheticDepositTokens_call_count syntheticDepositTokens_elapsed createKeyPage_call_count createKeyPage_elapsed updateKeyPage_call_count updateKeyPage_elapsed writeData_call_count writeData_elapsed updateKey_call_count updateKey_elapsed syntheticBurnTokens_call_count syntheticBurnTokens_elapsed createDataAccount_call_count createDataAccount_elapsed createIdentity_call_count createIdentity_elapsed issueTokens_call_count issueTokens_elapsed processSignature_call_count processSignature_elapsed beginBlock_call_count beginBlock_elapsed checkTx_call_count checkTx_elapsed deliverTx_call_count deliverTx_elapsed endBlock_call_count endBlock_elapsed commit_call_count commit_elapsed signing_call_count signing_elapsed networkAccountUpdates_call_count networkAccountUpdates_elapsed processRemoteSignatures_call_count processRemoteSignatures_elapsed processTransaction_call_count processTransaction_elapsed
3 2.311468 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0001555720 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 2 0.0003728500 1 0.0005052190 0 0.0000000000 0 0.0000000000 1 0.0015644480 0 0.0000000000 0 0.0000000000 2 0.0000002900 0 0.0000000000 1 0.0011976590
5 4.477125 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0000935660 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 2 0.0004725680 1 0.0004359090 0 0.0000000000 0 0.0000000000 1 0.0003651350 0 0.0000000000 0 0.0000000000 2 0.0000001500 0 0.0000000000 1 0.0005754800
7 144.101503 0 0.0000000000 1 0.0004054410 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0008751640 1 0.0003190800 0 0.0000000000 0 0.0000000000 1 0.0003708260 0 0.0000000000 0 0.0000000000 2 0.0000019030 0 0.0000000000 1 0.0005580490
9 146.222059 0 0.0000000000 1 0.0004166420 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 4 0.0011966580 1 0.0004966730 0 0.0000000000 0 0.0000000000 1 0.0008871570 0 0.0000000000 0 0.0000000000 3 0.0000048590 0 0.0000000000 2 0.0008437150
10 147.281158 0 0.0000000000 5 0.0000905300 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0001134630 1 0.0001347230 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 8 0.0001895870 1 0.0016913370 0 0.0000000000 0 0.0000000000 1 0.0010693480 0 0.0000000000 0 0.0000000000 14 0.0000011830 0 0.0000000000 7 0.0001697790
11 148.341193 0 0.0000000000 7 0.0001254050 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 10 0.0003141600 1 0.0010558330 0 0.0000000000 0 0.0000000000 1 0.0009233240 0 0.0000000000 0 0.0000000000 15 0.0000013730 0 0.0000000000 8 0.0002252740
12 149.397899 0 0.0000000000 7 0.0000899790 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0001259260 1 0.0001181720 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 25 0.0001936340 1 0.0023842190 0 0.0000000000 0 0.0000000000 1 0.0012977480 0 0.0000000000 0 0.0000000000 23 0.0000011120 0 0.0000000000 14 0.0001725850
13 150.456751 0 0.0000000000 6 0.0000949180 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0001783860 5 0.0000654630 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 34 0.0002136120 1 0.0022968250 0 0.0000000000 0 0.0000000000 1 0.0013510580 0 0.0000000000 0 0.0000000000 31 0.0000012620 0 0.0000000000 19 0.0001875130
14 151.516255 0 0.0000000000 7 0.0001080130 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002948440 7 0.0000663850 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 37 0.0002582250 1 0.0012867270 0 0.0000000000 0 0.0000000000 1 0.0018562970 0 0.0000000000 0 0.0000000000 37 0.0000015230 0 0.0000000000 22 0.0002165770
15 152.575345 0 0.0000000000 6 0.0000841880 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002562510 7 0.0000624570 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 33 0.0001993650 1 0.0026504990 0 0.0000000000 0 0.0000000000 1 0.0015441810 0 0.0000000000 0 0.0000000000 34 0.0000012530 0 0.0000000000 20 0.0001662820
16 153.637444 0 0.0000000000 7 0.0000989560 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002378270 6 0.0000803110 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 36 0.0001984130 1 0.0011440790 0 0.0000000000 0 0.0000000000 1 0.0020044350 0 0.0000000000 0 0.0000000000 35 0.0000013620 0 0.0000000000 21 0.0001849880
17 154.736503 0 0.0000000000 7 0.0004352180 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0004022150 7 0.0003049520 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 34 0.0008715070 1 0.0017132990 0 0.0000000000 0 0.0000000000 1 0.0049589560 0 0.0000000000 0 0.0000000000 36 0.0000077550 0 0.0000000000 21 0.0010850980
18 155.758831 0 0.0000000000 6 0.0001123310 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002539970 6 0.0000746500 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 35 0.0002248120 1 0.0019804310 0 0.0000000000 0 0.0000000000 1 0.0017733910 0 0.0000000000 0 0.0000000000 33 0.0000011720 0 0.0000000000 20 0.0002256640
19 156.846696 0 0.0000000000 7 0.0001253960 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0011927700 7 0.0004462380 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 37 0.0002664410 1 0.0023783890 0 0.0000000000 0 0.0000000000 1 0.0031113950 0 0.0000000000 0 0.0000000000 37 0.0000013920 0 0.0000000000 22 0.0002566320
20 157.880556 0 0.0000000000 6 0.0000987360 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002783130 7 0.0000753920 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 33 0.0002281090 1 0.0022094410 0 0.0000000000 0 0.0000000000 1 0.0019869930 0 0.0000000000 0 0.0000000000 34 0.0000011020 0 0.0000000000 20 0.0001855290
21 158.936813 0 0.0000000000 6 0.0001069110 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002635850 6 0.0000738480 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 35 0.0002143530 1 0.0016265060 0 0.0000000000 0 0.0000000000 1 0.0025801870 0 0.0000000000 0 0.0000000000 33 0.0000011920 0 0.0000000000 20 0.0002023500
22 159.997949 0 0.0000000000 7 0.0001253750 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0009636300 7 0.0000708330 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 34 0.0002125890 1 0.0011579650 0 0.0000000000 0 0.0000000000 1 0.0019590400 0 0.0000000000 0 0.0000000000 36 0.0000011920 0 0.0000000000 21 0.0002138020
23 161.053054 0 0.0000000000 6 0.0000928350 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002566720 6 0.0000700410 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 32 0.0002010580 1 0.0022748730 0 0.0000000000 0 0.0000000000 1 0.0019825650 0 0.0000000000 0 0.0000000000 32 0.0000012620 0 0.0000000000 19 0.0001784350
24 162.155475 0 0.0000000000 4 0.0003222750 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0009248170 6 0.0002466230 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 33 0.0008702150 1 0.0039117790 0 0.0000000000 0 0.0000000000 1 0.0071054880 0 0.0000000000 0 0.0000000000 29 0.0000041670 0 0.0000000000 18 0.0006506930
25 163.191630 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0009564970 7 0.0002702980 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 27 0.0003271350 1 0.0032510170 0 0.0000000000 0 0.0000000000 1 0.0014912310 0 0.0000000000 0 0.0000000000 22 0.0000002200 0 0.0000000000 14 0.0004838790
26 164.214576 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0003038710 6 0.0001010400 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 20 0.0000919030 1 0.0007108650 0 0.0000000000 0 0.0000000000 1 0.0004606660 0 0.0000000000 0 0.0000000000 18 0.0000000600 0 0.0000000000 11 0.0001738870
27 165.283179 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0005993260 4 0.0002483460 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 6 0.0002314050 1 0.0016289200 0 0.0000000000 0 0.0000000000 1 0.0016990320 0 0.0000000000 0 0.0000000000 10 0.0000002000 0 0.0000000000 5 0.0008553160
28 166.332292 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0000720160 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 2 0.0001503520 1 0.0008694440 0 0.0000000000 0 0.0000000000 1 0.0003993900 0 0.0000000000 0 0.0000000000 2 0.0000001600 0 0.0000000000 1 0.0004179250
29 167.391753 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0002129200 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 2 0.0003492670 1 0.0004978350 0 0.0000000000 0 0.0000000000 1 0.0004125850 0 0.0000000000 0 0.0000000000 2 0.0000001200 0 0.0000000000 1 0.0011095440
30 168.453569 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 1 0.0000933150 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 0 0.0000000000 2 0.0001548810 1 0.0011473460 0 0.0000000000 0 0.0000000000 1 0.0003985380 0 0.0000000000 0 0.0000000000 2 0.0000001500 0 0.0000000000 1 0.0005088860
Review Checklist
If any item is not complete, the merge request is not ready to be reviewed and must be marked Draft:
.
-
The merge request title is in the format <change type>(<change scope>): <short description> [<task id>]
- For example,
feat(cli): add QR code generation [AC-123]
- For details, see CONTRIBUTING.md
- For example,
-
The description includes Closes <jira task ID>
(or rarelyUpdates <jira task ID>
) -
The change is fully validated by tests that are run during CI - In most cases this means a test in "validate.sh"
- In some cases, a Go test may be acceptable
- Validation is not applicable to things like documentation updates
- Purely UI/UX changes can be manually validated, such as changes to human-readable output
- For all other changes, automated validation tests are an absolute requirement unless a maintainer specifically explains why they are not in a comment on this merge request
-
The change is marked with one of the validation labels - validationci/cd for changes validated by CI tests
- validationmanual for changes validated by hand
- validationdeferred for changes validated by a follow up merge request
- validationnot applicable for changes where validation is not applicable
Merge Checklist
-
CI is passing -
Merge conflicts are resolved -
All discussions are resolved
Related to AC-1106
Edited by Dennis B