So that is what makes circular references not a problem because a circular reference isn’t possible with immutable data alone?
Does it make serializing records with mutable fields more expensive than immutable-only data? Because of the additional tracking involved.
I was able to grow the Buffer further by growing in smaller increments (1k items per call), so it really seems like the issue stemmed from the fact that GC became too expensive at some point to insert 20k elements within the same message.
I rewrote grow to this
public func grow(n : Nat) : Nat {
for (i in Iter.range(1, n)) {
_transactions.add({
token = "abc";
seller = Principal.fromText("aaaaa-aa");
price = 1000;
buyer = "abc";
time = Time.now();
});
};
_transactions.size();
};
This table is from a run were the initial Buffer size is 0 and the Buffer is serialised into stable memory using an array, and initialised from that array after the upgrade
┌─────────┬─────────────────┬──────────────┬───────────┬─────────────┬─────────────┬─────────────┬────────────────────┬──────────────────────┬──────────────────┬────────────────────┐
│ (index) │ gc │ transactions │ reinstall │ max live │ heap │ memory │ upgrade successful │ max live postupgrade │ heap postupgrade │ memory postupgrade │
├─────────┼─────────────────┼──────────────┼───────────┼─────────────┼─────────────┼─────────────┼────────────────────┼──────────────────────┼──────────────────┼────────────────────┤
│ 0 │ 'copying-force' │ '400,000' │ true │ '73.50 MB' │ '73.50 MB' │ '147.38 MB' │ true │ '83.18 MB' │ '83.18 MB' │ '241.00 MB' │
│ 1 │ 'copying-force' │ '800,000' │ true │ '147.27 MB' │ '147.27 MB' │ '294.94 MB' │ true │ '166.13 MB' │ '166.13 MB' │ '481.13 MB' │
└─────────┴─────────────────┴──────────────┴───────────┴─────────────┴─────────────┴─────────────┴────────────────────┴──────────────────────┴──────────────────┴────────────────────┘
Thanks to everyone who participated in this thread 
Can you show the code in your pre/post-upgrade functions? Just wondering why the heap size increased across the upgrade.
Is your original question answered? You wanted to know how large you can make the Buffer while it still survives the upgrade. Did you push it to the limit?
What does this tell me or how shall I use it? I suppose I have to make sure that my current heap size plus the value returned by this function stableVarQuery together fit in 4GB?
Can you show the code in your pre/post-upgrade functions? Just wondering why the heap size increased across the upgrade.
Is your original question answered? You wanted to know how large you can make the Buffer while it still survives the upgrade. Did you push it to the limit?
I was able to push it to the limit without the --force-gc flag:
┌─────────┬────────────────┬──────────────┬───────────┬──────────────┬──────────────┬──────────────┬────────────────────┬──────────────────────┬──────────────────┬────────────────────┐
│ (index) │ gc │ transactions │ reinstall │ max live │ heap │ memory │ upgrade successful │ max live postupgrade │ heap postupgrade │ memory postupgrade │
├─────────┼────────────────┼──────────────┼───────────┼──────────────┼──────────────┼──────────────┼────────────────────┼──────────────────────┼──────────────────┼────────────────────┤
│ 0 │ 'copying' │ '400,000' │ false │ '61.85 MB' │ '77.73 MB' │ '130.88 MB' │ true │ '83.17 MB' │ '83.23 MB' │ '241.00 MB' │
│ 1 │ 'copying' │ '800,000' │ false │ '154.06 MB' │ '156.80 MB' │ '325.19 MB' │ true │ '166.33 MB' │ '166.43 MB' │ '481.75 MB' │
│ 2 │ 'copying' │ '1,000,000' │ false │ '166.33 MB' │ '215.48 MB' │ '481.75 MB' │ true │ '207.91 MB' │ '208.02 MB' │ '602.13 MB' │
│ 3 │ 'copying' │ '1,400,000' │ false │ '207.91 MB' │ '306.11 MB' │ '602.13 MB' │ true │ '291.07 MB' │ '291.18 MB' │ '842.81 MB' │
│ 4 │ 'copying' │ '2,000,000' │ false │ '397.57 MB' │ '399.14 MB' │ '842.81 MB' │ true │ '415.82 MB' │ '415.92 MB' │ '1203.88 MB' │
│ 5 │ 'copying' │ '2,800,000' │ false │ '415.82 MB' │ '612.17 MB' │ '1203.88 MB' │ true │ '582.14 MB' │ '582.24 MB' │ '1685.31 MB' │
│ 6 │ 'copying' │ '3,400,000' │ false │ '582.14 MB' │ '729.55 MB' │ '1685.31 MB' │ true │ '706.88 MB' │ '706.98 MB' │ '2046.38 MB' │
│ 7 │ 'copying' │ '4,000,000' │ false │ '706.88 MB' │ '854.31 MB' │ '2046.38 MB' │ true │ '831.62 MB' │ '831.72 MB' │ '2407.44 MB' │
│ 8 │ 'copying' │ '5,000,000' │ false │ '831.62 MB' │ '1077.29 MB' │ '2407.44 MB' │ true │ '1039.52 MB' │ '1039.62 MB' │ '3009.19 MB' │
│ 9 │ 'compacting' │ '400,000' │ false │ '61.85 MB' │ '77.73 MB' │ '78.06 MB' │ true │ '83.17 MB' │ '83.23 MB' │ '162.81 MB' │
│ 10 │ 'compacting' │ '800,000' │ false │ '154.06 MB' │ '156.80 MB' │ '176.44 MB' │ true │ '166.33 MB' │ '166.41 MB' │ '325.25 MB' │
│ 11 │ 'compacting' │ '1,000,000' │ false │ '166.33 MB' │ '215.46 MB' │ '325.25 MB' │ true │ '207.91 MB' │ '207.99 MB' │ '406.50 MB' │
│ 12 │ 'compacting' │ '1,400,000' │ false │ '207.91 MB' │ '306.08 MB' │ '406.50 MB' │ true │ '291.07 MB' │ '291.18 MB' │ '569.00 MB' │
│ 13 │ 'compacting' │ '2,000,000' │ false │ '397.57 MB' │ '399.09 MB' │ '569.00 MB' │ true │ '415.82 MB' │ '415.92 MB' │ '812.69 MB' │
│ 14 │ 'compacting' │ '2,800,000' │ false │ '415.82 MB' │ '612.26 MB' │ '812.69 MB' │ true │ '582.14 MB' │ '582.24 MB' │ '1137.63 MB' │
│ 15 │ 'compacting' │ '3,400,000' │ false │ '582.14 MB' │ '729.50 MB' │ '1137.63 MB' │ true │ '706.88 MB' │ '706.98 MB' │ '1381.31 MB' │
│ 16 │ 'compacting' │ '4,000,000' │ false │ '706.88 MB' │ '854.29 MB' │ '1381.31 MB' │ true │ '831.62 MB' │ '831.72 MB' │ '1625.06 MB' │
│ 17 │ 'compacting' │ '5,000,000' │ false │ '831.62 MB' │ '1077.24 MB' │ '1625.06 MB' │ true │ '1039.52 MB' │ '1039.62 MB' │ '2031.19 MB' │
│ 18 │ 'generational' │ '400,000' │ false │ '72.75 MB' │ '79.12 MB' │ '79.44 MB' │ true │ '83.18 MB' │ '83.24 MB' │ '162.81 MB' │
│ 19 │ 'generational' │ '800,000' │ false │ '153.85 MB' │ '160.98 MB' │ '162.81 MB' │ true │ '166.34 MB' │ '166.45 MB' │ '325.25 MB' │
│ 20 │ 'generational' │ '1,000,000' │ false │ '197.54 MB' │ '204.91 MB' │ '325.25 MB' │ true │ '207.92 MB' │ '208.06 MB' │ '406.50 MB' │
│ 21 │ 'generational' │ '1,400,000' │ false │ '275.52 MB' │ '282.18 MB' │ '406.50 MB' │ true │ '291.08 MB' │ '291.24 MB' │ '569.00 MB' │
│ 22 │ 'generational' │ '2,000,000' │ false │ '394.90 MB' │ '400.55 MB' │ '569.00 MB' │ true │ '415.83 MB' │ '416.01 MB' │ '812.69 MB' │
│ 23 │ 'generational' │ '2,800,000' │ false │ '556.03 MB' │ '560.95 MB' │ '812.69 MB' │ true │ '582.15 MB' │ '582.33 MB' │ '1137.63 MB' │
│ 24 │ 'generational' │ '3,400,000' │ false │ '685.96 MB' │ '691.61 MB' │ '1137.63 MB' │ true │ '706.89 MB' │ '707.07 MB' │ '1381.31 MB' │
│ 25 │ 'generational' │ '4,000,000' │ false │ '810.52 MB' │ '816.94 MB' │ '1381.31 MB' │ true │ '831.63 MB' │ '831.81 MB' │ '1625.06 MB' │
│ 26 │ 'generational' │ '5,000,000' │ false │ '1008.23 MB' │ '1012.42 MB' │ '1625.06 MB' │ true │ '1039.53 MB' │ '1039.73 MB' │ '2031.19 MB' │
└─────────┴────────────────┴──────────────┴───────────┴──────────────┴──────────────┴──────────────┴────────────────────┴──────────────────────┴──────────────────┴────────────────────┘
Creating canister copying-force.
To speed things up, I ran 10 parallel calls of grow(1000). With the --force-gc flag, message execution took so long, that the messages in the queue timed out when the Buffer was already filled with a couple hundred thousand entries. The bigger the buffer, the longer it took for the messages to be executed. After upgrading the canister, the execution time grew significantly (130 instead of 30 seconds).
Creating canister copying-force...
copying-force canister created with canister id: rno2w-sqaaa-aaaaa-aaacq-cai
--------------------------------------------------
Reinstalling...
Reinstalled
Fabricating cycles...
Fabricated cycles
Growing transaction size to 400,000...
Growing transactions to 10000/400000
All commands executed successfully
Took 2.304730499267578 seconds to execute
Growing transactions to 20000/400000
All commands executed successfully
Took 2.301433624267578 seconds to execute
Growing transactions to 30000/400000
All commands executed successfully
Took 3.324260457992554 seconds to execute
Growing transactions to 40000/400000
All commands executed successfully
Took 4.344848001480103 seconds to execute
Growing transactions to 50000/400000
All commands executed successfully
Took 4.319609043121338 seconds to execute
Growing transactions to 60000/400000
All commands executed successfully
Took 5.3472237911224365 seconds to execute
Growing transactions to 70000/400000
All commands executed successfully
Took 6.4522719593048095 seconds to execute
Growing transactions to 80000/400000
All commands executed successfully
Took 6.912330875396728 seconds to execute
Growing transactions to 90000/400000
All commands executed successfully
Took 7.903315542221069 seconds to execute
Growing transactions to 100000/400000
All commands executed successfully
Took 8.698994625091553 seconds to execute
Growing transactions to 110000/400000
All commands executed successfully
Took 9.754751081466674 seconds to execute
Growing transactions to 120000/400000
All commands executed successfully
Took 9.749219499588012 seconds to execute
Growing transactions to 130000/400000
All commands executed successfully
Took 10.777633541107178 seconds to execute
Growing transactions to 140000/400000
All commands executed successfully
Took 11.79283745956421 seconds to execute
Growing transactions to 150000/400000
All commands executed successfully
Took 11.806708457946778 seconds to execute
Growing transactions to 160000/400000
All commands executed successfully
Took 12.830129793167114 seconds to execute
Growing transactions to 170000/400000
All commands executed successfully
Took 13.80576591682434 seconds to execute
Growing transactions to 180000/400000
All commands executed successfully
Took 13.832445833206176 seconds to execute
Growing transactions to 190000/400000
All commands executed successfully
Took 14.815648916244507 seconds to execute
Growing transactions to 200000/400000
All commands executed successfully
Took 15.839829708099366 seconds to execute
Growing transactions to 210000/400000
All commands executed successfully
Took 16.926885665893554 seconds to execute
Growing transactions to 220000/400000
All commands executed successfully
Took 16.886094667434694 seconds to execute
Growing transactions to 230000/400000
All commands executed successfully
Took 17.888822666168213 seconds to execute
Growing transactions to 240000/400000
All commands executed successfully
Took 18.95769966506958 seconds to execute
Growing transactions to 250000/400000
All commands executed successfully
Took 18.909073709487917 seconds to execute
Growing transactions to 260000/400000
All commands executed successfully
Took 18.9390909576416 seconds to execute
Growing transactions to 270000/400000
All commands executed successfully
Took 20.993517957687377 seconds to execute
Growing transactions to 280000/400000
All commands executed successfully
Took 22.009947999954225 seconds to execute
Growing transactions to 290000/400000
All commands executed successfully
Took 22.038469083786012 seconds to execute
Growing transactions to 300000/400000
All commands executed successfully
Took 21.959165000915526 seconds to execute
Growing transactions to 310000/400000
All commands executed successfully
Took 24.003851585388183 seconds to execute
Growing transactions to 320000/400000
All commands executed successfully
Took 24.038773332595824 seconds to execute
Growing transactions to 330000/400000
All commands executed successfully
Took 25.039592500686645 seconds to execute
Growing transactions to 340000/400000
All commands executed successfully
Took 25.01791833305359 seconds to execute
Growing transactions to 350000/400000
All commands executed successfully
Took 26.073978666305543 seconds to execute
Growing transactions to 360000/400000
All commands executed successfully
Took 27.148988082885744 seconds to execute
Growing transactions to 370000/400000
All commands executed successfully
Took 28.092508998870848 seconds to execute
Growing transactions to 380000/400000
All commands executed successfully
Took 28.07980354309082 seconds to execute
Growing transactions to 390000/400000
All commands executed successfully
Took 29.12529295730591 seconds to execute
Growing transactions to 400000/400000
All commands executed successfully
Took 30.15587545776367 seconds to execute
Took a total of 640.3228264160156 seconds to execute
Stopping...
Upgrading...
Starting...
┌─────────┬─────────────────┬──────────────┬───────────┬────────────┬────────────┬─────────────┬────────────────────┬──────────────────────┬──────────────────┬────────────────────┐
│ (index) │ gc │ transactions │ reinstall │ max live │ heap │ memory │ upgrade successful │ max live postupgrade │ heap postupgrade │ memory postupgrade │
├─────────┼─────────────────┼──────────────┼───────────┼────────────┼────────────┼─────────────┼────────────────────┼──────────────────────┼──────────────────┼────────────────────┤
│ 0 │ 'copying-force' │ '400,000' │ false │ '73.50 MB' │ '73.50 MB' │ '147.38 MB' │ true │ '83.18 MB' │ '83.18 MB' │ '241.00 MB' │
└─────────┴─────────────────┴──────────────┴───────────┴────────────┴────────────┴─────────────┴────────────────────┴──────────────────────┴──────────────────┴────────────────────┘
--------------------------------------------------
Growing transaction size to 800,000...
Growing transactions to 410000/800000
All commands executed successfully
Took 130.0328239593506 seconds to execute
Growing transactions to 420000/800000
All commands executed successfully
Took 136.77689070701598 seconds to execute
Growing transactions to 430000/800000
.
.
.
I have a couple of questions regarding that behaviour:
--force-gc flag, I don’t really see any iterations that stand out, it always seems to take ~2s for ten grow(1000) calls to execute without gc, with gc I see mesages that take up to 7s when the Buffer has more than 500k entries. Why aren’t those messages where the gc is run taking the same amount of time to execute as for messages with the --force-gc on, namely ~13s?If you want to try the test yourself, the code is in the test-upgrade branch.
You can modify the test logic in test-upgrade.js and find the grow implementation here.
Run npm run replica to start a clean local replica, and npm run test-upgrade to start the tests.
i thought DTS was enabled for 6 rounds, and a round is ~2s, how is it possible that a message takes longer than that?
DTS executes about 2B instructions per round. The message instruction limit is currently 20B instructions, so a message with DTS would run for 10 rounds.
Looking at your script, I’m not really sure you are measuring the time to gc rather than the elapsed time to go through the replica with an increasing number of concurrent calls.
There’s Motoko prims you can call rts_mutator_instructions and rts_collector_instructions that return the instruction counts for computation/gc of the previous message (use with care). That might give you more accurate measurements of what the motoko code, rather than the replica/OS etc are doing.
Since the heap size doesn’t seem to grow radically after upgrade, I’d expect the gc to not get drastically more expense, but maybe we have a bug or you are actually measuring something else, like the cost of contention on the replica. (The memory size doubling after upgrade is probably due to the fact that deserializaion first copied the stable variable serialized data into memory then deserializes it into memory, leading to doubling.)
The amount of concurrent calls stays the same (10) after the update. But true, I’m not measuring the time it takes to gc, I’m measuring the time it takes to execute all of the concurrent calls. Sometimes this includes gc, sometimes it doesn’t. Sometimes all messages fit within a block, sometimes a block only contains one message.
I still don’t understand those two observations 