From c83871a35a279df57c72f8822205c2345e8819f1 Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 00:28:16 +0000 Subject: [PATCH 1/7] Add a bunch of performance logs to on_message --- nephthys/events/message.py | 37 +++++++++++++++++++++++++++++++++++++ nephthys/utils/slack.py | 5 +++++ 2 files changed, 42 insertions(+) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index 5d73b32..fa3eb51 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -1,5 +1,6 @@ import logging from datetime import datetime +from time import perf_counter from typing import Any from typing import Dict @@ -25,10 +26,13 @@ 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() user = event.get("user", "unknown") text = event.get("text", "") db_user = await env.db.user.find_first(where={"slackId": user}) + db_lookup_time = perf_counter() + logging.info(f"on_message: DB lookup took {db_lookup_time - start_time:.2f}s") # 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): @@ -80,10 +84,19 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): }, ) return + special_cases_time = perf_counter() + logging.info( + f"on_message: Special cases took {special_cases_time - db_lookup_time:.2f}s" + ) thread_url = f"https://hackclub.slack.com/archives/{env.slack_help_channel}/p{event['ts'].replace('.', '')}" db_user = await env.db.user.find_first(where={"slackId": user}) + db_lookup_2_time = perf_counter() + logging.info( + f"on_message: 2nd DB lookup took {db_lookup_2_time - special_cases_time:.2f}s" + ) + if db_user: past_tickets = await env.db.ticket.count(where={"openedById": db_user.id}) else: @@ -106,8 +119,16 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): "update": {"slackId": user, "username": username}, }, ) + db_count_time = perf_counter() + logging.info( + f"on_message: Getting ticket count/updating user DB took {db_count_time - db_lookup_2_time:.2f}s" + ) user_info_response = await client.users_info(user=user) or {} + slack_user_info_time = perf_counter() + logging.info( + f"on_message: Slack user info fetch took {slack_user_info_time - db_count_time:.2f}s" + ) user_info = user_info_response.get("user") profile_pic = None display_name = "Explorer" @@ -144,6 +165,10 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): unfurl_links=True, unfurl_media=True, ) + ticket_message_time = perf_counter() + logging.info( + f"on_message: Sending ticket message took {ticket_message_time - slack_user_info_time:.2f}s" + ) ticket_message_ts = ticket_message["ts"] if not ticket_message_ts: @@ -173,6 +198,10 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): else: data = await res.json() title = data["choices"][0]["message"]["content"].strip() + ai_response_time = perf_counter() + logging.info( + f"on_message: AI title generation took {ai_response_time - ticket_message_time:.2f}s" + ) user_facing_message_text = ( env.transcript.first_ticket_create.replace("(user)", display_name) @@ -215,6 +244,10 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): unfurl_links=True, unfurl_media=True, ) + user_facing_message_time = perf_counter() + logging.info( + f"on_message: Sending FAQ message took {user_facing_message_time - ai_response_time:.2f}s" + ) user_facing_message_ts = user_facing_message["ts"] if not user_facing_message_ts: @@ -236,6 +269,10 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): }, }, ) + ticket_creation_time = perf_counter() + logging.info( + f"on_message: Ticket creation in DB took {ticket_creation_time - user_facing_message_time:.2f}s" + ) try: await client.reactions_add( diff --git a/nephthys/utils/slack.py b/nephthys/utils/slack.py index b6ecce5..ac44147 100644 --- a/nephthys/utils/slack.py +++ b/nephthys/utils/slack.py @@ -1,4 +1,5 @@ import logging +from time import perf_counter from typing import Any from typing import Dict @@ -27,6 +28,7 @@ @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" @@ -36,6 +38,9 @@ async def handle_message(event: Dict[str, Any], client: AsyncWebClient): 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" + ) @app.action("mark_resolved") From d36a7ddb27dd31b13ce56e8b6bdb81c32929129a Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 00:30:24 +0000 Subject: [PATCH 2/7] Remove duplicate DB user lookup --- nephthys/events/message.py | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index fa3eb51..98d2734 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -91,12 +91,6 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): thread_url = f"https://hackclub.slack.com/archives/{env.slack_help_channel}/p{event['ts'].replace('.', '')}" - db_user = await env.db.user.find_first(where={"slackId": user}) - db_lookup_2_time = perf_counter() - logging.info( - f"on_message: 2nd DB lookup took {db_lookup_2_time - special_cases_time:.2f}s" - ) - if db_user: past_tickets = await env.db.ticket.count(where={"openedById": db_user.id}) else: @@ -121,7 +115,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) db_count_time = perf_counter() logging.info( - f"on_message: Getting ticket count/updating user DB took {db_count_time - db_lookup_2_time:.2f}s" + f"on_message: Getting ticket count/updating user DB took {db_count_time - special_cases_time:.2f}s" ) user_info_response = await client.users_info(user=user) or {} From 775103408854b95e28c29361320436bd0df399e8 Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 00:34:33 +0000 Subject: [PATCH 3/7] Ensure Slack user info is only fetched once --- nephthys/events/message.py | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index 98d2734..9de1cf6 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -90,15 +90,20 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) thread_url = f"https://hackclub.slack.com/archives/{env.slack_help_channel}/p{event['ts'].replace('.', '')}" + user_info_response = await client.users_info(user=user) or {} + slack_user_info_time = perf_counter() + logging.info( + f"on_message: Slack user info fetch took {slack_user_info_time - special_cases_time:.2f}s" + ) + user_info = user_info_response.get("user") if db_user: past_tickets = await env.db.ticket.count(where={"openedById": db_user.id}) else: past_tickets = 0 - user_info = await client.users_info(user=user) or {} - username = user_info.get("user", {})[ + username = (user_info or {}).get( "name" - ] # this should never actually be empty but if it is, that is a major issue + ) # this should never actually be empty but if it is, that is a major issue if not username: await send_heartbeat( @@ -115,15 +120,9 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) db_count_time = perf_counter() logging.info( - f"on_message: Getting ticket count/updating user DB took {db_count_time - special_cases_time:.2f}s" + f"on_message: Getting ticket count/updating user DB took {db_count_time - slack_user_info_time:.2f}s" ) - user_info_response = await client.users_info(user=user) or {} - slack_user_info_time = perf_counter() - logging.info( - f"on_message: Slack user info fetch took {slack_user_info_time - db_count_time:.2f}s" - ) - user_info = user_info_response.get("user") profile_pic = None display_name = "Explorer" if user_info: From 2b3b672528073b295011a5f9acaf8c36b888fc72 Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 00:37:23 +0000 Subject: [PATCH 4/7] Make AI title generation happen after the FAQ message has been sent --- nephthys/events/message.py | 63 ++++++++++++++++++++------------------ 1 file changed, 34 insertions(+), 29 deletions(-) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index 9de1cf6..be20d6c 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -168,34 +168,6 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): logging.error(f"Ticket message has no ts: {ticket_message}") return - async with env.session.post( - "https://ai.hackclub.com/chat/completions", - json={ - "messages": [ - { - "role": "system", - "content": "You are a helpful assistant that helps organise tickets for Hack Club's support team. You're going to take in a message and give it a title. You will return no other content. Even if it's silly please summarise it. Use no more than 7 words, but as few as possible.", - }, - { - "role": "user", - "content": f"Here is a message from a user: {text}\n\nPlease give this ticket a title.", - }, - ] - }, - ) as res: - if res.status != 200: - await send_heartbeat( - f"Failed to get AI response for ticket creation: {res.status} - {await res.text()}" - ) - title = "No title provided by AI." - else: - data = await res.json() - title = data["choices"][0]["message"]["content"].strip() - ai_response_time = perf_counter() - logging.info( - f"on_message: AI title generation took {ai_response_time - ticket_message_time:.2f}s" - ) - user_facing_message_text = ( env.transcript.first_ticket_create.replace("(user)", display_name) if past_tickets == 0 @@ -239,7 +211,13 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) user_facing_message_time = perf_counter() logging.info( - f"on_message: Sending FAQ message took {user_facing_message_time - ai_response_time:.2f}s" + f"on_message: Sending FAQ message took {user_facing_message_time - ticket_message_time:.2f}s" + ) + + title = await generate_ticket_title(text) + ai_response_time = perf_counter() + logging.info( + f"on_message: AI title generation took {ai_response_time - user_facing_message_time:.2f}s" ) user_facing_message_ts = user_facing_message["ts"] @@ -288,3 +266,30 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): await send_heartbeat( f"Successfully pinged uptime URL: {res.status} - {await res.text()}" ) + + +async def generate_ticket_title(text): + async with env.session.post( + "https://ai.hackclub.com/chat/completions", + json={ + "messages": [ + { + "role": "system", + "content": "You are a helpful assistant that helps organise tickets for Hack Club's support team. You're going to take in a message and give it a title. You will return no other content. Even if it's silly please summarise it. Use no more than 7 words, but as few as possible.", + }, + { + "role": "user", + "content": f"Here is a message from a user: {text}\n\nPlease give this ticket a title.", + }, + ] + }, + ) as res: + if res.status != 200: + await send_heartbeat( + f"Failed to get AI response for ticket creation: {res.status} - {await res.text()}" + ) + title = "No title provided by AI." + else: + data = await res.json() + title = data["choices"][0]["message"]["content"].strip() + return title From 97576cf4c064ed2616350b74ad803b0711c87ffa Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 00:59:28 +0000 Subject: [PATCH 5/7] Make the performance logging debug-level --- nephthys/events/message.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index be20d6c..2395fa7 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -32,7 +32,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): db_user = await env.db.user.find_first(where={"slackId": user}) db_lookup_time = perf_counter() - logging.info(f"on_message: DB lookup took {db_lookup_time - start_time:.2f}s") + logging.debug(f"on_message: DB lookup took {db_lookup_time - start_time:.2f}s") # 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): @@ -85,14 +85,14 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) return special_cases_time = perf_counter() - logging.info( + logging.debug( f"on_message: Special cases took {special_cases_time - db_lookup_time:.2f}s" ) thread_url = f"https://hackclub.slack.com/archives/{env.slack_help_channel}/p{event['ts'].replace('.', '')}" user_info_response = await client.users_info(user=user) or {} slack_user_info_time = perf_counter() - logging.info( + logging.debug( f"on_message: Slack user info fetch took {slack_user_info_time - special_cases_time:.2f}s" ) user_info = user_info_response.get("user") @@ -119,7 +119,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): }, ) db_count_time = perf_counter() - logging.info( + logging.debug( f"on_message: Getting ticket count/updating user DB took {db_count_time - slack_user_info_time:.2f}s" ) @@ -159,7 +159,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): unfurl_media=True, ) ticket_message_time = perf_counter() - logging.info( + logging.debug( f"on_message: Sending ticket message took {ticket_message_time - slack_user_info_time:.2f}s" ) @@ -210,13 +210,13 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): unfurl_media=True, ) user_facing_message_time = perf_counter() - logging.info( + logging.debug( f"on_message: Sending FAQ message took {user_facing_message_time - ticket_message_time:.2f}s" ) title = await generate_ticket_title(text) ai_response_time = perf_counter() - logging.info( + logging.debug( f"on_message: AI title generation took {ai_response_time - user_facing_message_time:.2f}s" ) @@ -241,7 +241,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): }, ) ticket_creation_time = perf_counter() - logging.info( + logging.debug( f"on_message: Ticket creation in DB took {ticket_creation_time - user_facing_message_time:.2f}s" ) From 5aec9daf8791fd35088cedeeac5983614bee3474 Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 19:57:55 +0000 Subject: [PATCH 6/7] Fix some perf calculations being incorrect --- nephthys/events/message.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index 2395fa7..e250f44 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -160,7 +160,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) ticket_message_time = perf_counter() logging.debug( - f"on_message: Sending ticket message took {ticket_message_time - slack_user_info_time:.2f}s" + f"on_message: Sending ticket message took {ticket_message_time - db_count_time:.2f}s" ) ticket_message_ts = ticket_message["ts"] @@ -242,7 +242,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) ticket_creation_time = perf_counter() logging.debug( - f"on_message: Ticket creation in DB took {ticket_creation_time - user_facing_message_time:.2f}s" + f"on_message: Ticket creation in DB took {ticket_creation_time - ai_response_time:.2f}s" ) try: From d8e9ea035d5f99da6466d3046f1936d5413793ba Mon Sep 17 00:00:00 2001 From: MMK21Hub <50421330+MMK21Hub@users.noreply.github.com> Date: Mon, 27 Oct 2025 19:58:40 +0000 Subject: [PATCH 7/7] Add type hint --- nephthys/events/message.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/nephthys/events/message.py b/nephthys/events/message.py index e250f44..89aa255 100644 --- a/nephthys/events/message.py +++ b/nephthys/events/message.py @@ -268,7 +268,7 @@ async def on_message(event: Dict[str, Any], client: AsyncWebClient): ) -async def generate_ticket_title(text): +async def generate_ticket_title(text: str): async with env.session.post( "https://ai.hackclub.com/chat/completions", json={