Yes, I think that should work as long as there are no other concurrent messages that could run during the await.
Perhaps we could improve this behaviour. Would need to think about it.
3 Likes
@luc-blaeser do these counters still behave the same for the incremental gc? I think so, but want to check
1 Like
To be clear, you probably only want to count the collector instructions, the mutator instructions are user code
Yes, Prim.rts_mutator_instructions() and Prim.rts_collector_instructions() have the same semantics for the incremental GC. rts_collector_instructions() returns the number of instructions of the last GC increment. A detail aspect is that the costs of write barriers and load barriers are added to the mutator instructions. This is the case for the incremental GC and for the generational GC (the latter only entails write barriers).
Referring to the example above, it would make sense to also count the Prim.rts_collector_instructions() inside the noop() function, since most probably the GC is also running when the await expression is reached and before noop() is executed (as a result, the function noop() sees the costs of this previous GC run). With the incremental GC, there could be multiple consecutive GC increments for a larger heap, one at the await (the most probable for all GCs), one at the end of the noop(), one at the end of the public function etc…
2 Likes
So he should do this then?
public func gcIns() : async Nat {
doSomeWork(); // add/remove heap data
await async { Prim.rts_collector_instructions() }; // gc cost for doSomeWork()
};
1 Like
How to Define or Count unlimted better?
Thank you very much!
I’m not sure I follow, @abc
1 Like
Does rts_collector_instructions reset after each await or does it just increase?
Is this example correct?
var ins = Nat64.toNat(ExperimentalInternetComputer.countInstructions(func() {
doSomeWork();
}));
ins += await async {
Prim.rts_collector_instructions();
};
ins += Prim.rts_collector_instructions();
1 Like
Yes, rts_collector_instructions() resets after each message end.
Therefore, it is good to sum the collector instructions in each continuation of the async function as it is done in your example.
There are two aspects to be considered:
- An additional GC increment may run at the function end. Those costs are currently not yet captured in this example.
- This assumes that no other message/async function runs in between at the await point. Otherwise, this other function would see the previous GC costs.
2 Likes
Would await* async* help keep other messages from jumping in front?
Would await* async* help keep other messages from jumping in front?
No, unfortunately, the code would just run synchronously and you would not count the last GC.
I think if we really wanted to collect these stats properly we would need to do a bit more book-keeping in the generated code, and (perhaps) selectively return the stats as additional fields of every response (or using a log message, once supported).
I found that it doesn’t reset after every async call:
doSomeWork();
Debug.print("-----------------------------------");
await async {};
Debug.print("1");
Debug.print(debug_show(Prim.rts_collector_instructions()));
await (func() : async() {
Debug.print(debug_show(Prim.rts_collector_instructions()));
})();
Debug.print("2");
Debug.print(debug_show(Prim.rts_collector_instructions()));
await (func() : async() {
await async {};
Debug.print(debug_show(Prim.rts_collector_instructions()));
})();
Debug.print("3");
Debug.print(debug_show(Prim.rts_collector_instructions()));
await noop();
Debug.print(debug_show(Prim.rts_collector_instructions()));
Debug.print("4");
Debug.print(debug_show(Prim.rts_collector_instructions()));
await noop2();
Debug.print(debug_show(Prim.rts_collector_instructions()));
output
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] -----------------------------------
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 1
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_903
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_903
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 2
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_903
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 41_869
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 3
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_903
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_903
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 4
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_903
2023-12-15 08:20:13.606126639 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 37_876
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] -----------------------------------
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 1
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_318
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_318
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 2
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_318
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 485_284
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 3
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_318
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_318
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 4
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_318
2023-12-15 08:20:15.555419004 UTC: [Canister bkyz2-fmaaa-aaaaa-qaaaq-cai] 481_291
moc 0.10.2 with --force-gc --copying-gc
dfx 0.15.2
Thank you very much @ZenVoich for analyzing this. The results look indeed strange, but I believe there is the following phenomenon:
The GC is running with exactly the same number of instructions (due to the very deterministic setup here). To be sure (it is always good to test/verify the implementation, therefore thanks again for reporting this), I double checked it by instrumenting the compiler/runtime system to log the update of the variable behind rts_collector_instructions() and got this trace:
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] -----------------------------------
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 3048
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17626
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17626
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 1
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665 <-- GC ran with exactly the same number of instructions
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 2
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 22932
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 22932
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 22932
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 22_932
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 22932
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 3
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 4
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17665
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17620
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17620
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 17620
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 17_620
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 17620
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 12356
This log shows that the GC is indeed repeatedly running with exactly the same number of instructions, which is possible because no intermediate live objects have been allocated and --force-gc option schedules the GC in a continuous interval.
I tried to create some live (non-garbage) objects to obtain more variations in the GC instructions counters in this example:
Debug.print("1");
var x = Array.init<Nat>(1_000_000, 0);
Debug.print(debug_show(Prim.rts_collector_instructions()));
await (func() : async() {
x := Array.init<Nat>(1_000, 0);
Debug.print(debug_show(Prim.rts_collector_instructions()));
})();
Debug.print("length " # debug_show(x.size())); // necessary to retain array during previous GC runs.
With this change, I get the following different GC instruction results:
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 1
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 18_087
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 18087
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 34519036
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] 34_519_036
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] COPYING GC
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] OLD GC INSTRUCTIONS 34519036
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] RESET TO NEW GC INSTRUCTIONS 53505
[Canister rwlgt-iiaaa-aaaaa-aaaaa-cai] length 1_000