From e72315052de15a7e41fd16660e0bcace796a18e4 Mon Sep 17 00:00:00 2001 From: DrillableBit Date: Mon, 11 May 2026 21:25:24 +0200 Subject: [PATCH 1/5] add export_parquet command and pyarrow --- .../management/commands/export_parquet.py | 479 ++++++++++++++++++ pyproject.toml | 1 + uv.lock | 20 + 3 files changed, 500 insertions(+) create mode 100644 aiarena/core/management/commands/export_parquet.py diff --git a/aiarena/core/management/commands/export_parquet.py b/aiarena/core/management/commands/export_parquet.py new file mode 100644 index 000000000..6ffe1a8c2 --- /dev/null +++ b/aiarena/core/management/commands/export_parquet.py @@ -0,0 +1,479 @@ +import re +from pathlib import Path +from uuid import UUID + +from django.core.management.base import BaseCommand, CommandError +from django.db import transaction +from django.db.models.signals import post_delete + +import pandas as pd + +from aiarena.core.models import ( + Bot, + BotRace, + Competition, + Game, + GameMode, + Map, + Match, + MatchParticipation, + MatchTag, + Result, + Round, + Tag, +) +from aiarena.core.models.match_tag import delete_orphan_tags + + +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}", + ) + + # self.cleanup_exported_competition_data( + # 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 cleanup_exported_competition_data(self, competition_id): + self.stdout.write(self.style.WARNING(f"Cleaning up exported DB data for competition {competition_id}")) + + with transaction.atomic(): + rounds = Round.objects.filter(competition_id=competition_id) + + matches = Match.objects.filter(round__competition_id=competition_id) + + match_ids = list(matches.values_list("id", flat=True)) + result_ids = list(matches.exclude(result_id__isnull=True).values_list("result_id", flat=True)) + + # delete m2m rows first + Match.tags.through.objects.filter(match_id__in=match_ids).delete() + + # delete participations + MatchParticipation.objects.filter(match_id__in=match_ids).delete() + + # delete matches + matches.delete() + + # delete results + Result.objects.filter(id__in=result_ids).delete() + + # delete rounds + rounds.delete() + + # delete orphaned match tags + orphaned_match_tags = MatchTag.objects.filter(match__isnull=True) + + orphaned_tag_ids = list(orphaned_match_tags.values_list("tag_id", flat=True)) + + post_delete.disconnect( + delete_orphan_tags, + sender=MatchTag, + ) + + try: + orphaned_match_tags.delete() + finally: + post_delete.connect( + delete_orphan_tags, + sender=MatchTag, + ) + + # delete orphaned tags + used_tag_ids = MatchTag.objects.values_list( + "tag_id", + flat=True, + ).distinct() + + Tag.objects.filter(id__in=orphaned_tag_ids).exclude(id__in=used_tag_ids).delete() + + # finally delete competition + Competition.objects.filter(id=competition_id).delete() + + self.stdout.write(self.style.SUCCESS(f"Finished cleanup for competition {competition_id}")) + + 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/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" From c3d722540aea63b97d64f9f5574ed9605617a526 Mon Sep 17 00:00:00 2001 From: DrillableBit Date: Thu, 14 May 2026 12:19:50 +0200 Subject: [PATCH 2/5] remove delete cleanup, add description --- .../management/commands/export_parquet.py | 76 +++---------------- 1 file changed, 12 insertions(+), 64 deletions(-) diff --git a/aiarena/core/management/commands/export_parquet.py b/aiarena/core/management/commands/export_parquet.py index 6ffe1a8c2..0ef061550 100644 --- a/aiarena/core/management/commands/export_parquet.py +++ b/aiarena/core/management/commands/export_parquet.py @@ -3,8 +3,6 @@ from uuid import UUID from django.core.management.base import BaseCommand, CommandError -from django.db import transaction -from django.db.models.signals import post_delete import pandas as pd @@ -22,9 +20,20 @@ Round, Tag, ) -from aiarena.core.models.match_tag import delete_orphan_tags +# 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"] @@ -227,10 +236,6 @@ def export_competition(self, competition_id, base_output_dir): competition_qs=Competition.objects.filter(id=competition_id), success_message=f"Finished sanitized Parquet export for competition {competition_id}", ) - - # self.cleanup_exported_competition_data( - # competition.id - # ) return ds def export_all_competitions(self, year, base_output_dir): @@ -351,63 +356,6 @@ def export_all_requested_matches(self, year, base_output_dir): self.stdout.write(self.style.SUCCESS(f"Total exported rows across all requested exports: {total_rows:,}")) - def cleanup_exported_competition_data(self, competition_id): - self.stdout.write(self.style.WARNING(f"Cleaning up exported DB data for competition {competition_id}")) - - with transaction.atomic(): - rounds = Round.objects.filter(competition_id=competition_id) - - matches = Match.objects.filter(round__competition_id=competition_id) - - match_ids = list(matches.values_list("id", flat=True)) - result_ids = list(matches.exclude(result_id__isnull=True).values_list("result_id", flat=True)) - - # delete m2m rows first - Match.tags.through.objects.filter(match_id__in=match_ids).delete() - - # delete participations - MatchParticipation.objects.filter(match_id__in=match_ids).delete() - - # delete matches - matches.delete() - - # delete results - Result.objects.filter(id__in=result_ids).delete() - - # delete rounds - rounds.delete() - - # delete orphaned match tags - orphaned_match_tags = MatchTag.objects.filter(match__isnull=True) - - orphaned_tag_ids = list(orphaned_match_tags.values_list("tag_id", flat=True)) - - post_delete.disconnect( - delete_orphan_tags, - sender=MatchTag, - ) - - try: - orphaned_match_tags.delete() - finally: - post_delete.connect( - delete_orphan_tags, - sender=MatchTag, - ) - - # delete orphaned tags - used_tag_ids = MatchTag.objects.values_list( - "tag_id", - flat=True, - ).distinct() - - Tag.objects.filter(id__in=orphaned_tag_ids).exclude(id__in=used_tag_ids).delete() - - # finally delete competition - Competition.objects.filter(id=competition_id).delete() - - self.stdout.write(self.style.SUCCESS(f"Finished cleanup for competition {competition_id}")) - def export_match_dataset( self, output_dir, From 50e09b52642b2bce5d133bf9307558bfe36f48df Mon Sep 17 00:00:00 2001 From: DrillableBit Date: Thu, 14 May 2026 18:58:20 +0200 Subject: [PATCH 3/5] remove logs --- .../api/arenaclient/common/ac_coordinator.py | 50 +------- .../common/result_submission_handler.py | 23 ---- aiarena/api/arenaclient/common/views.py | 107 +++--------------- .../service_implementations/_matches.py | 104 +---------------- 4 files changed, 20 insertions(+), 264 deletions(-) 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/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: From 70a116f9c86f7fbc6b84f8c8f4d68168a3bfec9d Mon Sep 17 00:00:00 2001 From: DrillableBit Date: Thu, 14 May 2026 19:03:06 +0200 Subject: [PATCH 4/5] Revert "remove logs" This reverts commit 50e09b52642b2bce5d133bf9307558bfe36f48df. --- .../api/arenaclient/common/ac_coordinator.py | 50 +++++++- .../common/result_submission_handler.py | 23 ++++ aiarena/api/arenaclient/common/views.py | 107 +++++++++++++++--- .../service_implementations/_matches.py | 104 ++++++++++++++++- 4 files changed, 264 insertions(+), 20 deletions(-) diff --git a/aiarena/api/arenaclient/common/ac_coordinator.py b/aiarena/api/arenaclient/common/ac_coordinator.py index 1082f8a2c..be03dc5b0 100644 --- a/aiarena/api/arenaclient/common/ac_coordinator.py +++ b/aiarena/api/arenaclient/common/ac_coordinator.py @@ -12,6 +12,7 @@ from aiarena.core.models import ArenaClient import logging +import time from django.db import connection, transaction from django.db.models.signals import pre_save @@ -32,6 +33,9 @@ logger = logging.getLogger(__name__) +loggerECS = logging.getLogger("aiarena") + +threshold_logger = 3 class ACCoordinator: @@ -39,18 +43,30 @@ 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 @@ -59,9 +75,22 @@ 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, @@ -77,13 +106,20 @@ 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() @@ -98,12 +134,20 @@ 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 a440bad78..2996a84fb 100644 --- a/aiarena/api/arenaclient/common/result_submission_handler.py +++ b/aiarena/api/arenaclient/common/result_submission_handler.py @@ -1,4 +1,5 @@ import logging +import time from dataclasses import dataclass from typing import Any @@ -29,13 +30,23 @@ 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( @@ -49,6 +60,12 @@ 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) @@ -76,6 +93,12 @@ 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 b72ee99b5..618cb8296 100644 --- a/aiarena/api/arenaclient/common/views.py +++ b/aiarena/api/arenaclient/common/views.py @@ -1,4 +1,5 @@ import logging +import time from wsgiref.util import FileWrapper from django.core.cache import cache @@ -27,6 +28,9 @@ logger = logging.getLogger(__name__) +loggerECS = logging.getLogger("aiarena") + +threshold_logger = 3 class MatchViewSet(viewsets.GenericViewSet): @@ -55,24 +59,84 @@ def load_participants(self, match: Match): ) def create(self, request, *args, **kwargs): - no_game_available = cache.get("NoGameAvailable", False) - - if request.user.is_arenaclient: - match = ACCoordinator.next_match(request.user.arenaclient, no_game_available) - - 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) + 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, + ) raise NoGameForClient() + finally: + loggerECS.warning( + "Slow request - next-match create total %.3fs | user=%s", + time.monotonic() - total_start, + user_id, + ) + # todo: check match is in progress/bot is in this match @action( detail=True, @@ -119,6 +183,7 @@ 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() @@ -145,7 +210,19 @@ 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/services/service_implementations/_matches.py b/aiarena/core/services/service_implementations/_matches.py index e97e40018..be719915a 100644 --- a/aiarena/core/services/service_implementations/_matches.py +++ b/aiarena/core/services/service_implementations/_matches.py @@ -1,5 +1,6 @@ import logging import random +import time from django.db import transaction from django.db.models import Count, Max @@ -35,6 +36,9 @@ logger = logging.getLogger(__name__) +loggerECS = logging.getLogger("aiarena") + +threshold_logger = 3 class Matches: @@ -70,6 +74,7 @@ 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") @@ -77,9 +82,19 @@ 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 @@ -93,6 +108,7 @@ 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( """ @@ -105,8 +121,15 @@ 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( @@ -125,8 +148,14 @@ 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( @@ -143,22 +172,40 @@ 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( @@ -170,6 +217,17 @@ 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) @@ -190,6 +248,11 @@ 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 @@ -313,6 +376,7 @@ 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 @@ -334,27 +398,63 @@ 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: From bb7a361db061ce65ede07c5de1a8e39393275591 Mon Sep 17 00:00:00 2001 From: DrillableBit Date: Thu, 14 May 2026 19:03:40 +0200 Subject: [PATCH 5/5] Reapply "remove logs" This reverts commit 70a116f9c86f7fbc6b84f8c8f4d68168a3bfec9d. --- .../api/arenaclient/common/ac_coordinator.py | 50 +------- .../common/result_submission_handler.py | 23 ---- aiarena/api/arenaclient/common/views.py | 107 +++--------------- .../service_implementations/_matches.py | 104 +---------------- 4 files changed, 20 insertions(+), 264 deletions(-) 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/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: