# Introducing Performance Counter on The Internet Computer

**URL:** <https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027>\
**Category:** Developers\
**Created:** [June 24, 2022, 7:23pm UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027 "2022-06-24T19:23:09Z")\
**Posts on this page:** 13\
**Page:** 3

<div class="post-metadata">

**Author:** ![claudio](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/claudio/32/322_2.png) [@claudio](https://forum.dfinity.org/u/claudio)\
**Post date:** [December 11, 2023, 8:36am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/41 "2023-12-11T08:36:40Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![claudio](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/claudio/32/322_2.png) [@claudio](https://forum.dfinity.org/u/claudio)\
**Post date:** [December 11, 2023, 8:38am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/42 "2023-12-11T08:38:42Z")

</div>

@luc-blaeser do these counters still behave the same for the incremental gc? I think so, but want to check

---

<div class="post-metadata">

**Author:** ![claudio](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/claudio/32/322_2.png) [@claudio](https://forum.dfinity.org/u/claudio)\
**Post date:** [December 11, 2023, 8:40am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/43 "2023-12-11T08:40:51Z")

</div>

To be clear, you probably only want to count the collector instructions, the mutator instructions are user code

---

<div class="post-metadata">

**Author:** ![luc-blaeser](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/luc-blaeser/32/7410_2.png) [@luc-blaeser](https://forum.dfinity.org/u/luc-blaeser)\
**Post date:** [December 11, 2023, 9:45am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/44 "2023-12-11T09:45:16Z")

</div>

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…

---

<div class="post-metadata">

**Author:** ![timo](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/timo/32/5543_2.png) [@timo](https://forum.dfinity.org/u/timo)\
**Post date:** [December 11, 2023, 10:42am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/45 "2023-12-11T10:42:20Z")

</div>

> [@luc-blaeser](#):
>
> as a result, the function `noop()` sees the costs of this previous GC run

So he should do this then?

```auto
public func gcIns() : async Nat {
  doSomeWork(); // add/remove heap data
  await async { Prim.rts_collector_instructions() }; // gc cost for doSomeWork()
};

```

---

<div class="post-metadata">

**Author:** ![abc](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/abc/32/8845_2.png) [@abc](https://forum.dfinity.org/u/abc)\
**Post date:** [December 11, 2023, 11:47am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/46 "2023-12-11T11:47:14Z")

</div>

> <https://twitter.com/dstar_peter/status/1734168796535890127?s=20>

**How to Define or Count unlimted better?**  
**Thank you very much!**

---

<div class="post-metadata">

**Author:** ![berestovskyy](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/berestovskyy/32/3989_2.png) [@berestovskyy](https://forum.dfinity.org/u/berestovskyy)\
**Post date:** [December 11, 2023, 12:45pm UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/47 "2023-12-11T12:45:21Z")

</div>

I’m not sure I follow, @abc

---

<div class="post-metadata">

**Author:** ![ZenVoich](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/zenvoich/32/5969_2.png) [@ZenVoich](https://forum.dfinity.org/u/ZenVoich)\
**Post date:** [December 11, 2023, 1:00pm UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/48 "2023-12-11T13:00:57Z")

</div>

> [@luc-blaeser](#):
>
> 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)

Does `rts_collector_instructions` reset after each `await` or does it just increase?

Is this example correct?

```motoko
var ins = Nat64.toNat(ExperimentalInternetComputer.countInstructions(func() {
	doSomeWork();
}));
ins += await async {
	Prim.rts_collector_instructions();
};
ins += Prim.rts_collector_instructions();

```

---

<div class="post-metadata">

**Author:** ![luc-blaeser](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/luc-blaeser/32/7410_2.png) [@luc-blaeser](https://forum.dfinity.org/u/luc-blaeser)\
**Post date:** [December 11, 2023, 4:18pm UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/49 "2023-12-11T16:18:00Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![skilesare](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/skilesare/32/5609_2.png) [@skilesare](https://forum.dfinity.org/u/skilesare)\
**Post date:** [December 12, 2023, 3:51pm UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/50 "2023-12-12T15:51:27Z")

</div>

> [@ZenVoich](#):
>
> ```auto
> ins += await async {
> Prim.rts_collector_instructions();
> };
> 
> ```

Would await\* async\* help keep other messages from jumping in front?

---

<div class="post-metadata">

**Author:** ![claudio](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/claudio/32/322_2.png) [@claudio](https://forum.dfinity.org/u/claudio)\
**Post date:** [December 12, 2023, 4:40pm UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/51 "2023-12-12T16:40:45Z")

</div>

> 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).

---

<div class="post-metadata">

**Author:** ![ZenVoich](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/zenvoich/32/5969_2.png) [@ZenVoich](https://forum.dfinity.org/u/ZenVoich)\
**Post date:** [December 15, 2023, 8:27am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/52 "2023-12-15T08:27:22Z")

</div>

> [@luc-blaeser](#):
>
> Yes, `rts_collector_instructions()` resets after each message end.

I found that it doesn’t reset after every async call:

```motoko
		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

```raw
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

---

<div class="post-metadata">

**Author:** ![luc-blaeser](https://sea1.discourse-cdn.com/flex023/user_avatar/forum.dfinity.org/luc-blaeser/32/7410_2.png) [@luc-blaeser](https://forum.dfinity.org/u/luc-blaeser)\
**Post date:** [December 15, 2023, 9:43am UTC](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027/53 "2023-12-15T09:43:12Z")

</div>

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:

```auto
[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:

```auto
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:

```auto
[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

```

[Previous page](https://forum.dfinity.org/t/introducing-performance-counter-on-the-internet-computer/14027.md?page=2)