perf: log more metrics

3 files changed, 93 insertions, 6 deletions

diff --git a/examples/php-on-wasm/php-wasm.php b/examples/php-on-wasm/php-wasm.php
index 54f6561..cf7e328 100644
--- a/examples/php-on-wasm/php-wasm.php
+++ b/examples/php-on-wasm/php-wasm.php
@@ -149,8 +149,8 @@ assert(is_int($exitCode));
 fprintf(STDERR, "Exit code: $exitCode\n");
 fprintf(STDERR, "Memory peak usage: %s\n", memory_get_peak_usage());
 fprintf(STDERR, "\n\n");
-foreach ($runtime->getInstrMetrics() as $instr => $count) {
-    fprintf(STDERR, "%s: %d\n", $instr, $count);
+foreach ($runtime->getInstrMetrics() as $instr => [$count, $time]) {
+    fprintf(STDERR, "%s: %d %d %f\n", $instr, $time, $count, $time / $count);
 }
 
 function allocateStringOnWasmMemory(Runtime $runtime, string $str): int {
diff --git a/src/Execution/Runtime.php b/src/Execution/Runtime.php
index 1efaacc..19d5771 100644
--- a/src/Execution/Runtime.php
+++ b/src/Execution/Runtime.php
@@ -24,7 +24,7 @@ use function is_int;
 final class Runtime
 {
     /**
-     * @var array<string, int>
+     * @var array<string, array{int, int}>
      */
     private array $instrMetrics = [];
 
@@ -157,7 +157,7 @@ final class Runtime
     }
 
     /**
-     * @return array<string, int>
+     * @return array<string, array{int, int}>
      */
     public function getInstrMetrics(): array
     {
@@ -538,8 +538,9 @@ final class Runtime
             default => throw new RuntimeException("invalid instruction"),
         };
 
-        // $this->instrMetrics[$instr::opName()] ??= 0;
-        // $this->instrMetrics[$instr::opName()] += hrtime(true) - $start;
+        // $this->instrMetrics[$instr::opName()] ??= [0, 0];
+        // $this->instrMetrics[$instr::opName()][0] += 1;
+        // $this->instrMetrics[$instr::opName()][1] += hrtime(true) - $start;
 
         return $result;
     }
diff --git a/traces/20240314-1121.stderr.log b/traces/20240314-1121.stderr.log
new file mode 100644
index 0000000..7a46fc3
--- /dev/null
+++ b/traces/20240314-1121.stderr.log
@@ -0,0 +1,86 @@
+Decoding...
+Instantiating...
+Executing...
+
+Exit code: 0
+Memory peak usage: 194459424
+
+
+i32.rem_u: 5921 1 5921.000000
+i64.rot_l: 7655 1 7655.000000
+f64.gt: 4849 2 2424.500000
+f64.mul: 6834 2 3417.000000
+i64.eq: 11604 2 5802.000000
+f64.load: 22213 2 11106.500000
+f64.add: 8266 4 2066.500000
+f64.convert_i32_s: 8557 4 2139.250000
+i64.extend_i32_s: 373957 16 23372.312500
+i64.sub: 428937 16 26808.562500
+i64.lt_u: 552495 17 32499.705882
+f64.store: 732577 24 30524.041667
+f64.const: 687123 26 26427.807692
+i32.wrap_i64: 422841 32 13213.781250
+i64.eqz: 659942 42 15712.904762
+i64.or: 449442 46 9770.478261
+i64.gt_u: 644191 46 14004.152174
+i64.shl: 516989 47 10999.765957
+i32.le_s: 743679 49 15177.122449
+i64.xor: 491630 62 7929.516129
+i64.ne: 653306 70 9332.942857
+i32.extend8_s: 582414 78 7466.846154
+i32.load16_s: 908372 81 11214.469136
+memory.size: 759867 130 5845.130769
+i32.ge_s: 815976 134 6089.373134
+i32.ctz: 1365171 155 8807.554839
+i64.and: 500951 226 2216.597345
+i64.shr_u: 516366 239 2160.527197
+i32.extend16_s: 644498 256 2517.570312
+i32.div_u: 927005 284 3264.102113
+i64.add: 655511 323 2029.445820
+i32.load16_u: 1218588 426 2860.535211
+i64.extend_i32_u: 1616328 592 2730.283784
+i32.gt_s: 1075177 613 1753.959217
+i64.mul: 1261502 842 1498.220903
+i32.store16: 3244007 1998 1623.627127
+i32.lt_s: 1922054 2161 889.428043
+i32.rot_l: 3035745 2203 1378.004993
+i32.clz: 3294742 5130 642.249903
+br_table: 8467414 6061 1397.032503
+i64.const: 3152338 9965 316.340993
+call_indirect: 9838820542 12643 778203.001028
+i64.load: 10364306 12927 801.756479
+drop: 5206384 15033 346.330340
+i32.xor: 12487750 18826 663.324657
+return: 6350359 19633 323.453318
+i32.le_u: 11637937 25404 458.114352
+global.get: 9668241 25951 372.557551
+select: 12858993 29114 441.677303
+i32.ge_u: 15268237 33468 456.204046
+i32.store8: 19742921 42849 460.755700
+loop: 9740080551 44110 220813.433484
+global.set: 16968389 51161 331.666484
+i32.shr_u: 19373076 51699 374.728254
+i32.load8_s: 20408302 54242 376.245382
+i32.sub: 22990019 64081 358.764985
+i32.eq: 24442710 66100 369.783812
+i32.mul: 24585216 68122 360.899797
+call: 36684717411 70579 519768.166324
+i32.or: 38330658 71541 535.785885
+i32.shl: 36051528 86408 417.224424
+i32.ne: 31550767 92660 340.500399
+i32.lt_u: 37354493 101169 369.228647
+i32.gt_u: 41854705 117828 355.218666
+i32.load8_u: 65740201 159431 412.342650
+i32.eqz: 53991602 198278 272.302535
+i32.and: 103813802 249884 415.447976
+i64.store: 196452396 306534 640.882891
+i32.store: 198052442 362806 545.890757
+local.set: 102276040 439632 232.640117
+br: 123832447 491022 252.193276
+i32.load: 249880707 564315 442.803588
+block: 78571426952 723450 108606.575371
+br_if: 340576107 732305 465.074125
+local.tee: 170952875 758661 225.334998
+i32.add: 202026275 812466 248.658128
+i32.const: 263163263 1589717 165.540950
+local.get: 543645174 3135728 173.371279