Poor mans profiling - pinpointing pain points

[dzervas]

I'm losing some keystrokes here and there and I also want to implement display features, so it's sane to do a bit of a performance hit research. I'm not into GDB and regular profiling (I suck) so bunch of prints should be able to tell us just some basic info.

Stats captured with MCP23017 on all columns with I2C on 100kHz

Setup

I a bunch of prints using time.monotonic() deltas and a quick python script to compute the statistics. The prints diff (based on commit aebf516ffdf4eb4b9e393ac72547ce85e36a84b1 on my fork):

diff --git a/kmk/kmk_keyboard.py b/kmk/kmk_keyboard.py
index 2f03444..6dab6bb 100644
--- a/kmk/kmk_keyboard.py
+++ b/kmk/kmk_keyboard.py
@@ -6,6 +6,7 @@ import kmk.preload_imports  # isort:skip # NOQA
 import busio
 import gc

+from time import monotonic
 from kmk import led, rgb
 from kmk.consts import KMK_RELEASE, LeaderMode, UnicodeMode
 from kmk.hid import USBHID, AbstractHID, HIDModes
@@ -290,6 +291,7 @@ class KMKKeyboard:
         self._print_debug_cycle(init=True)

         while True:
+            starttime = monotonic()
             state_changed = False

             if self.split_type is not None and self.is_master:
@@ -298,7 +300,9 @@ class KMKKeyboard:
                     self._handle_matrix_report(update)
                     state_changed = True

+            matrixtime = monotonic()
             update = self.matrix.scan_for_changes()
+            print("[go][matrix]", monotonic() - matrixtime)

             if update is not None:
                 if self.is_master:
@@ -309,7 +313,9 @@ class KMKKeyboard:
                     self._send_to_master(update)

             if self._state.hid_pending:
+                hidtime = monotonic()
                 self._send_hid()
+                print("[go][send_hid]", monotonic() - hidtime)

             old_timeouts_len = len(self._state.timeouts)
             self._state.process_timeouts()
@@ -332,3 +338,5 @@ class KMKKeyboard:

             if state_changed:
                 self._print_debug_cycle()
+
+            print("[go]", monotonic() - starttime)
diff --git a/kmk/matrix.py b/kmk/matrix.py
index 8d809bc..e51bf2c 100644
--- a/kmk/matrix.py
+++ b/kmk/matrix.py
@@ -209,5 +209,6 @@ class MatrixScanner:
                 ba_idx += 1

             opin.value = False
+            # print("[scan_for_changes][matrix][total]", monotonic() - starttime)
             if any_changed:
                 return self.report

Python script to parse all these: stats.py

#!/usr/bin/env python3
import statistics
from sys import stdin

all_nums = []

for line in stdin:
    num = line.split(" ")[-1]
    all_nums.append(float(num) * 1000)

print("Max:", max(all_nums))
print("Min:", min(all_nums))
print("Average:", statistics.mean(all_nums))
print("Median:", statistics.median(all_nums))
print("Median Low:", statistics.median_low(all_nums))
print("Median High:", statistics.median_high(all_nums))

Usage

First of all, dump all serial output to a log file - with debug DISABLED: miniterm.py --raw /dev/ttyACM0 115200 | tee /tmp/kmk.log

Find all available log messages

❯ grep -o "^\[.*\]" /tmp/kmk.log| sort -u
[go]
[go][matrix]
[go][send_hid]

Find stats for a specific log (whole go function):

❯ grep "^\[go\] " /tmp/kmk.log | ../stats.py
Max: 109.375
Min: 15.625
Average: 52.96680728241563
Median: 62.5
Median Low: 62.5
Median High: 62.5

Results

Whole go function

❯ grep "^\[go\] " /tmp/kmk.log | ../stats.py
Max: 109.375
Min: 15.625
Average: 52.96680728241563
Median: 62.5
Median Low: 62.5
Median High: 62.5

scan_for_changes

❯ grep "^\[go\]\[matrix\] " /tmp/kmk.log | ../stats.py
Max: 109.375
Min: 0.0
Average: 37.932564330079856
Median: 31.25
Median Low: 31.25
Median High: 31.25

_send_hid

❯ grep "^\[go\]\[send_hid\] " /tmp/kmk.log | ../stats.py
Max: 46.875
Min: 0.0
Average: 1.8411624203821657
Median: 0.0
Median Low: 0.0
Median High: 0.0

[dzervas]

Added some more prints

process_timeouts

❯ grep "^\[go\]\[process_timeouts\] " /tmp/kmk_all.log | ../stats.py
Amount of samples: 1366

Max: 31.25
Min: 0.0
Average: 0.11438506588579796
Median: 0.0
Median Low: 0.0
Median High: 0.0

[dzervas]

I tested ramping up I2C at 1.7MHz (max for MCP):

❯ command grep "^\[go\] " /tmp/kmk_1.7.log | ../stats.py
Amount of samples: 1601

Max: 93.75
Min: 0.0
Average: 40.34587757651468
Median: 31.25
Median Low: 31.25
Median High: 31.25