monitor_pico.py: improve hog detection.

Author: peterhinch

v3/as_demos/monitor/README.md

@@ -4,12 +4,13 @@ This library provides a means of examining the behaviour of a running
 `uasyncio` system. The device under test is linked to a Raspberry Pi Pico. The
 latter displays the behaviour of the host by pin changes and/or optional print
 statements. A logic analyser or scope provides an insight into the way an
-asynchronous application is working.
+asynchronous application is working, although valuable informtion can be
+gleaned without such tools.
 
 Communication with the Pico may be by UART or SPI, and is uni-directional from
 system under test to Pico. If a UART is used only one GPIO pin is used; at last
-a use for the ESP8266 transmit-only UART(1). SPI requires three - mosi, sck and
-cs/.
+a use for the ESP8266 transmit-only UART(1). SPI requires three - `mosi`, `sck`
+and `cs/`.
 
 Where an application runs multiple concurrent tasks it can be difficult to
 locate a task which is hogging CPU time. Long blocking periods can also result
@@ -25,11 +26,14 @@ trigger because another task is hogging the CPU. Lines 01 and 03 show the `foo`
 and `bar` tasks.  
 ![Image](./monitor.jpg)
 
-### Breaking changes to support SPI
+### Status
 
-The `set_uart` method is replaced by `set_device`. Pin mappings on the Pico
-have changed. Barring bug fixes or user suggestions I consider this project to
-be complete.
+30th Sep 2021 Pico code has improved hog detection.
+
+27th Sep 2021 SPI support added. The `set_uart` method is replaced by
+`set_device`. Pin mappings on the Pico changed.
+
+21st Sep 2021 Initial release.
 
 ## 1.1 Pre-requisites
 
@@ -133,10 +137,8 @@ To aid in detecting the gaps in execution, the Pico code implements a timer.
 This is retriggered by activity on `ident=0`. If it times out, a brief high
 going pulse is produced on pin 28, along with the console message "Hog". The
 pulse can be used to trigger a scope or logic analyser. The duration of the
-timer may be adjusted - see [section 4](./README.md~4-the-pico-code).
-
-Note that hog detection will be triggered if the host application terminates.
-The Pico cannot determine the reason why the `hog_detect` task has stopped.
+timer may be adjusted. Other modes of hog detection are also supported. See
+[section 4](./README.md~4-the-pico-code).
 
 # 2. Monitoring synchronous code
 
@@ -239,6 +241,38 @@ reported if blocking is for more than 60ms, issue
 from monitor_pico import run
 run(60, (4, 7))
 ```
+Hog reporting is as follows. If ident 0 is inactive for more than the specified
+time, "Timeout" is issued. If ident 0 occurs after this, "Hog Nms" is issued
+where N is the duration of the outage. If the outage is longer than the prior
+maximum, "Max hog Nms" is also issued.
+
+This means that if the application under test terminates, throws an exception
+or crashes, "Timeout" will be issued.
+
+## 4.1 Advanced hog detection
+
+The detection of rare instances of high latency is a key requirement and other
+modes are available. There are two aims: providing information to users lacking
+test equipment and enhancing the ability to detect infrequent cases. Modes
+affect the timing of the trigger pulse and the frequency of reports.
+
+Modes are invoked by passing a 2-tuple as the `period` arg.  
+ * `period[0]` The period (ms): outages shorter than this time will be ignored.
+ * `period[1]` is the mode: constants `SOON`, `LATE` and `MAX` are exported.
+
+The mode has the following effect on the trigger pulse:  
+ * `SOON` Default behaviour: pulse occurs early at time `period[0]` ms after
+ the last trigger.
+ * `LATE` Pulse occurs when the outage ends.
+ * `MAX` Pulse occurs when the outage ends and its duration exceeds the prior
+ maximum.
+
+The mode also affects reporting. The effect of mode is as follows:
+ * `SOON` Default behaviour as described in section 4.
+ * `LATE` As above, but no "Timeout" message: reporting occurs at the end of an
+ outage only.
+ * `MAX` Report at end of outage but only when prior maximum exceeded. This
+ ensures worst-case is not missed.
 
 # 5. Performance and design notes
 

v3/as_demos/monitor/monitor_pico.py

@@ -11,6 +11,7 @@
 
 import rp2
 from machine import UART, Pin, Timer, freq
+from time import ticks_ms, ticks_diff
 
 freq(250_000_000)
 
@@ -54,27 +55,43 @@ def read(self):
 # GPIO 0,1,2 are for interface so pins are 3..22, 26..27
 PIN_NOS = list(range(3, 23)) + list(range(26, 28))
 
+# Index is incoming ID
+# contents [Pin, instance_count, verbose]
+pins = []
+for pin_no in PIN_NOS:
+    pins.append([Pin(pin_no, Pin.OUT), 0, False])
+
+# ****** Timing *****
+
 pin_t = Pin(28, Pin.OUT)
 def _cb(_):
     pin_t(1)
-    print('Hog')
+    print("Timeout.")
     pin_t(0)
 
 tim = Timer()
-t_ms = 100
-# Index is incoming ID
-# contents [Pin, instance_count, verbose]
-pins = []
-for pin_no in PIN_NOS:
-    pins.append([Pin(pin_no, Pin.OUT), 0, False])
 
 # ****** Monitor ******
+
+SOON = const(0)
+LATE = const(1)
+MAX = const(2)
+# Modes. Pulses and reports only occur if an outage exceeds the threshold.
+# SOON: pulse early when timer times out. Report at outage end.
+# LATE: pulse when outage ends. Report at outage end.
+# MAX: pulse when outage exceeds prior maximum. Report only in that instance.
+
 # native reduced latency to 10μs but killed the hog detector: timer never timed out.
 # Also locked up Pico so ctrl-c did not interrupt.
 #@micropython.native
 def run(period=100, verbose=(), device="uart", vb=True):
-    global t_ms
-    t_ms = period
+    if isinstance(period, int):
+        t_ms = period
+        mode = SOON
+    else:
+        t_ms, mode = period
+        if mode not in (SOON, LATE, MAX):
+            raise ValueError('Invalid mode.')
     for x in verbose:
         pins[x][2] = True
     # A device must support a blocking read.
@@ -92,15 +109,36 @@ def read():
         raise ValueError("Unsupported device:", device)
 
     vb and print('Awaiting communication')
+    h_max = 0  # Max hog duration (ms)
+    h_start = 0  # Absolute hog start time
     while True:
         if x := read():  # Get an initial 0 on UART
             if x == 0x7a:  # Init: program under test has restarted
                 vb and print('Got communication.')
+                h_max = 0  # Restart timing
+                h_start = 0
                 for pin in pins:
-                    pin[1] = 0
+                    pin[1] = 0  # Clear instance counters
                 continue
-            if x == 0x40:  # Retrigger hog detector.
-                tim.init(period=t_ms, mode=Timer.ONE_SHOT, callback=_cb)
+            if x == 0x40:  # hog_detect task has started.
+                t = ticks_ms()  # Arrival time
+                if mode == SOON:  # Pulse on absence of activity
+                    tim.init(period=t_ms, mode=Timer.ONE_SHOT, callback=_cb)
+                if h_start:  # There was a prior trigger
+                    dt = ticks_diff(t, h_start)
+                    if dt > t_ms:  # Delay exceeds threshold
+                        if mode != MAX:
+                            print(f"Hog {dt}ms")
+                        if mode == LATE:
+                            pin_t(1)
+                            pin_t(0)
+                        if dt > h_max:
+                            h_max = dt
+                            print(f"Max hog {dt}ms")
+                            if mode == MAX:
+                                pin_t(1)
+                                pin_t(0)
+                h_start = t
             p = pins[x & 0x1f]  # Key: 0x40 (ord('@')) is pin ID 0
             if x & 0x20:  # Going down
                 p[1] -= 1

v3/as_demos/monitor/monitor_test.py

@@ -1,5 +1,8 @@
 # monitor_test.py
 
+# Copyright (c) 2021 Peter Hinch
+# Released under the MIT License (MIT) - see LICENSE file
+
 import uasyncio as asyncio
 from monitor import monitor, monitor_init, mon_func, mon_call, set_device
 

v3/as_demos/monitor/quick_test.py

@@ -1,5 +1,8 @@
 # quick_test.py
 
+# Copyright (c) 2021 Peter Hinch
+# Released under the MIT License (MIT) - see LICENSE file
+
 import uasyncio as asyncio
 import time
 from machine import Pin, UART, SPI
@@ -17,8 +20,9 @@ async def foo(t, pin):
 
 @monitor(2)
 async def hog():
-    await asyncio.sleep(5)
-    time.sleep_ms(500)
+    while True:
+        await asyncio.sleep(5)
+        time.sleep_ms(500)
 
 @monitor(3)
 async def bar(t):
@@ -27,12 +31,16 @@ async def bar(t):
 
 async def main():
     monitor_init()
-    test_pin = Pin('X6', Pin.OUT)
+    # test_pin = Pin('X6', Pin.OUT)
+    test_pin = lambda _ : None  # If you don't want to measure latency
     asyncio.create_task(hog_detect())
     asyncio.create_task(hog())  # Will hog for 500ms after 5 secs
     while True:
         asyncio.create_task(foo(100, test_pin))
         await bar(150)
         await asyncio.sleep_ms(50)
 
-asyncio.run(main())
+try:
+    asyncio.run(main())
+finally:
+    asyncio.new_event_loop()