diff --git a/aiarena/api/arenaclient/common/ac_coordinator.py b/aiarena/api/arenaclient/common/ac_coordinator.py index be03dc5b0..1082f8a2c 100644 --- a/aiarena/api/arenaclient/common/ac_coordinator.py +++ b/aiarena/api/arenaclient/common/ac_coordinator.py @@ -12,7 +12,6 @@ from aiarena.core.models import ArenaClient import logging -import time from django.db import connection, transaction from django.db.models.signals import pre_save @@ -33,9 +32,6 @@ logger = logging.getLogger(__name__) -loggerECS = logging.getLogger("aiarena") - -threshold_logger = 3 class ACCoordinator: @@ -43,30 +39,18 @@ class ACCoordinator: @staticmethod def next_requested_match(arenaclient: ArenaClient): - t = time.monotonic() # REQUESTED MATCHES with transaction.atomic(): match = matches.attempt_to_start_a_requested_match(arenaclient) if match is not None: - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ACCoordinator next_requested_match took %.3fs | match=%s", - time.monotonic() - t, - getattr(match, "id", None), - ) return match # a match was found - we're done return None @staticmethod def next_competition_match(arenaclient: ArenaClient): - t = time.monotonic() competition_ids = ACCoordinator._get_competition_priority_order() - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ACCoordinator _get_competition_priority_order took %.3fs", - time.monotonic() - t, - ) + for id in competition_ids: competition = Competition.objects.get(id=id) # This excludes non-trusted clients from competitions requiring trusted infrastructure @@ -75,22 +59,9 @@ def next_competition_match(arenaclient: ArenaClient): with transaction.atomic(): # this call will apply a select for update, so we do it inside an atomic block has_matches = competitions.check_has_matches_to_play_and_apply_locks(competition) - if time.monotonic() - t > 3: - loggerECS.warning( - "Slow request - ACCoordinator check_has_matches_to_play_and_apply_locks took %.3fs | competition=%s", - time.monotonic() - t, - competition.id, - ) if has_matches: try: match = matches.start_next_match_for_competition(arenaclient, competition) - if time.monotonic() - t > 3: - loggerECS.warning( - "Slow request - ACCoordinator start_next_match_for_competition took %.3fs | competition=%s | match=%s", - time.monotonic() - t, - competition.id, - getattr(match, "id", None), - ) return match except ( NoMaps, @@ -106,20 +77,13 @@ def next_competition_match(arenaclient: ArenaClient): @staticmethod def next_new_match(arenaclient: ArenaClient): - t = time.monotonic() requested_match = ACCoordinator.next_requested_match(arenaclient) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ACCoordinator next_new_match next_requested_match took %.3fs", - time.monotonic() - t, - ) if requested_match is not None: return requested_match return ACCoordinator.next_competition_match(arenaclient) @staticmethod def next_match(arenaclient: ArenaClient, only_unfinished_matches: bool) -> Match | None: - t = time.monotonic() if not config.LADDER_ENABLED: raise LadderDisabled() @@ -134,20 +98,12 @@ def next_match(arenaclient: ArenaClient, only_unfinished_matches: bool) -> Match ) .order_by("round_id") ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ACCoordinator next_match Match.objects.only took %.3fs", - time.monotonic() - t, - ) + if len(unfinished_matches) > 0: return unfinished_matches[0] # todo: re-set started time? if only_unfinished_matches: return None # Return None so we don't try to start a new match - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ACCoordinator next_match total took %.3fs", - time.monotonic() - t, - ) + # Trying a new match return ACCoordinator.next_new_match(arenaclient) diff --git a/aiarena/api/arenaclient/common/result_submission_handler.py b/aiarena/api/arenaclient/common/result_submission_handler.py index 2996a84fb..a440bad78 100644 --- a/aiarena/api/arenaclient/common/result_submission_handler.py +++ b/aiarena/api/arenaclient/common/result_submission_handler.py @@ -1,5 +1,4 @@ import logging -import time from dataclasses import dataclass from typing import Any @@ -30,23 +29,13 @@ logger = logging.getLogger(__name__) -loggerECS = logging.getLogger("aiarena") - -threshold_logger = 3 def handle_result_submission(match_id, result_data): - t = time.monotonic() with transaction.atomic(): match = Match.objects.prefetch_related( Prefetch("matchparticipation_set", MatchParticipation.objects.all().select_related("bot")) ).get(id=match_id) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - handle_result_submission get Match took %.3fs | match_id=%s", - time.monotonic() - t, - match_id=match_id, - ) # validate result result = SubmitResultResultSerializer( @@ -60,12 +49,6 @@ def handle_result_submission(match_id, result_data): } ) result.is_valid(raise_exception=True) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - handle_result_submission validate result took %.3fs | match_id=%s", - time.monotonic() - t, - match_id=match_id, - ) # validate participants p1_instance = match.matchparticipation_set.get(participant_number=1) @@ -93,12 +76,6 @@ def handle_result_submission(match_id, result_data): partial=True, ) participant2.is_valid(raise_exception=True) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - handle_result_submission validate participants took %.3fs | match_id=%s", - time.monotonic() - t, - match_id=match_id, - ) result_submission = ResultSubmission( match=match, diff --git a/aiarena/api/arenaclient/common/views.py b/aiarena/api/arenaclient/common/views.py index 618cb8296..b72ee99b5 100644 --- a/aiarena/api/arenaclient/common/views.py +++ b/aiarena/api/arenaclient/common/views.py @@ -1,5 +1,4 @@ import logging -import time from wsgiref.util import FileWrapper from django.core.cache import cache @@ -28,9 +27,6 @@ logger = logging.getLogger(__name__) -loggerECS = logging.getLogger("aiarena") - -threshold_logger = 3 class MatchViewSet(viewsets.GenericViewSet): @@ -59,83 +55,23 @@ def load_participants(self, match: Match): ) def create(self, request, *args, **kwargs): - total_start = time.monotonic() - user_id = getattr(request.user, "id", "AnonymousUser") - - try: - t = time.monotonic() - no_game_available = cache.get("NoGameAvailable", False) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - next-match cache.get took %.3fs | user=%s | no_game_available=%s", - time.monotonic() - t, - user_id, - no_game_available, - ) - - if request.user.is_arenaclient: - t = time.monotonic() - match = ACCoordinator.next_match(request.user.arenaclient, no_game_available) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - next-match ACCoordinator.next_match took %.3fs | user=%s | match=%s", - time.monotonic() - t, - user_id, - getattr(match, "id", None), - ) - - if match: - t = time.monotonic() - self.load_participants(match) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - next-match load_participants took %.3fs | user=%s | match=%s", - time.monotonic() - t, - user_id, - match.id, - ) - - t = time.monotonic() - serializer = self.get_serializer(match) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - next-match get_serializer took %.3fs | user=%s | match=%s", - time.monotonic() - t, - user_id, - match.id, - ) - - t = time.monotonic() - data = serializer.data - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - next-match serializer.data took %.3fs | user=%s | match=%s", - time.monotonic() - t, - user_id, - match.id, - ) - - return Response(data, status=status.HTTP_201_CREATED) - - else: - if not no_game_available: - t = time.monotonic() - cache.set("NoGameAvailable", True, config.GAME_AVAILABLE_CACHE_TIME) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - next-match cache.set took %.3fs | user=%s", - time.monotonic() - t, - user_id, - ) + no_game_available = cache.get("NoGameAvailable", False) - raise NoGameForClient() + if request.user.is_arenaclient: + match = ACCoordinator.next_match(request.user.arenaclient, no_game_available) - finally: - loggerECS.warning( - "Slow request - next-match create total %.3fs | user=%s", - time.monotonic() - total_start, - user_id, - ) + if match: + self.load_participants(match) + + serializer = self.get_serializer(match) + + return Response(data=serializer.data, status=status.HTTP_201_CREATED) + + else: + if not no_game_available: + cache.set("NoGameAvailable", True, config.GAME_AVAILABLE_CACHE_TIME) + + raise NoGameForClient() # todo: check match is in progress/bot is in this match @action( @@ -183,7 +119,6 @@ class ResultViewSet(mixins.CreateModelMixin, viewsets.GenericViewSet): swagger_schema = None # exclude this from swagger generation def create(self, request, *args, **kwargs): - t = time.monotonic() if not config.LADDER_ENABLED: raise LadderDisabled() @@ -210,19 +145,7 @@ def create(self, request, *args, **kwargs): f"bot2_data: {serializer.validated_data.get('bot2_data')} " f"bot2_tags: {serializer.validated_data.get('bot2_tags')} " ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ResultViewSet get_serializer took %.3fs", - time.monotonic() - t, - ) - t = time.monotonic() result = handle_result_submission(match_id, serializer.validated_data) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - ResultViewSet handle_result_submission took %.3fs", - time.monotonic() - t, - ) - t = time.monotonic() headers = self.get_success_headers(serializer.data) return Response({"result_id": result.id}, status=status.HTTP_201_CREATED, headers=headers) diff --git a/aiarena/core/management/commands/export_parquet.py b/aiarena/core/management/commands/export_parquet.py new file mode 100644 index 000000000..0ef061550 --- /dev/null +++ b/aiarena/core/management/commands/export_parquet.py @@ -0,0 +1,427 @@ +import re +from pathlib import Path +from uuid import UUID + +from django.core.management.base import BaseCommand, CommandError + +import pandas as pd + +from aiarena.core.models import ( + Bot, + BotRace, + Competition, + Game, + GameMode, + Map, + Match, + MatchParticipation, + MatchTag, + Result, + Round, + Tag, +) + + +# Exports competition or a users requested matches to parquet. +# Data is sanitized to remove sensitive information. + +# Exporting 'by year' counts from the end date of a competition. +# If a competition is started in 2025 but ends in 2026, it will be included in exports for 2026 but not 2025. + +# Usage: +# - Export a specific competition: `python manage.py export_parquet competition ` +# - Export all competitions closed in a specific year: `python manage.py export_parquet all_competitions ` +# - Export matches requested by a specific user in a specific year: `python manage.py export_parquet requested ` +# - Export all requested matches in a specific year: `python manage.py export_parquet all_requests ` + +GAME_FIELDS = ["id", "name", "map_file_extension"] +GAME_MODE_FIELDS = ["id", "name", "game_id", "game__name"] + +COMPETITION_FIELDS = [ + "id", + "name", + "game_mode_id", + "game_mode__name", + "game_mode__game_id", + "game_mode__game__name", + "date_created", + "date_opened", + "date_closed", + "status", + "max_active_rounds", + "interest", + "target_n_divisions", + "n_divisions", + "target_division_size", + "rounds_per_cycle", + "rounds_this_cycle", + "n_placements", + "require_trusted_infrastructure", + "statistics_finalized", + "competition_finalized", + "indepth_bot_statistics_enabled", +] + +PLAYABLE_RACE_FIELDS = ["id", "label"] +MAP_FIELDS = ["id", "name", "game_mode_id", "game_mode__name", "enabled"] +ROUND_FIELDS = ["id", "number", "competition_id", "started", "finished", "complete"] + +MATCH_FIELDS = [ + "id", + "result_id", + "map_id", + "map__name", + "created", + "started", + "first_started", + "round_id", + "assigned_to_id", + "assigned_to__username", + "requested_by_id", + "requested_by__username", + "require_trusted_arenaclient", +] + +RESULT_FIELDS = [ + "id", + "type", + "created", + "winner_id", + "winner__name", + "winner__game_display_id", + "winner__plays_race_id", + "winner__plays_race__label", + "game_steps", + "submitted_by_id", + "submitted_by__username", + "replay_file_has_been_cleaned", + "arenaclient_log_has_been_cleaned", +] + +MATCH_MATCH_TAG_FIELDS = ["match_id", "matchtag_id"] +MATCH_TAG_FIELDS = ["id", "tag_id", "tag__name", "user_id", "user__username"] +TAG_FIELDS = ["id", "name"] + +MATCH_PARTICIPATION_FIELDS = [ + "id", + "match_id", + "participant_number", + "bot_id", + "bot__name", + "bot__game_display_id", + "bot__plays_race_id", + "bot__plays_race__label", + "bot__type", + "bot__user_id", + "bot__user__username", + "starting_elo", + "resultant_elo", + "elo_change", + "avg_step_time", + "result", + "result_cause", + "use_bot_data", + "update_bot_data", + "match_log_has_been_cleaned", +] + +BOT_FIELDS = [ + "id", + "name", + "created", + "plays_race_id", + "plays_race__label", + "type", + "game_display_id", + "user_id", + "user__username", + "bot_zip_publicly_downloadable", + "bot_data_enabled", + "bot_data_publicly_downloadable", +] + + +class Command(BaseCommand): + help = "Export competition or requested bot matches to sanitized Parquet." + + def add_arguments(self, parser): + subparsers = parser.add_subparsers(dest="mode", required=True) + + competition_parser = subparsers.add_parser("competition") + competition_parser.add_argument("competition_id", type=int) + + all_competitions_parser = subparsers.add_parser("all_competitions") + all_competitions_parser.add_argument("year", type=int) + + requested_parser = subparsers.add_parser("requested") + requested_parser.add_argument("user_id", type=int) + requested_parser.add_argument("year", type=int) + + all_requests_parser = subparsers.add_parser("all_requests") + all_requests_parser.add_argument("year", type=int) + + parser.add_argument("--output-dir", default="exports") + + def write_parquet(self, qs, path, fields): + rows = list(qs) + df = pd.DataFrame.from_records(rows, columns=fields) + + for column in df.columns: + if df[column].map(lambda value: isinstance(value, UUID)).any(): + df[column] = df[column].map(lambda value: str(value) if value is not None else None) + + df.to_parquet(path, index=False) + + row_count = len(df) + self.stdout.write(f"{path.name}: {row_count} rows") + + return row_count + + def safe_name(self, value): + value = value.strip().lower() + value = re.sub(r"[^a-z0-9_-]+", "_", value) + return value.strip("_") or "unknown" + + def handle(self, *args, **options): + mode = options["mode"] + base_output_dir = Path(options["output_dir"]) + + if mode == "competition": + self.export_competition( + options["competition_id"], + base_output_dir, + ) + + elif mode == "all_competitions": + self.export_all_competitions( + options["year"], + base_output_dir, + ) + + elif mode == "requested": + self.export_requested_matches( + options["user_id"], + options["year"], + base_output_dir, + ) + + elif mode == "all_requests": + self.export_all_requested_matches( + options["year"], + base_output_dir, + ) + + else: + raise CommandError("Unknown mode") + + def export_competition(self, competition_id, base_output_dir): + output_dir = base_output_dir / f"competition_{competition_id}" + output_dir.mkdir(parents=True, exist_ok=True) + + competition = Competition.objects.get(id=competition_id) + + if competition.playable_races.exists(): + playable_races_qs = competition.playable_races.values(*PLAYABLE_RACE_FIELDS) + else: + playable_races_qs = BotRace.objects.all().values(*PLAYABLE_RACE_FIELDS) + + rounds = Round.objects.filter(competition_id=competition_id) + matches = Match.objects.filter(round__competition_id=competition_id) + + ds = self.export_match_dataset( + output_dir=output_dir, + matches=matches, + rounds=rounds, + playable_races_qs=playable_races_qs, + competition_qs=Competition.objects.filter(id=competition_id), + success_message=f"Finished sanitized Parquet export for competition {competition_id}", + ) + return ds + + def export_all_competitions(self, year, base_output_dir): + competitions = Competition.objects.filter( + date_closed__year=year, + ).order_by("id") + total_rows = 0 + exported_competitions = [] + + for competition in competitions: + self.stdout.write( + self.style.HTTP_INFO(f"Starting export for competition {competition.id} ({competition.name})") + ) + + rows_exported = self.export_competition( + competition.id, + base_output_dir, + ) + + total_rows += rows_exported or 0 + + exported_competitions.append( + { + "id": competition.id, + "name": competition.name, + } + ) + + self.stdout.write("") + self.stdout.write( + self.style.SUCCESS( + f"Finished sanitized Parquet export for {len(exported_competitions)} competitions closed in {year}" + ) + ) + + self.stdout.write("") + self.stdout.write(self.style.SUCCESS("Exported competitions:")) + + for competition in exported_competitions: + self.stdout.write(f"- {competition['id']}: {competition['name']}") + + self.stdout.write(self.style.SUCCESS(f"Total exported rows across all competitions: {total_rows:,}")) + + def export_requested_matches(self, user_id, year, base_output_dir): + output_dir = base_output_dir / "requested_matches" / f"user_{user_id}" / str(year) + output_dir.mkdir(parents=True, exist_ok=True) + + matches = Match.objects.filter( + requested_by_id=user_id, + created__year=year, + ).distinct() + + self.export_match_dataset( + output_dir=output_dir, + matches=matches, + rounds=Round.objects.none(), + playable_races_qs=BotRace.objects.all().values(*PLAYABLE_RACE_FIELDS), + competition_qs=Competition.objects.none(), + success_message=f"Finished sanitized Parquet export for requested matches by user {user_id} in {year}", + ) + + def export_all_requested_matches(self, year, base_output_dir): + total_rows = 0 + exported_users = [] + + all_output_dir = base_output_dir / "requested_matches" / "all_users" / str(year) + all_output_dir.mkdir(parents=True, exist_ok=True) + + all_matches = Match.objects.filter( + requested_by_id__isnull=False, + created__year=year, + ).distinct() + + rows_exported = self.export_match_dataset( + output_dir=all_output_dir, + matches=all_matches, + rounds=Round.objects.none(), + playable_races_qs=BotRace.objects.all().values(*PLAYABLE_RACE_FIELDS), + competition_qs=Competition.objects.none(), + success_message=f"Finished sanitized Parquet export for all requested matches in {year}", + ) + + total_rows += rows_exported or 0 + + user_ids = all_matches.values_list("requested_by_id", flat=True).distinct() + + for user_id in user_ids: + output_dir = base_output_dir / "requested_matches" / f"user_{user_id}" / str(year) + output_dir.mkdir(parents=True, exist_ok=True) + + matches = all_matches.filter( + requested_by_id=user_id, + ).distinct() + + rows_exported = self.export_match_dataset( + output_dir=output_dir, + matches=matches, + rounds=Round.objects.none(), + playable_races_qs=BotRace.objects.all().values(*PLAYABLE_RACE_FIELDS), + competition_qs=Competition.objects.none(), + success_message=f"Finished sanitized Parquet export for requested matches by user {user_id} in {year}", + ) + + total_rows += rows_exported or 0 + + exported_users.append(user_id) + + self.stdout.write("") + self.stdout.write( + self.style.SUCCESS(f"Finished exporting requested matches for {len(exported_users):,} users in {year}") + ) + + self.stdout.write("") + self.stdout.write(self.style.SUCCESS("Exported users:")) + + for user_id in exported_users: + self.stdout.write(f"- user_{user_id}") + + self.stdout.write(self.style.SUCCESS(f"Total exported rows across all requested exports: {total_rows:,}")) + + def export_match_dataset( + self, + output_dir, + matches, + rounds, + playable_races_qs, + competition_qs, + success_message, + ): + total_rows = 0 + + result_ids = matches.exclude(result_id__isnull=True).values_list("result_id", flat=True) + results = Result.objects.filter(id__in=result_ids) + + participations = MatchParticipation.objects.filter(match_id__in=matches.values_list("id", flat=True)) + + match_ids = matches.values_list("id", flat=True) + bot_ids = participations.values_list("bot_id", flat=True).distinct() + + map_ids = matches.values_list("map_id", flat=True).distinct() + maps = Map.objects.filter(id__in=map_ids) + + game_mode_ids = maps.values_list("game_mode_id", flat=True).distinct() + game_modes = GameMode.objects.filter(id__in=game_mode_ids) + game_ids = game_modes.values_list("game_id", flat=True).distinct() + + bots = Bot.objects.filter(id__in=bot_ids) + + match_match_tags = Match.tags.through.objects.filter(match_id__in=match_ids) + match_tag_ids = match_match_tags.values_list("matchtag_id", flat=True).distinct() + + match_tags = MatchTag.objects.filter(id__in=match_tag_ids) + tag_ids = match_tags.values_list("tag_id", flat=True).distinct() + + total_rows += self.write_parquet( + Game.objects.filter(id__in=game_ids).values(*GAME_FIELDS), output_dir / "games.parquet", GAME_FIELDS + ) + total_rows += self.write_parquet( + game_modes.values(*GAME_MODE_FIELDS), output_dir / "game_modes.parquet", GAME_MODE_FIELDS + ) + total_rows += self.write_parquet( + competition_qs.values(*COMPETITION_FIELDS), output_dir / "competitions.parquet", COMPETITION_FIELDS + ) + total_rows += self.write_parquet(playable_races_qs, output_dir / "playable_races.parquet", PLAYABLE_RACE_FIELDS) + total_rows += self.write_parquet(maps.values(*MAP_FIELDS), output_dir / "maps.parquet", MAP_FIELDS) + total_rows += self.write_parquet(rounds.values(*ROUND_FIELDS), output_dir / "rounds.parquet", ROUND_FIELDS) + total_rows += self.write_parquet(matches.values(*MATCH_FIELDS), output_dir / "matches.parquet", MATCH_FIELDS) + total_rows += self.write_parquet(results.values(*RESULT_FIELDS), output_dir / "results.parquet", RESULT_FIELDS) + total_rows += self.write_parquet( + match_match_tags.values(*MATCH_MATCH_TAG_FIELDS), + output_dir / "match_match_tags.parquet", + MATCH_MATCH_TAG_FIELDS, + ) + total_rows += self.write_parquet( + match_tags.values(*MATCH_TAG_FIELDS), output_dir / "match_tags.parquet", MATCH_TAG_FIELDS + ) + total_rows += self.write_parquet( + Tag.objects.filter(id__in=tag_ids).values(*TAG_FIELDS), output_dir / "tags.parquet", TAG_FIELDS + ) + total_rows += self.write_parquet( + participations.values(*MATCH_PARTICIPATION_FIELDS), + output_dir / "match_participations.parquet", + MATCH_PARTICIPATION_FIELDS, + ) + total_rows += self.write_parquet(bots.values(*BOT_FIELDS), output_dir / "bots_sanitized.parquet", BOT_FIELDS) + + self.stdout.write(self.style.SUCCESS(f"{success_message} | Total exported rows: {total_rows:,}")) + + return total_rows diff --git a/aiarena/core/services/service_implementations/_matches.py b/aiarena/core/services/service_implementations/_matches.py index be719915a..e97e40018 100644 --- a/aiarena/core/services/service_implementations/_matches.py +++ b/aiarena/core/services/service_implementations/_matches.py @@ -1,6 +1,5 @@ import logging import random -import time from django.db import transaction from django.db.models import Count, Max @@ -36,9 +35,6 @@ logger = logging.getLogger(__name__) -loggerECS = logging.getLogger("aiarena") - -threshold_logger = 3 class Matches: @@ -74,7 +70,6 @@ def timeout_overtime_bot_games(self): def attempt_to_start_a_requested_match(self, requesting_ac: ArenaClient): # Try get a requested match # Do we want trusted clients to run games not requiring trusted clients? - t = time.monotonic() matches = ( Match.objects.select_related("round") .only("started", "assigned_to", "round") @@ -82,19 +77,9 @@ def attempt_to_start_a_requested_match(self, requesting_ac: ArenaClient): .select_for_update(of=("self",)) .order_by("created") ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches attempt_to_start_a_requested_match took %.3fs ", - time.monotonic() - t, - ) + if matches.count() > 0: - t = time.monotonic() match = self._start_and_return_a_match(requesting_ac, matches) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _start_and_return_a_match took %.3fs ", - time.monotonic() - t, - ) return match else: return None @@ -108,7 +93,6 @@ def _start_and_return_a_match(self, requesting_ac: ArenaClient, matches): def _attempt_to_start_a_ladder_match(self, requesting_ac: ArenaClient, for_round): assert requesting_ac is not None assert for_round is not None - t = time.monotonic() ladder_matches_to_play = list( Match.objects.raw( """ @@ -121,15 +105,8 @@ def _attempt_to_start_a_ladder_match(self, requesting_ac: ArenaClient, for_round (for_round.id,), ) ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_start_a_ladder_match Match.objects.raw took %.3fs ", - time.monotonic() - t, - ) if len(ladder_matches_to_play) > 0: - t_0 = time.monotonic() - t = time.monotonic() bots_with_a_ladder_match_to_play = ( Bot.objects.exclude( matchparticipation__in=MatchParticipation.objects.filter( @@ -148,14 +125,8 @@ def _attempt_to_start_a_ladder_match(self, requesting_ac: ArenaClient, for_round .distinct() .only("id") ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_start_a_ladder_match bots_with_a_ladder_match_to_play took %.3fs ", - time.monotonic() - t, - ) match_ids = [match.id for match in ladder_matches_to_play] bot_ids = [bot.id for bot in bots_with_a_ladder_match_to_play] - t = time.monotonic() available_ladder_matches_to_play = ( list( Match.objects.raw( @@ -172,40 +143,22 @@ def _attempt_to_start_a_ladder_match(self, requesting_ac: ArenaClient, for_round if bot_ids else [] ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_start_a_ladder_match Match.objects.raw_2 took %.3fs ", - time.monotonic() - t, - ) # Prioritize matches involving bots with data enabled (they can't play concurrent matches) # and bots that have waited the longest since their last match. - t = time.monotonic() if available_ladder_matches_to_play: available_match_ids = [m.id for m in available_ladder_matches_to_play] - t_a = time.monotonic() # Map each match to its participant bot IDs match_bot_map = {} for mp in MatchParticipation.objects.filter(match_id__in=available_match_ids).values( "match_id", "bot_id" ): match_bot_map.setdefault(mp["match_id"], []).append(mp["bot_id"]) - if time.monotonic() - t_a > threshold_logger: - loggerECS.warning( - "Slow request - Matches available_ladder_matches_to_play MatchParticipation.objects.filter took %.3fs ", - time.monotonic() - t_a, - ) - t_a = time.monotonic() + # Identify which available bots have data enabled data_enabled_bot_ids = set( Bot.objects.filter(id__in=bot_ids, bot_data_enabled=True).values_list("id", flat=True) ) - if time.monotonic() - t_a > threshold_logger: - loggerECS.warning( - "Slow request - Matches available_ladder_matches_to_play data_enabled_bot_ids took %.3fs ", - time.monotonic() - t_a, - ) - t_a = time.monotonic() # Get the most recent match start time for each bot last_match_start_times = dict( MatchParticipation.objects.filter( @@ -217,17 +170,6 @@ def _attempt_to_start_a_ladder_match(self, requesting_ac: ArenaClient, for_round .annotate(last_start=Max("match__started")) .values_list("bot_id", "last_start") ) - if time.monotonic() - t_a > threshold_logger: - loggerECS.warning( - "Slow request - Matches available_ladder_matches_to_play last_match_start_times took %.3fs ", - time.monotonic() - t_a, - ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches available_ladder_matches_to_play queries took %.3fs ", - time.monotonic() - t, - ) - # Bots with no previous match get the earliest possible time (highest priority) epoch = timezone.datetime.min.replace(tzinfo=timezone.utc) @@ -248,11 +190,6 @@ def match_sort_key(match): # if, out of the bots that have a ladder match to play, at least 2 are active, then try starting matches. if self.bots_service.available_is_more_than(bots_with_a_ladder_match_to_play, 2): match = self._start_and_return_a_match(requesting_ac, available_ladder_matches_to_play) - if time.monotonic() - t_0 > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_start_a_ladder_match total took %.3fs ", - time.monotonic() - t_0, - ) return match return None @@ -376,7 +313,6 @@ def start_next_match_for_competition(self, requesting_ac: ArenaClient, competiti # LADDER MATCHES # Get rounds with un-started matches # The "IN" is a workaround due to postgresql not allowing "FOR UPDATE" with a DISTINCT clause - t = time.monotonic() rounds = Round.objects.raw( """ SELECT @@ -398,63 +334,27 @@ def start_next_match_for_competition(self, requesting_ac: ArenaClient, competiti FOR UPDATE""", (competition.id,), ) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches start_next_match_for_competition rounds query took %.3fs ", - time.monotonic() - t, - ) - t = time.monotonic() for round in rounds: match = self._attempt_to_start_a_ladder_match(requesting_ac, round) if match is not None: - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_start_a_ladder_match took %.3fs ", - time.monotonic() - t, - ) return match # a match was found - we're done # If none of the previous matches were able to start, and we don't have 2 active bots available, # then we give up. # todo: does this need to be a select_for_update? - t = time.monotonic() active_bots = self.competitions_service.get_active_bots(competition).select_for_update() - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches get_active_bots took %.3fs ", - time.monotonic() - t, - ) if not self.bots_service.available_is_more_than(active_bots, 2): raise NotEnoughAvailableBots() # If we get to here, then we have # - no matches from any existing round we can start # - at least 2 active bots available for play - t = time.monotonic() has_reached_max_active_rounds = self.competitions_service.has_reached_maximum_active_rounds(competition) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches has_reached_maximum_active_rounds took %.3fs ", - time.monotonic() - t, - ) if has_reached_max_active_rounds: raise MaxActiveRounds() else: # generate new round - t = time.monotonic() round = self._attempt_to_generate_new_round(competition) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_generate_new_round took %.3fs ", - time.monotonic() - t, - ) - - t = time.monotonic() match = self._attempt_to_start_a_ladder_match(requesting_ac, round) - if time.monotonic() - t > threshold_logger: - loggerECS.warning( - "Slow request - Matches _attempt_to_start_a_ladder_match took %.3fs ", - time.monotonic() - t, - ) if match is None: raise APIException("Failed to start match. There might not be any available participants.") else: diff --git a/pyproject.toml b/pyproject.toml index 29acf44f1..94f39ad6b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -40,6 +40,7 @@ dependencies = [ "pandas==2.2.2", "pinax-theme-bootstrap==8.0.1", "psycopg2-binary==2.9.9", + "pyarrow==17.0.0", "pytz==2022.7.1", "redis==5.2.1", "sentry-sdk[django]==1.45.1", diff --git a/uv.lock b/uv.lock index 10f44bee3..ea4b00916 100644 --- a/uv.lock +++ b/uv.lock @@ -44,6 +44,7 @@ dependencies = [ { name = "pandas" }, { name = "pinax-theme-bootstrap" }, { name = "psycopg2-binary" }, + { name = "pyarrow" }, { name = "pytz" }, { name = "redis" }, { name = "sentry-sdk", extra = ["django"] }, @@ -111,6 +112,7 @@ requires-dist = [ { name = "pandas", specifier = "==2.2.2" }, { name = "pinax-theme-bootstrap", specifier = "==8.0.1" }, { name = "psycopg2-binary", specifier = "==2.9.9" }, + { name = "pyarrow", specifier = "==17.0.0" }, { name = "pytz", specifier = "==2022.7.1" }, { name = "redis", specifier = "==5.2.1" }, { name = "sentry-sdk", extras = ["django"], specifier = "==1.45.1" }, @@ -1284,6 +1286,24 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/7b/08/9c66c269b0d417a0af9fb969535f0371b8c538633535a7a6a5ca3f9231e2/psycopg2_binary-2.9.9-cp312-cp312-win_amd64.whl", hash = "sha256:81ff62668af011f9a48787564ab7eded4e9fb17a4a6a74af5ffa6a457400d2ab", size = 1163864, upload-time = "2023-10-28T09:37:28.155Z" }, ] +[[package]] +name = "pyarrow" +version = "17.0.0" +source = { registry = "https://pypi.org/simple" } +dependencies = [ + { name = "numpy" }, +] +sdist = { url = "https://files.pythonhosted.org/packages/27/4e/ea6d43f324169f8aec0e57569443a38bab4b398d09769ca64f7b4d467de3/pyarrow-17.0.0.tar.gz", hash = "sha256:4beca9521ed2c0921c1023e68d097d0299b62c362639ea315572a58f3f50fd28", size = 1112479, upload-time = "2024-07-17T10:41:25.092Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/d4/62/ce6ac1275a432b4a27c55fe96c58147f111d8ba1ad800a112d31859fae2f/pyarrow-17.0.0-cp312-cp312-macosx_10_15_x86_64.whl", hash = "sha256:9b8a823cea605221e61f34859dcc03207e52e409ccf6354634143e23af7c8d22", size = 29019418, upload-time = "2024-07-16T10:30:55.573Z" }, + { url = "https://files.pythonhosted.org/packages/8e/0a/dbd0c134e7a0c30bea439675cc120012337202e5fac7163ba839aa3691d2/pyarrow-17.0.0-cp312-cp312-macosx_11_0_arm64.whl", hash = "sha256:f1e70de6cb5790a50b01d2b686d54aaf73da01266850b05e3af2a1bc89e16053", size = 27152197, upload-time = "2024-07-16T10:31:02.036Z" }, + { url = "https://files.pythonhosted.org/packages/cb/05/3f4a16498349db79090767620d6dc23c1ec0c658a668d61d76b87706c65d/pyarrow-17.0.0-cp312-cp312-manylinux_2_17_aarch64.manylinux2014_aarch64.whl", hash = "sha256:0071ce35788c6f9077ff9ecba4858108eebe2ea5a3f7cf2cf55ebc1dbc6ee24a", size = 39263026, upload-time = "2024-07-16T10:31:10.351Z" }, + { url = "https://files.pythonhosted.org/packages/c2/0c/ea2107236740be8fa0e0d4a293a095c9f43546a2465bb7df34eee9126b09/pyarrow-17.0.0-cp312-cp312-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:757074882f844411fcca735e39aae74248a1531367a7c80799b4266390ae51cc", size = 39880798, upload-time = "2024-07-16T10:31:17.66Z" }, + { url = "https://files.pythonhosted.org/packages/f6/b0/b9164a8bc495083c10c281cc65064553ec87b7537d6f742a89d5953a2a3e/pyarrow-17.0.0-cp312-cp312-manylinux_2_28_aarch64.whl", hash = "sha256:9ba11c4f16976e89146781a83833df7f82077cdab7dc6232c897789343f7891a", size = 38715172, upload-time = "2024-07-16T10:31:25.965Z" }, + { url = "https://files.pythonhosted.org/packages/f1/c4/9625418a1413005e486c006e56675334929fad864347c5ae7c1b2e7fe639/pyarrow-17.0.0-cp312-cp312-manylinux_2_28_x86_64.whl", hash = "sha256:b0c6ac301093b42d34410b187bba560b17c0330f64907bfa4f7f7f2444b0cf9b", size = 39874508, upload-time = "2024-07-16T10:31:33.721Z" }, + { url = "https://files.pythonhosted.org/packages/ae/49/baafe2a964f663413be3bd1cf5c45ed98c5e42e804e2328e18f4570027c1/pyarrow-17.0.0-cp312-cp312-win_amd64.whl", hash = "sha256:392bc9feabc647338e6c89267635e111d71edad5fcffba204425a7c8d13610d7", size = 25099235, upload-time = "2024-07-16T10:31:40.893Z" }, +] + [[package]] name = "pyasn1" version = "0.6.1"