From 9f3ec875ac61e63ff9a509f51a1d4a92a7fcb818 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jes=C3=BAs=20Pelay?=
 <45865185+jpelay@users.noreply.github.com>
Date: Thu, 4 Apr 2024 01:30:32 -0400
Subject: [PATCH] =?UTF-8?q?=F0=9F=A7=AA=20Profile=20live=20statistics=20pa?=
 =?UTF-8?q?ge=20(#5365)?=
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Adds a sort of profiling to this page by placing some timers in some key function where I think the slowdown happens. Why is it so hacky? I tried for several hours to use werkzeug's `ProfilerMiddleware` but I think there's a bug with the implementation, as several people have reported in some other tools: https://github.com/jazzband/django-debug-toolbar/issues/1875, https://github.com/jazzband/django-silk/issues/682

I thought that since we didn't need the full-fledged tool and didn't want to spend more time on this, this approach would suffice.
---
 website/statistics.py | 27 +++++++++++++++++++++++----
 1 file changed, 23 insertions(+), 4 deletions(-)

diff --git a/website/statistics.py b/website/statistics.py
index 049514dd899..c242fbaa7e9 100644
--- a/website/statistics.py
+++ b/website/statistics.py
@@ -14,11 +14,18 @@
 from website.flask_helpers import render_template
 from website import querylog
 from website.auth import is_admin, is_teacher, requires_admin, requires_login
-
+from timeit import default_timer as timer
 from .database import Database
 from .website_module import WebsiteModule, route
 from bs4 import BeautifulSoup
 
+import logging
+from logging_config import LOGGING_CONFIG
+from logging.config import dictConfig as logConfig
+
+logConfig(LOGGING_CONFIG)
+logger = logging.getLogger(__name__)
+
 """The Key tuple is used to aggregate the raw data by level, time or username."""
 Key = namedtuple("Key", ["name", "class_"])
 level_key = Key("level", int)
@@ -335,8 +342,11 @@ def __init__(self, db: Database):
         self.MAX_FEED_SIZE = 4
 
     def __selected_levels(self, class_id):
+        start = timer()
         class_customization = get_customizations(self.db, class_id)
         class_overview = class_customization.get('dashboard_customization')
+        end = timer()
+        logger.debug(f'Time taken by __selected_levels {end-start}')
         if class_overview:
             return class_overview.get('selected_levels', [1])
         return [1]
@@ -349,6 +359,7 @@ def __common_errors(self, class_id):
 
     def __all_students(self, class_):
         """Returns a list of all students in a class along with some info."""
+        start = timer()
         students = []
         for student_username in class_.get("students", []):
             programs = self.db.programs_for_user(student_username)
@@ -365,6 +376,8 @@ def __all_students(self, class_):
                     "current_level": programs[0]['level'] if programs else '0'
                 }
             )
+        end = timer()
+        logger.debug(f'Time taken by __all_students {end-start}')
         return students
 
     def __get_adventures_for_overview(self, user, class_id):
@@ -440,6 +453,7 @@ def render_live_stats(self, user, class_id):
         )
 
     def get_class_live_stats(self, user, class_):
+        start = timer()
         # Retrieve common errors and selected levels in class overview from the database for class
         selected_levels = self.__selected_levels(class_['id'])
         if selected_levels:
@@ -476,7 +490,8 @@ def get_class_live_stats(self, user, class_):
                     programs_for_student[_student] = adventures_for_student
             if programs_for_student != []:
                 attempted_adventures[level] = programs_for_student
-
+        end = timer()
+        logger.debug(f'Time taken by get_class_live_stats {end-start}')
         return students, common_errors, selected_levels, quiz_info, attempted_adventures, adventures
 
     @route("/live_stats/class/<class_id>/select_level", methods=["GET"])
@@ -810,6 +825,7 @@ def retrieve_exceptions_per_student(self, class_id):
         :param class_id: class id
         :return: exceptions_per_user
         """
+        start = timer()
         class_ = self.db.get_class(class_id)
         exceptions_per_user = {}
         students = sorted(class_.get("students", []))
@@ -820,7 +836,8 @@ def retrieve_exceptions_per_student(self, class_id):
                 program_stats = program_stats[-1]
                 exceptions = {k: v for k, v in program_stats.items() if k.lower().endswith("exception")}
                 exceptions_per_user[student_username] = exceptions
-
+        end = timer()
+        logger.debug(f'Tike taken by retrieve_exceptions_per_student {end-start}')
         return exceptions_per_user
 
     def new_id_calc(self, common_errors, class_id):
@@ -856,6 +873,7 @@ def common_exception_detection(self, class_id, user):
         """
         Detects misconceptions of students in the class based on errors they are making.
         """
+        start = timer()
         common_errors = self.__common_errors(class_id)
         # Group the error messages by session and count their occurrences
         exceptions_per_user = self.retrieve_exceptions_per_student(class_id)  # retrieves relevant data from db
@@ -913,7 +931,8 @@ def common_exception_detection(self, class_id, user):
                     'active': 1,
                     "students": users_only
                 })
-
+        end = timer()
+        logger.debug(f'Time taken by common_exception_detection {end-start}')
         return self.db.update_class_errors(common_errors)
 
     @route("/live_stats/class/<class_id>", methods=["POST"])