variable tick time (#62)

* Tests fix

* Add import

* Fixed comments

* Fix tests

backend/db/migration.py

@@ -22,7 +22,7 @@ async def fill_tables():
         dataset_id=dataset_id,
         start_time=datetime.now(),
         total_ticks=2300,
-        tick_time=3000)
+        tick_time=5000)
     nat_game_id = await Game.create(
         game_name="Natjecanje",
         is_contest=True,
@@ -160,7 +160,7 @@ async def run_migrations():
               volume INT,
               PRIMARY KEY (game_id, tick, resource)
               )''')
-    
+
     await database.execute('CREATE INDEX CONCURRENTLY tick_idx ON market (tick);')
 
     await database.execute('''

backend/game/tick/test_ticker_run_all_game_ticks.py

@@ -1,82 +1,152 @@
+from collections import defaultdict
 from databases import Database
 import pytest
 from datetime import datetime, timedelta
-from unittest.mock import patch
+from unittest.mock import AsyncMock, MagicMock, patch
 from game.tick import Ticker, GameData
 from model import Game
+from unittest.mock import Mock
 
 
 @pytest.mark.asyncio
-async def test_run_all_game_ticks_game_just_finished():
-    # Prepare
-    game = Game(game_id=1, game_name="Test Game", start_time=datetime.now(), current_tick=10,
-                total_ticks=10, is_finished=False, dataset_id=1, bots="", tick_time=1000, is_contest=False)
-    ticker = Ticker()
-    ticker.game_data[game.game_id] = GameData(game, {})
+async def test_run_tick_manager():
+
+    games = [Game(game_id=1, game_name="Game1", is_finished=False,
+                  start_time=datetime.now(), current_tick=0, total_ticks=10, dataset_id=1, tick_time=1000, is_contest=True)]
+    mock_game_list = AsyncMock(return_value=games)
+
+    mock_start_game = AsyncMock()
+    mock_end_game = AsyncMock()
+
+    with patch('model.Game.list', new=mock_game_list), \
+            patch('game.tick.Ticker.start_game', new=mock_start_game), \
+            patch('game.tick.Ticker.end_game', new=mock_end_game):
+
+        ticker = Ticker()
+
+        await ticker.run_tick_manager(1)
+
+        mock_start_game.assert_called_once_with(games[0])
+
+        mock_end_game.assert_not_called()
+
+
+@pytest.mark.asyncio
+async def test_run_tick_manager_game_finished():
+
+    games = [Game(game_id=1, game_name="Game1", is_finished=True,
+                  start_time=datetime.now(), current_tick=0, total_ticks=10, dataset_id=1, tick_time=1000, is_contest=True)]
+    mock_game_list = AsyncMock(return_value=games)
+
+    mock_start_game = AsyncMock()
+    mock_end_game = AsyncMock()
+
+    with patch('model.Game.list', new=mock_game_list), \
+            patch('game.tick.Ticker.start_game', new=mock_start_game), \
+            patch('game.tick.Ticker.end_game', new=mock_end_game):
+
+        ticker = Ticker()
+
+        await ticker.run_tick_manager(1)
+
+        mock_start_game.assert_not_called()
+
+        mock_end_game.assert_not_called()
+
+
+@pytest.mark.asyncio
+async def test_run_tick_manager_game_not_started():
+
+    games = [Game(game_id=1, game_name="Game1", is_finished=False,
+                  start_time=datetime.now() + timedelta(seconds=10), current_tick=0, total_ticks=10, dataset_id=1, tick_time=1000, is_contest=True)]
+    mock_game_list = AsyncMock(return_value=games)
+
+    mock_start_game = AsyncMock()
+    mock_end_game = AsyncMock()
 
-    # Execute
-    with patch.object(Game, 'list') as mock_game_list:
-        mock_game_list.return_value = [game]
-        with patch.object(Game, 'update') as mock_game_update:
-            await ticker.run_all_game_ticks()
+    with patch('model.Game.list', new=mock_game_list), \
+            patch('game.tick.Ticker.start_game', new=mock_start_game), \
+            patch('game.tick.Ticker.end_game', new=mock_end_game):
 
-    # Verify
-    assert mock_game_update.call_count == 1
-    mock_game_update.assert_called_with(game_id=game.game_id, is_finished=True)
+        ticker = Ticker()
+
+        await ticker.run_tick_manager(1)
+
+        mock_start_game.assert_not_called()
+
+        mock_end_game.assert_not_called()
 
 
 @pytest.mark.asyncio
-async def test_run_all_game_ticks_game_not_started():
-    # Prepare
-    game = Game(game_id=2, game_name="Test Game 2", start_time=datetime.now() + timedelta(hours=1),
-                current_tick=1, total_ticks=10, is_finished=False, dataset_id=1, bots="", tick_time=1000, is_contest=False)
+async def test_end_game():
+    game = Game(game_id=1, game_name="Game1", is_finished=False,
+                start_time=datetime.now() - timedelta(seconds=1), current_tick=10, total_ticks=10, dataset_id=1, tick_time=1000, is_contest=True)
+
     ticker = Ticker()
-    ticker.game_data[game.game_id] = GameData(game, {})
 
-    # Execute
-    with patch.object(Game, 'list') as mock_game_list:
-        mock_game_list.return_value = [game]
-        await ticker.run_all_game_ticks()
+    ticker.game_data[1] = Mock()
+    ticker.game_futures[1] = Mock()
+
+    mock_game_update = AsyncMock()
+
+    with patch('model.Game.update', new=mock_game_update):
 
-    # Verify
-    # Tick should not increase since the game has not started yet
-    assert game.current_tick == 1
+        await ticker.end_game(game)
+
+        mock_game_update.assert_called_once_with(
+            game_id=1, is_finished=True)
+
+        assert 1 not in ticker.game_data
+
+        ticker.game_futures[1].cancel.assert_called_once()
 
 
 @pytest.mark.asyncio
-async def test_run_all_game_ticks_game_started():
-    # Prepare
-    game = Game(game_id=3, game_name="Test Game 3", start_time=datetime.now() - timedelta(hours=1),
-                current_tick=1, total_ticks=10, is_finished=False, dataset_id=1, bots="", tick_time=1000, is_contest=False)
+async def test_start_game():
+    game = Game(game_id=1, game_name="Game1", is_finished=False,
+                start_time=datetime.now() - timedelta(seconds=1), current_tick=10, total_ticks=10, dataset_id=1, tick_time=1000, is_contest=True)
+
     ticker = Ticker()
-    ticker.game_data[game.game_id] = GameData(game, {})
 
-    with patch.object(Database, 'transaction') as mock_transaction:
-        with patch.object(Database, 'execute') as mock_execute:
-            with patch.object(Game, 'list') as mock_game_list:
-                mock_game_list.return_value = [game]
-                with patch.object(Ticker, 'run_game_tick') as mock_run_game_tick:
-                    await ticker.run_all_game_ticks()
+    ticker.game_data[1] = Mock()
+    ticker.game_futures[1] = Mock()
+
+    mock_game_update = AsyncMock()
+
+    with patch('model.Game.update', new=mock_game_update) as mock_game_update, \
+            patch('game.tick.Ticker.delete_all_running_bots') as mock_delete_all_running_bots, \
+            patch('game.tick.Ticker.run_game') as mock_run_game:
 
-    mock_run_game_tick.assert_called_once_with(game)
+        await ticker.start_game(game)
+
+        mock_delete_all_running_bots.assert_called_once_with(1)
+
+        assert 1 in ticker.game_data
+        assert 1 in ticker.game_futures
+
+        await ticker.game_futures[1]
 
 
 @pytest.mark.asyncio
