changeset 2216:acf1b68d031a

fancier background_loop reporting for faders
author drewp@bigasterisk.com
date Tue, 23 May 2023 14:43:12 -0700
parents d8853f173568
children e22c7d15a504
files lib/background_loop.py light9/effect/sequencer/service.py pdm.lock pyproject.toml
diffstat 4 files changed, 56 insertions(+), 31 deletions(-) [+]
line wrap: on
line diff
--- a/lib/background_loop.py	Tue May 23 14:41:04 2023 -0700
+++ b/lib/background_loop.py	Tue May 23 14:43:12 2023 -0700
@@ -6,8 +6,10 @@
 from typing import Any, Awaitable, Callable, Union
 
 from prometheus_client import Gauge, Summary
+from light9.recentfps import RecentFps
+from braillegraph import horizontal_graph
 
-log = logging.getLogger()
+log = logging.getLogger('loop')
 
 
 # throw this away (when net_routes is rewritten)
@@ -45,14 +47,21 @@
         func: UserFunc,
         sleep_period: float,
         metric_prefix: str,
+        extra_sleep_on_error: float = 2,
+        log_fps=False,
     ):
         self.func = func
         self.sleep_period = sleep_period
+        self.extra_sleep_on_error = extra_sleep_on_error
+        self.metric_prefix = metric_prefix
 
         self.up_metric = Gauge(f'{metric_prefix}_up', 'not erroring')
         self.call_metric = Summary(f'{metric_prefix}_calls', 'calls')
         self.lastSuccessRun = 0
         self.everSucceeded = False
+        self.succeeding = False
+        self.fps = RecentFps() if log_fps else None
+        self.lastFpsLog = 0
 
     async def call_func(self, first_run: bool, call_kwargs={}) -> F_RET:
         with self.call_metric.time():
@@ -64,6 +73,7 @@
 
     async def _run(self):
         self.first_run = True
+        self.newlyFailing = True
         while True:
             await self._runOne()
             await asyncio.sleep(self.sleep_period)
@@ -75,20 +85,44 @@
         return await self._runOne(call_kwargs=kwargs)
 
     async def _runOne(self, call_kwargs={}):
+        now = time.time()
+        self._updateFps(now)
         try:
             result = await self.call_func(self.first_run, call_kwargs)
             self.lastSuccessRun = time.time()
+            if self.fps:
+                self.fps.mark()
             self.up_metric.set(1)
             self.everSucceeded = True
+            self.newlyFailing = True
             self.first_run = False
         except Exception as ex:
-            log.error(ex)
-            traceback.print_exc()
+            if self.newlyFailing:
+                traceback.print_exc()
+                self.newlyFailing = False
+            else:
+                log.error(ex)
             self.up_metric.set(0)
             result = None
+            self.succeeding = False
+
+            await asyncio.sleep(self.extra_sleep_on_error)
             # todo: something that reveals error ratio
         return result
 
