Add a perf_timer() utility for timing blocks of code (#108)

* Add a perf_timer() utility for timing blocks of code

It has replaced raw perf_counter() calls in some files.

* Use perf_timer in ticket_status_pie.py

* Use perf_timer() for app home performance logging

* Remove plt.show() call

That was never meant to be there :pf:

* Print performance logs as debug logs

nephthys/events/app_home_opened.py

@@ -6,6 +6,7 @@ from slack_sdk.web.async_client import AsyncWebClient
 
 from nephthys.utils.env import env
 from nephthys.utils.logging import send_heartbeat
+from nephthys.utils.performance import perf_timer
 from nephthys.views.home.assigned import get_assigned_tickets_view
 from nephthys.views.home.error import get_error_view
 from nephthys.views.home.helper import get_helper_view
@@ -36,22 +37,23 @@ async def open_app_home(home_type: str, client: AsyncWebClient, user_id: str):
             view = get_unknown_user_view(name)
         else:
             logging.info(f"Opening {home_type} for {user_id}")
-            match home_type:
-                case "default" | "dashboard":
-                    view = await get_helper_view(user)
-                case "assigned-tickets":
-                    view = await get_assigned_tickets_view(user)
-                case "tags":
-                    view = await get_manage_tags_view(user)
-                case "my-stats":
-                    view = await get_stats_view(user)
-                case _:
-                    await send_heartbeat(
-                        f"Attempted to load unknown app home type {home_type} for <@{user_id}>"
-                    )
-                    view = get_error_view(
-                        f"This shouldn't happen, please tell <@{env.slack_maintainer_id}> that app home case `_` was hit with home type `{home_type}`"
-                    )
+            async with perf_timer(f"Rendering app home (type={home_type})"):
+                match home_type:
+                    case "default" | "dashboard":
+                        view = await get_helper_view(user)
+                    case "assigned-tickets":
+                        view = await get_assigned_tickets_view(user)
+                    case "tags":
+                        view = await get_manage_tags_view(user)
+                    case "my-stats":
+                        view = await get_stats_view(user)
+                    case _:
+                        await send_heartbeat(
+                            f"Attempted to load unknown app home type {home_type} for <@{user_id}>"
+                        )
+                        view = get_error_view(
+                            f"This shouldn't happen, please tell <@{env.slack_maintainer_id}> that app home case `_` was hit with home type `{home_type}`"
+                        )
     except Exception as e:
         logging.error(f"Error opening app home: {e}")
         tb = traceback.format_exception(e)

nephthys/events/message.py

@@ -1,6 +1,5 @@
 import logging
 from datetime import datetime
-from time import perf_counter
 from typing import Any
 from typing import Dict
 
@@ -10,6 +9,7 @@ from slack_sdk.web.async_client import AsyncWebClient
 from nephthys.macros import run_macro
 from nephthys.utils.env import env
 from nephthys.utils.logging import send_heartbeat
+from nephthys.utils.performance import perf_timer
 from nephthys.utils.ticket_methods import delete_and_clean_up_ticket
 from prisma.enums import TicketStatus
 from prisma.models import User
@@ -83,8 +83,8 @@ async def send_ticket_message(
     event: Dict[str, Any],
     client: AsyncWebClient,
     past_tickets: int,
-    display_name: str,
-    profile_pic: str,
+    display_name: str | None,
+    profile_pic: str | None,
 ):
     """Send a "backend" message to the tickets channel with ticket details."""
     user = event.get("user", "unknown")
@@ -135,17 +135,14 @@ async def handle_new_question(
         client (AsyncWebClient): Slack API client.
         db_user (User | None): The database user object, or None if user doesn't exist yet.
     """
-    start_time = perf_counter()
-    user = event.get("user", "unknown")
-    text = event.get("text", "")
-    user_info_response = await client.users_info(user=user) or {}
-    slack_user_info_time = perf_counter()
-    logging.debug(
-        f"on_message: Slack user info fetch took {slack_user_info_time - start_time:.2f}s"
-    )
+    async with perf_timer("Slack user info fetch"):
+        user = event.get("user", "unknown")
+        text = event.get("text", "")
+        user_info_response = await client.users_info(user=user) or {}
+
     user_info = user_info_response.get("user")
     if user_info:
-        profile_pic: str = user_info["profile"].get("image_512", "")
+        profile_pic: str | None = user_info["profile"].get("image_512", "")
         display_name: str = (
             user_info["profile"]["display_name"] or user_info["real_name"]
         )
@@ -154,42 +151,37 @@ async def handle_new_question(
         display_name = "Explorer"
 
     if db_user:
-        past_tickets = await env.db.ticket.count(where={"openedById": db_user.id})
+        async with perf_timer("Getting ticket count from DB"):
+            past_tickets = await env.db.ticket.count(where={"openedById": db_user.id})
     else:
         past_tickets = 0
         username = (user_info or {}).get(
             "name"
         )  # this should never actually be empty but if it is, that is a major issue
 
-        if not username:
-            await send_heartbeat(
-                f"SOMETHING HAS GONE TERRIBLY WRONG <@{user}> has no username found - <@{env.slack_maintainer_id}>"
+        async with perf_timer("Creating user in DB"):
+            if not username:
+                await send_heartbeat(
+                    f"SOMETHING HAS GONE TERRIBLY WRONG <@{user}> has no username found - <@{env.slack_maintainer_id}>"
+                )
+            db_user = await env.db.user.upsert(
+                where={
+                    "slackId": user,
+                },
+                data={
+                    "create": {"slackId": user, "username": username},
+                    "update": {"slackId": user, "username": username},
+                },
             )
-        db_user = await env.db.user.upsert(
-            where={
-                "slackId": user,
-            },
-            data={
-                "create": {"slackId": user, "username": username},
-                "update": {"slackId": user, "username": username},
-            },
-        )
-    db_count_time = perf_counter()
-    logging.debug(
-        f"on_message: Getting ticket count/updating user DB took {db_count_time - slack_user_info_time:.2f}s"
-    )
 
-    ticket_message = await send_ticket_message(
-        event,
-        client,
-        past_tickets=past_tickets,
-        display_name=display_name,
-        profile_pic=profile_pic,
-    )
-    ticket_message_time = perf_counter()
-    logging.debug(
-        f"on_message: Sending ticket message took {ticket_message_time - db_count_time:.2f}s"
-    )
+    async with perf_timer("Sending backend ticket message"):
+        ticket_message = await send_ticket_message(
+            event,
+            client,
+            past_tickets=past_tickets,
+            display_name=display_name,
+            profile_pic=profile_pic,
+        )
 
     ticket_message_ts = ticket_message["ts"]
     if not ticket_message_ts:
@@ -203,44 +195,35 @@ async def handle_new_question(
     )
     ticket_url = f"https://hackclub.slack.com/archives/{env.slack_ticket_channel}/p{ticket_message_ts.replace('.', '')}"
 
-    user_facing_message = await send_user_facing_message(
-        event, client, text=user_facing_message_text, ticket_url=ticket_url
-    )
-    user_facing_message_time = perf_counter()
-    logging.debug(
-        f"on_message: Sending FAQ message took {user_facing_message_time - ticket_message_time:.2f}s"
-    )
+    async with perf_timer("Sending user-facing FAQ message"):
+        user_facing_message = await send_user_facing_message(
+            event, client, text=user_facing_message_text, ticket_url=ticket_url
+        )
 
-    title = await generate_ticket_title(text)
-    ai_response_time = perf_counter()
-    logging.debug(
-        f"on_message: AI title generation took {ai_response_time - user_facing_message_time:.2f}s"
-    )
+    async with perf_timer("AI ticket title generation"):
+        title = await generate_ticket_title(text)
 
     user_facing_message_ts = user_facing_message["ts"]
     if not user_facing_message_ts:
         logging.error(f"User-facing message has no ts: {user_facing_message}")
         return
 
-    ticket = await env.db.ticket.create(
-        {
-            "title": title,
-            "description": text,
-            "msgTs": event["ts"],
-            "ticketTs": ticket_message_ts,
-            "openedBy": {"connect": {"id": db_user.id}},
-            "userFacingMsgs": {
-                "create": {
-                    "channelId": event["channel"],
-                    "ts": user_facing_message_ts,
-                }
+    async with perf_timer("Creating ticket in DB"):
+        ticket = await env.db.ticket.create(
+            {
+                "title": title,
+                "description": text,
+                "msgTs": event["ts"],
+                "ticketTs": ticket_message_ts,
+                "openedBy": {"connect": {"id": db_user.id}},
+                "userFacingMsgs": {
+                    "create": {
+                        "channelId": event["channel"],
+                        "ts": user_facing_message_ts,
+                    }
+                },
             },
-        },
-    )
-    ticket_creation_time = perf_counter()
-    logging.debug(
-        f"on_message: Ticket creation in DB took {ticket_creation_time - ai_response_time:.2f}s"
-    )
+        )
 
     try:
         await client.reactions_add(
@@ -318,27 +301,20 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient):
         logging.info(f"Ignoring bot message from {event['bot_id']}")
         return
 
-    start_time = perf_counter()
-
-    db_user = await env.db.user.find_first(
-        where={"slackId": event.get("user", "unknown")}
-    )
-    db_lookup_time = perf_counter()
-    logging.debug(f"on_message: DB lookup took {db_lookup_time - start_time:.2f}s")
+    async with perf_timer("DB user lookup"):
+        db_user = await env.db.user.find_first(
+            where={"slackId": event.get("user", "unknown")}
+        )
 
     # Messages sent in a thread with the "send to channel" checkbox checked
     if event.get("subtype") == "thread_broadcast" and not (db_user and db_user.helper):
-        await handle_message_sent_to_channel(event, client)
+        async with perf_timer("Handling message sent to channel"):
+            await handle_message_sent_to_channel(event, client)
 
     if event.get("thread_ts"):
         await handle_message_in_thread(event, db_user)
         return
 
-    special_cases_time = perf_counter()
-    logging.debug(
-        f"on_message: Special cases took {special_cases_time - db_lookup_time:.2f}s"
-    )
-
     await handle_new_question(event, client, db_user)
 
     if env.uptime_url and env.environment == "production":

nephthys/utils/performance.py

@@ -0,0 +1,14 @@
+import inspect
+import logging
+from contextlib import asynccontextmanager
+from time import perf_counter
+
+
+@asynccontextmanager
+async def perf_timer(name: str):
+    start_time = perf_counter()
+    yield
+    duration = perf_counter() - start_time
+    # Get the name of the function that called the `perf_timer()`
+    function_name = inspect.stack()[2].function
+    logging.debug(f"{function_name}: {name} took {duration:.3f}s")

nephthys/utils/slack.py

@@ -1,5 +1,4 @@
 import logging
-from time import perf_counter
 from typing import Any
 from typing import Dict
 
@@ -21,6 +20,7 @@ from nephthys.events.message import on_message
 from nephthys.events.message_deletion import on_message_deletion
 from nephthys.options.tags import get_tags
 from nephthys.utils.env import env
+from nephthys.utils.performance import perf_timer
 
 app = AsyncApp(token=env.slack_bot_token, signing_secret=env.slack_signing_secret)
 
@@ -28,19 +28,17 @@ app = AsyncApp(token=env.slack_bot_token, signing_secret=env.slack_signing_secre
 @app.event("message")
 async def handle_message(event: Dict[str, Any], client: AsyncWebClient):
     logging.debug(f"Message event: {event}")
-    start_time = perf_counter()
     is_message_deletion = (
         event.get("subtype") == "message_changed"
         and event["message"].get("subtype") == "tombstone"
     ) or event.get("subtype") == "message_deleted"
-    if event["channel"] == env.slack_help_channel:
-        if is_message_deletion:
-            await on_message_deletion(event, client)
-        else:
-            await on_message(event, client)
-    logging.info(
-        f"Processed message event in {perf_counter() - start_time:.2f} seconds total"
-    )
+
+    async with perf_timer("Processing message event (total time)"):
+        if event["channel"] == env.slack_help_channel:
+            if is_message_deletion:
+                await on_message_deletion(event, client)
+            else:
+                await on_message(event, client)
 
 
 @app.action("mark_resolved")

nephthys/views/home/components/ticket_status_pie.py

@@ -1,15 +1,14 @@
-import logging
 from datetime import datetime
 from datetime import timedelta
 from datetime import timezone
 from io import BytesIO
-from time import perf_counter
 
 import numpy as np
 
 from nephthys.utils.bucky import upload_file
 from nephthys.utils.env import env
 from nephthys.utils.graphs.pie import generate_pie_chart
+from nephthys.utils.performance import perf_timer
 from nephthys.utils.time import is_day
 from prisma.enums import TicketStatus
 
@@ -17,7 +16,6 @@ from prisma.enums import TicketStatus
 async def get_ticket_status_pie_chart(
     tz: timezone | None = None, raw: bool = False
 ) -> dict | bytes:
-    time_start = perf_counter()
     is_daytime = is_day(tz) if tz else True
 
     if is_daytime:
@@ -30,18 +28,17 @@ async def get_ticket_status_pie_chart(
     now = datetime.now(timezone.utc)
     one_week_ago = now - timedelta(days=7)
 
-    recently_closed_tickets = await env.db.ticket.count(
-        where={
-            "status": TicketStatus.CLOSED,
-            "closedAt": {"gte": one_week_ago},
-        }
-    )
-    in_progress_tickets = await env.db.ticket.count(
-        where={"status": TicketStatus.IN_PROGRESS}
-    )
-    open_tickets = await env.db.ticket.count(where={"status": TicketStatus.OPEN})
-    time_get_tickets = perf_counter()
-    logging.debug(f"Fetched tickets in {time_get_tickets - time_start:.4f} seconds")
+    async with perf_timer("Fetching ticket counts from DB"):
+        recently_closed_tickets = await env.db.ticket.count(
+            where={
+                "status": TicketStatus.CLOSED,
+                "closedAt": {"gte": one_week_ago},
+            }
+        )
+        in_progress_tickets = await env.db.ticket.count(
+            where={"status": TicketStatus.IN_PROGRESS}
+        )
+        open_tickets = await env.db.ticket.count(where={"status": TicketStatus.OPEN})
 
     y = [recently_closed_tickets, in_progress_tickets, open_tickets]
     labels = ["Closed", "In Progress", "Open"]
@@ -51,50 +48,44 @@ async def get_ticket_status_pie_chart(
         "#FF746C",
     ]
 
-    for count in range(
-        len(y) - 1, -1, -1
-    ):  # iterate in reverse so that indexes are not affected
-        if y[count] == 0:
-            del y[count]
-            del labels[count]
-            del colours[count]
+    async with perf_timer("Building pie chart"):
+        for count in range(
+            len(y) - 1, -1, -1
+        ):  # iterate in reverse so that indexes are not affected
+            if y[count] == 0:
+                del y[count]
+                del labels[count]
+                del colours[count]
 
-    y = np.array(y)
-
-    b = BytesIO()
-    plt = generate_pie_chart(
-        y=y,
-        labels=labels,
-        colours=colours,
-        text_colour=text_colour,
-        bg_colour=bg_colour,
-    )
-    time_generate_chart = perf_counter()
-    logging.debug(
-        f"Built pie chart in {time_generate_chart - time_get_tickets:.4f} seconds"
-    )
-    plt.savefig(
-        b, bbox_inches="tight", pad_inches=0.1, transparent=False, dpi=300, format="png"
-    )
-    time_save_chart = perf_counter()
-    logging.debug(
-        f"Saved pie chart to buffer in {time_save_chart - time_generate_chart:.4f} seconds"
-    )
-
-    plt.show()
+        b = BytesIO()
+        y = np.array(y)
+        plt = generate_pie_chart(
+            y=y,
+            labels=labels,
+            colours=colours,
+            text_colour=text_colour,
+            bg_colour=bg_colour,
+        )
+    async with perf_timer("Saving pie chart to buffer"):
+        plt.savefig(
+            b,
+            bbox_inches="tight",
+            pad_inches=0.1,
+            transparent=False,
+            dpi=300,
+            format="png",
+        )
 
     if raw:
         return b.getvalue()
 
-    url = await upload_file(
-        file=b.getvalue(),
-        filename="ticket_status.png",
-        content_type="image/png",
-    )
-    time_upload_file = perf_counter()
-    logging.debug(
-        f"Uploaded pie chart in {time_upload_file - time_save_chart:.4f} seconds"
-    )
+    async with perf_timer("Uploading pie chart"):
+        url = await upload_file(
+            file=b.getvalue(),
+            filename="ticket_status.png",
+            content_type="image/png",
+        )
+
     caption = "Ticket stats"
 
     if not url:

nephthys/views/home/helper.py

@@ -1,9 +1,7 @@
-import logging
-from time import perf_counter
-
 import pytz
 
 from nephthys.utils.env import env
+from nephthys.utils.performance import perf_timer
 from nephthys.views.home.components.buttons import get_buttons
 from nephthys.views.home.components.header import get_header
 from nephthys.views.home.components.leaderboards import get_leaderboard_view
@@ -13,10 +11,8 @@ from prisma.models import User
 
 
 async def get_helper_view(user: User):
-    time_start = perf_counter()
-    user_info = await env.slack_client.users_info(user=user.slackId)
-    time_user_info = perf_counter()
-    logging.debug(f"Fetched user info in {time_user_info - time_start:.4f} seconds")
+    async with perf_timer("Fetching user info"):
+        user_info = await env.slack_client.users_info(user=user.slackId)
     if not user_info or not (slack_user := user_info.get("user")):
         return get_error_view(
             ":rac_freaking: oops, i couldn't find your info! try again in a bit?"
@@ -24,22 +20,14 @@ async def get_helper_view(user: User):
     tz_string = slack_user.get("tz", "Europe/London")
     tz = pytz.timezone(tz_string)
 
-    pie_chart = await get_ticket_status_pie_chart(tz)
-    time_pie_chart = perf_counter()
-    logging.debug(
-        f"Rendered pie chart in {time_pie_chart - time_user_info:.4f} seconds total"
-    )
-    leaderboard = await get_leaderboard_view()
-    time_leaderboard = perf_counter()
-    logging.debug(
-        f"Generated leaderboard in {time_leaderboard - time_pie_chart:.4f} seconds"
-    )
+    async with perf_timer("Rendering pie chart (total time)"):
+        pie_chart = await get_ticket_status_pie_chart(tz)
+
+    async with perf_timer("Generating leaderboard"):
+        leaderboard = await get_leaderboard_view()
 
     header = get_header()
     btns = get_buttons(user, "dashboard")
-    logging.debug(
-        f"Generated Dashboard view in {perf_counter() - time_start:.4f} seconds total"
-    )
 
     return {
         "type": "home",