-async def test_run_all_game_ticks_game_finished():
-    # Prepare
-    game = Game(game_id=5, game_name="Test Game 5", start_time=datetime.now() - timedelta(hours=1),
-                current_tick=10, total_ticks=10, is_finished=True, dataset_id=1, bots="", tick_time=1000, is_contest=False)
+async def test_run_game():
+
+    game = Game(game_id=1, game_name="Game1", is_finished=False,
+                start_time=datetime.now() - timedelta(seconds=1), current_tick=9, total_ticks=10, dataset_id=1, tick_time=1000, is_contest=True)
+
     ticker = Ticker()
-    ticker.game_data[game.game_id] = GameData(game, {})
-
-    # Execute
-    with patch.object(Game, 'list') as mock_game_list:
-        mock_game_list.return_value = [game]
-        with patch.object(Ticker, 'run_game_tick') as mock_run_game_tick:
-            await ticker.run_all_game_ticks()
-
-    # Verify
-    mock_run_game_tick.assert_not_called()
-    assert game.current_tick == 10
-    assert game.is_finished is True
-    assert game.game_id in ticker.game_data
+
+    with patch('model.Game.get') as mock_get, \
+            patch('databases.Database.transaction') as mock_transaction, \
+            patch('databases.Database.execute') as mock_execute, \
+            patch('game.tick.Ticker.run_game_tick') as mock_run_game_tick, \
+            patch('asyncio.sleep') as mock_sleep:
+
+        mock_get.return_value = game
+
+        ticker.run_game_tick = MagicMock()
+
+        await ticker.run_game(game, iters=1)
+
+        mock_get.assert_called_once_with(game_id=1)
+
+        ticker.run_game_tick.assert_called_once_with(game)

backend/game/tick/test_ticker_test_run_game_tick.py

@@ -1,9 +1,13 @@
+from pprint import pprint
 import pytest
 from model import Game
 from game.tick import Ticker
 from unittest.mock import patch
 from tick.test_tick_fixtures import *
 