+    def _updateFps(self, now: float):
+        if self.fps is None:
+            return
+        if now < self.lastFpsLog + 5:
+            return
+        d = self.fps()
+        y_hi = 1 / self.sleep_period
+        if not d:
+            return
+        pts = [int(min(4, y / y_hi * 4)) for y in d['recents']]
+        log.info(f'{self.metric_prefix} fps={d["average"]:3.1f} (req={y_hi:3.1f}) {horizontal_graph(pts)}')
+        self.lastFpsLog = now
+
 
 def loop_forever(
     func: UserFunc,
@@ -96,6 +130,8 @@
     metric_prefix='background_loop',
     up_metric=None,
     call_metric=None,
+    extra_sleep_on_error=2,
+    log_fps=False,
 ):
     """
     sleep_period is the sleep time after however long func takes to run
@@ -103,6 +139,6 @@
     if up_metric is not None or call_metric is not None:
         raise NotImplementedError('remove old-style metrics')
 
-    loop = Loop(func, sleep_period, metric_prefix)
+    loop = Loop(func, sleep_period, metric_prefix, extra_sleep_on_error, log_fps)
     _created.append(asyncio.create_task(loop._run()))
     return loop
--- a/light9/effect/sequencer/service.py	Tue May 23 14:41:04 2023 -0700
+++ b/light9/effect/sequencer/service.py	Tue May 23 14:43:12 2023 -0700
@@ -23,6 +23,7 @@
 from light9.metrics import metrics
 from light9.run_local import log
 
+from lib.background_loop import loop_forever
 
 async def changes():
     state = {}
@@ -55,43 +56,22 @@
     await sendToCollector('effectSequencer', session='0', settings=ds)
 
 
-async def _forever(faders):
-    prevFail = True
-    while True:
-        try:
-            await _send_one(faders)
-            if prevFail:
-                log.info('connected')
-            prevFail = False
-        except (aiohttp.ClientConnectorError, aiohttp.ClientOSError) as e:
-            log.warn(f'{e!r} - retrying')
-            prevFail = True
-            await asyncio.sleep(2)
-        await asyncio.sleep(0.1)
-
-
-def send_updates_forever(faders):
-    asyncio.create_task(_forever(faders))
-
 
 ####################################################################
 
 
 def main():
-    session = 'effectSequencer'
     graph = SyncedGraph(networking.rdfdb.url, "effectSequencer")
     logging.getLogger('autodepgraphapi').setLevel(logging.INFO)
     logging.getLogger('syncedgraph').setLevel(logging.INFO)
     logging.getLogger('sse_starlette.sse').setLevel(logging.INFO)
 
-    async def send(settings: DeviceSettings):
-        await sendToCollector('effectSequencer', session, settings)
+    # seq = Sequencer(graph, send)  # per-song timed notes
+    faders = FaderEval(graph)  # bin/fade's untimed notes
 
-    # seq = Sequencer(graph, send)  # per-song timed notes
-    faders = FaderEval(graph, send)  # bin/fade's untimed notes
-    # asyncio.create_task(faders.startUpdating())
-
-    send_updates_forever(faders)
+    async def so(first_run):
+        await _send_one(faders)
+    faders_loop = loop_forever(so, metric_prefix='faders', sleep_period=.05, log_fps=True)
 
     app = Starlette(
         debug=True,
--- a/pdm.lock	Tue May 23 14:41:04 2023 -0700
+++ b/pdm.lock	Tue May 23 14:43:12 2023 -0700
@@ -93,6 +93,11 @@
 summary = "Specifications for callback functions passed in to an API"
 
 [[package]]
+name = "braillegraph"
+version = "0.6"
+summary = "A library for creating graphs using Unicode braille characters"
+
+[[package]]
 name = "certifi"
 version = "2023.5.7"
 requires_python = ">=3.6"
@@ -1020,7 +1025,7 @@
 
 [metadata]
 lock_version = "4.1"
-content_hash = "sha256:f6edf9705a4cc5011c8ebdaf29dc2fafe9d069072a34cd16fdc79d8c3786bb57"
+content_hash = "sha256:87020d26eb24328ebb0d89abe7e4343533e05a6cdd5286e57d1183d3f957ecdd"
 
 [metadata.files]
 "aiohttp 3.8.4" = [
@@ -1151,6 +1156,9 @@
     {url = "https://files.pythonhosted.org/packages/4c/1c/ff6546b6c12603d8dd1070aa3c3d273ad4c07f5771689a7b69a550e8c951/backcall-0.2.0-py2.py3-none-any.whl", hash = "sha256:fbbce6a29f263178a1f7915c1940bde0ec2b2a967566fe1c65c1dfb7422bd255"},
     {url = "https://files.pythonhosted.org/packages/a2/40/764a663805d84deee23043e1426a9175567db89c8b3287b5c2ad9f71aa93/backcall-0.2.0.tar.gz", hash = "sha256:5cbdbf27be5e7cfadb448baf0aa95508f91f2bbc6c6437cd9cd06e2a4c215e1e"},
 ]
+"braillegraph 0.6" = [
+    {url = "https://files.pythonhosted.org/packages/74/cf/f70fb67f740a12754c93039bf7977a2ca79737c8a5900c900c77a7afc13e/braillegraph-0.6.tar.gz", hash = "sha256:dd5656c371c4a60734013222b9ff9dbf4c27105090e66e5ef64cde1f6708d636"},
+]
 "certifi 2023.5.7" = [
     {url = "https://files.pythonhosted.org/packages/93/71/752f7a4dd4c20d6b12341ed1732368546bc0ca9866139fe812f6009d9ac7/certifi-2023.5.7.tar.gz", hash = "sha256:0f0d56dc5a6ad56fd4ba36484d6cc34451e1c6548c61daad8c320169f91eddc7"},
     {url = "https://files.pythonhosted.org/packages/9d/19/59961b522e6757f0c9097e4493fa906031b95b3ebe9360b2c3083561a6b4/certifi-2023.5.7-py3-none-any.whl", hash = "sha256:c6c2e98f5c7869efca1f8916fed228dd91539f9f1b444c314c06eef02980c716"},
--- a/pyproject.toml	Tue May 23 14:41:04 2023 -0700
+++ b/pyproject.toml	Tue May 23 14:43:12 2023 -0700
@@ -37,6 +37,7 @@
     "webcolors>=1.11.1",
     "rdfdb @ https://projects.bigasterisk.com/rdfdb/rdfdb-0.24.0.tar.gz",
     "scipy>=1.9.3",
+    "braillegraph>=0.6",
 ]
 requires-python = ">=3.10"