Changes ;)
[kiosk.git] / kiosk.py
index b043845b33664b7df1abe50f2c67967d8973160f..6d2fd4e00b5677c3bc8ea1728560ebb5912c6496 100755 (executable)
--- a/kiosk.py
+++ b/kiosk.py
@@ -1,9 +1,11 @@
 #!/usr/bin/env python3
 
+import collections
 from datetime import datetime
 import difflib
 import gc
 import linecache
+import logging
 import os
 import re
 import sys
@@ -16,8 +18,11 @@ from queue import Queue, Empty
 
 import astral  # type: ignore
 from astral.sun import sun  # type: ignore
+import numpy as np
+import pytz
 
 import constants
+import file_writer
 import renderer
 import renderer
 import renderer_catalog
@@ -28,6 +33,8 @@ import pvporcupine
 import trigger_catalog
 import utils
 
+logger = logging.getLogger(__file__)
+
 
 def thread_janitor() -> None:
     tracemalloc.start()
@@ -101,7 +108,7 @@ def guess_page(command: str, page_chooser: chooser.chooser) -> str:
     return best_page
 
 
-def process_command(command: str, page_history: List[str]) -> str:
+def process_command(command: str, page_history: List[str], page_chooser) -> str:
     page = None
     if 'hold' in command:
         page = page_history[0]
@@ -175,7 +182,7 @@ def thread_change_current(command_queue: Queue) -> None:
     swap_page_target = 0.0
 
     def filter_news_during_dinnertime(page: str) -> bool:
-        now = datetime.now()
+        now = datetime.now(tz=pytz.timezone("US/Pacific"))
         is_dinnertime = now.hour >= 17 and now.hour <= 20
         return not is_dinnertime or not (
             "cnn" in page
@@ -202,7 +209,7 @@ def thread_change_current(command_queue: Queue) -> None:
             pass
         if command is not None:
             triggered = True
-            page = process_command(command, page_history)
+            page = process_command(command, page_history, page_chooser)
 
         # Else pick a page randomly.
         else:
@@ -259,13 +266,13 @@ def emit_wrapped(f,
                  override_refresh_sec: int = None,
                  command: str = None) -> None:
     def pick_background_color() -> str:
+        now = datetime.now(tz=pytz.timezone("US/Pacific"))
         city = astral.LocationInfo(
             "Bellevue", "USA", "US/Pacific", 47.610, -122.201
         )
-        s = sun(city.observer, date=self.dt, tzinfo=pytz.timezone("US/Pacific"))
+        s = sun(city.observer, date=now, tzinfo=pytz.timezone("US/Pacific"))
         sunrise_mod = utils.minute_number(s["sunrise"].hour, s["sunrise"].minute)
         sunset_mod = utils.minute_number(s["sunset"].hour, s["sunset"].minute)
-        now = datetime.now()
         now_mod = utils.minute_number(now.hour, now.minute)
         if now_mod < sunrise_mod or now_mod > (sunset_mod + 45):
             return "E6B8B8"
@@ -277,7 +284,7 @@ def emit_wrapped(f,
     def get_refresh_period() -> float:
         if override_refresh_sec is not None:
             return float(override_refresh_sec * 1000.0)
-        now = datetime.now()
+        now = datetime.now(tz=pytz.timezone("US/Pacific"))
         if now.hour < 7:
             return float(constants.refresh_period_night_sec * 1000.0)
         else:
@@ -489,24 +496,92 @@ def emit_wrapped(f,
 
 
 def thread_invoke_renderers() -> None:
+    render_times: Dict[str, np.array] = {}
+    render_counts: collections.Counter = collections.Counter()
+    last_render: Dict[str, datetime] = {}
+
     while True:
-        print(f"renderer[{utils.timestamp()}]: invoking all renderers in catalog...")
+        print(f'renderer[{utils.timestamp()}]: invoking all overdue renderers in catalog...')
         for r in renderer_catalog.get_renderers():
+            name = r.get_name()
             now = time.time()
             try:
                 r.render()
             except Exception as e:
-                traceback.print_exc()
+                traceback.print_exc(file=sys.stdout)
+                logger.exception(e)
                 print(
-                    f"renderer[{utils.timestamp()}] unknown exception in {r.get_name()}, swallowing it."
+                    f"renderer[{utils.timestamp()}] Unknown exception ({e}) in {name}, swallowing it."
                 )
+
+            # Increment the count of render operations per renderer.
+            render_counts[name] += 1
+
+            # Keep track of the last time we invoked each renderer.
+            last_render[name] = datetime.now(tz=pytz.timezone("US/Pacific"))
+
+            # Record how long each render operation takes and warn if very long.
             delta = time.time() - now
+            times = render_times.get(name, np.array([]))
+            times = np.insert(times, 0, delta)
+            render_times[name] = times
             if delta > 1.0:
+                hdr = f'renderer[{utils.timestamp()}]:'
                 print(
-                    f"renderer[{utils.timestamp()}]: Warning: {r.get_name()}'s rendering took {delta:5.2f}s."
-                )
+f'''
+{hdr} Warning: {name}'s rendering took {delta:5.2f}s.
+{hdr} FYI: {name}'s render times: p25={np.percentile(times, 25):5.2f}, p50={np.percentile(times, 50):5.2f}, p75={np.percentile(times, 75):5.2f}, p90={np.percentile(times, 90):5.2f}, p99={np.percentile(times, 99):5.2f}
+''')
+
+        # Render a page about internal stats of renderers.
+        print(f'renderer[{utils.timestamp()}]: Updating internal statistics page.')
+        with file_writer.file_writer(constants.internal_stats_pagename) as f:
+            f.write(
+f'''
+<TABLE BORDER=0>
+    <TR>
+    <TH>Renderer Name</TH>
+    <TH>Last Run</TH>
+    <TH>Num Invocations</TH>
+    <TH>Render Latency</TH>
+    </TR>
+''')
+            for n, r in enumerate(renderer_catalog.get_renderers()):
+                if n % 2 == 0:
+                    style = 'style="margin: 0; padding: 0; background: #c6b0b0;"'
+                else:
+                    style = 'style="margin: 0; padding: 0; background: #eeeeee;"'
+                name = r.get_name()
+                last = last_render.get(name, None)
+                if last is None:
+                    last = 'never'
+                else:
+                    last = last.strftime('%Y/%m/%d %I:%M:%S%P')
+                count = render_counts.get(name, 0)
+                latency = render_times.get(name, np.array([]))
+                p25 = p50 = p75 = p90 = p99 = 'N/A'
+                try:
+                    p25 = np.percentile(latency, 25)
+                    p50 = np.percentile(latency, 50)
+                    p75 = np.percentile(latency, 75)
+                    p90 = np.percentile(latency, 90)
+                    p99 = np.percentile(latency, 99)
+                except IndexError:
+                    pass
+                f.write(
+f'''
+    <TR>
+    <TD {style}>{name}</TD>
+    <TD {style}>{last}</TD>
+    <TD {style}><CENTER>{count}</CENTER></TD>
+    <TD {style}>p25={p25:5.2f}, p50={p50:5.2f}, p75={p75:5.2f}, p90={p90:5.2f}, p99={p99:5.2f}</TD>
+    </TR>
+''')
+            f.write('</TABLE>')
+
         print(
-            f"renderer[{utils.timestamp()}]: thread having a little break for {constants.render_period_sec}s..."
+            f"renderer[{utils.timestamp()}]: " +
+            f"thread having a little break for {constants.render_period_sec}s..."
         )
         time.sleep(constants.render_period_sec)