+import tracemalloc
+tracemalloc.start()
+
 
 @pytest.mark.asyncio
 async def test_run_game_tick(

backend/game/tick/ticker.py

@@ -1,5 +1,7 @@
+import asyncio
+import sys
 import traceback
-from datetime import datetime
+from datetime import datetime, timedelta
 from pprint import pprint
 from typing import Dict, Tuple
 import pandas as pd
@@ -25,41 +27,76 @@ def __init__(self, game: Game, players: Dict[int, Player]):
 class Ticker:
     def __init__(self):
         self.game_data: Dict[int, GameData] = {}
+        self.game_futures: Dict[int, asyncio.Future] = {}
 
-    async def run_all_game_ticks(self):
-        games = await Game.list()
-
-        for game in games:
-            if game.is_finished:
-                continue
-
-            if datetime.now() < game.start_time:
-                continue
-
-            if game.current_tick >= game.total_ticks:
-                try:
-                    logger.info(
-                        f"Ending game ({game.game_id}) {game.game_name}")
-                    await Game.update(game_id=game.game_id, is_finished=True)
-                    if self.game_data.get(game.game_id) is not None:
-                        del self.game_data[game.game_id]
-                except Exception as e:
-                    logger.critical(
-                        f"Failed ending game ({game.game_id}) (tick {game.current_tick}) with error:\n{traceback.format_exc()}")
-                continue
-
-            if self.game_data.get(game.game_id) is None:
-                try:
-                    logger.info(
-                        f"Starting game ({game.game_id}) {game.game_name}")
-                    await self.delete_all_running_bots(game.game_id)
-                    self.game_data[game.game_id] = GameData(game, {})
-                except Exception as e:
-                    logger.critical(
-                        f"Failed creating game ({game.game_id}) (tick {game.current_tick}) with error:\n{traceback.format_exc()}")
+    async def run_tick_manager(self, iters=None):
+        for i in range(iters or sys.maxsize):
+            games = await Game.list()
+
+            for game in games:
+                if game.is_finished:
+                    continue
+
+                if datetime.now() < game.start_time:
                     continue
 
+                if not game.game_id in self.game_data:
+                    await self.start_game(game)
+                    continue
+
+            await asyncio.sleep(0.1)
+
+    async def end_game(self, game: Game):
+        try:
+            logger.info(
+                f"Ending game ({game.game_id}) {game.game_name}")
+            await Game.update(game_id=game.game_id, is_finished=True)
+            if self.game_data.get(game.game_id) is not None:
+                del self.game_data[game.game_id]
+                self.game_futures[game.game_id].cancel()
+
+        except Exception as e:
+            logger.critical(
+                f"Failed ending game ({game.game_id}) (tick {game.current_tick}) with error:\n{traceback.format_exc()}")
+
+    async def start_game(self, game: Game):
+        try:
+            logger.info(
+                f"Starting game ({game.game_id}) {game.game_name}")
+
+            await self.delete_all_running_bots(game.game_id)
+
+            self.game_data[game.game_id] = GameData(game, {})
+            self.game_futures[game.game_id] = asyncio.create_task(
+                self.run_game(game), name=f"game_{game.game_id}")
+
+        except Exception as e:
+            logger.critical(
+                f"Failed creating game ({game.game_id}) (tick {game.current_tick}) with error:\n{traceback.format_exc()}")
+
+    async def run_game(self, game: Game, iters=None):
+        for i in range(iters or sys.maxsize):
+            game = await Game.get(game_id=game.game_id)
             try:
+                if game.current_tick >= game.total_ticks:
+                    await self.end_game(game)
+                    return
+
+                # wait until the tick should start
+                should_start = game.start_time + \
+                    timedelta(milliseconds=game.current_tick *
+                              game.tick_time)
+
+                to_wait = max(
+                    0, (should_start - datetime.now()).total_seconds())
+
+                if to_wait < 0.1:
+                    logger.warning(
+                        f"({game.game_id}) {game.game_name} has short waiting time: {to_wait}, catching up or possible overload")
+
+                await asyncio.sleep(to_wait)
+
+                # run the tick
                 async with database.transaction():
                     await database.execute(
                         f"LOCK TABLE orders, players IN SHARE ROW EXCLUSIVE MODE")
@@ -77,14 +114,18 @@ async def delete_all_running_bots(self, game_id: int):
             await Player.update(player_id=bot.player_id, is_active=False)
 
     async def run_game_tick(self, game: Game):
+
         logger.debug(
             f"({game.game_id}) {game.game_name}: {game.current_tick} tick")
         tick_data = await self.get_tick_data(game)
+
         tick_data = self.run_markets(tick_data)
 
         tick_data = self.run_power_plants(tick_data)
+
         tick_data, energy_sold = self.run_electricity_market(
             tick_data, self.game_data[game.game_id].energy_market)
+
         await self.save_electricity_orders(
             game, tick_data.players, energy_sold, game.current_tick)
 
@@ -198,11 +239,16 @@ async def save_market_data(self, tick_data: TickData):
                 tick=tick,
                 resource=resource.value,
                 low=tick_data.markets[resource.value].price_tracker.get_low(),
-                high=tick_data.markets[resource.value].price_tracker.get_high(),
-                open=tick_data.markets[resource.value].price_tracker.get_open(),
-                close=tick_data.markets[resource.value].price_tracker.get_close(),
-                market=tick_data.markets[resource.value].price_tracker.get_average(),
-                volume=tick_data.markets[resource.value].price_tracker.get_volume()
+                high=tick_data.markets[resource.value].price_tracker.get_high(
+                ),
+                open=tick_data.markets[resource.value].price_tracker.get_open(
+                ),
+                close=tick_data.markets[resource.value].price_tracker.get_close(
+                ),
+                market=tick_data.markets[resource.value].price_tracker.get_average(
+                ),
+                volume=tick_data.markets[resource.value].price_tracker.get_volume(
+                )
             )
 
     async def run_bots(self, tick_data: TickData):