From 12a59217909283b2a43ff42ee3fab49d02783364 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Sun, 15 Oct 2023 16:19:55 +0400 Subject: [PATCH 01/38] Modify suggest_output_path() to allow prefixes --- sinner/BatchProcessingCore.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/sinner/BatchProcessingCore.py b/sinner/BatchProcessingCore.py index 2c6cfaa2..c2b14fc0 100644 --- a/sinner/BatchProcessingCore.py +++ b/sinner/BatchProcessingCore.py @@ -177,12 +177,12 @@ def get_postfix(self, futures_length: int) -> dict[str, Any]: postfix['limit_reaches'] = self._statistics['limits_reaches'] return postfix - def suggest_output_path(self) -> str: + def suggest_output_path(self, prefix: str = 'result') -> str: target_name, target_extension = os.path.splitext(os.path.basename(self.target_path)) if self.output_path is None: - return os.path.join(os.path.dirname(self.target_path), 'result-' + target_name + target_extension) + return os.path.join(os.path.dirname(self.target_path), f'{prefix}-{target_name}{target_extension}') if os.path.isdir(self.output_path): - return os.path.join(self.output_path, 'result-' + target_name + target_extension) + return os.path.join(self.output_path, f'{prefix}-{target_name}{target_extension}') return self.output_path @staticmethod From 5bd6a8343ae40f879e0b5568e032bc1acd4e4357 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:50:00 +0400 Subject: [PATCH 02/38] dev: debug logger --- sin.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/sin.py b/sin.py index d846124b..9323de52 100644 --- a/sin.py +++ b/sin.py @@ -1,4 +1,5 @@ #!/usr/bin/env python3 +import logging import os import signal import sys @@ -46,6 +47,15 @@ def run(self) -> None: if __name__ == '__main__': + logging.basicConfig( + level=logging.DEBUG, + format='%(name)s - %(message)s', + filename='debug.log', + filemode='w' + ) + logging.getLogger('PIL.PngImagePlugin').setLevel(logging.CRITICAL + 1) + logging.getLogger('PIL.PngImagePlugin').addHandler(logging.NullHandler()) + # todo: remnants of roop code, needs to be checked # single thread doubles cuda performance - needs to be set before torch import if any(arg.startswith('--execution-provider') for arg in sys.argv): From 4aa432d78187b61d1a337334727cca2eccdb6bd5 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:50:58 +0400 Subject: [PATCH 03/38] Implementing average value meter --- sinner/models/MovingAverage.py | 31 +++++++++++++++++++++++++++++++ 1 file changed, 31 insertions(+) create mode 100644 sinner/models/MovingAverage.py diff --git a/sinner/models/MovingAverage.py b/sinner/models/MovingAverage.py new file mode 100644 index 00000000..4f129c92 --- /dev/null +++ b/sinner/models/MovingAverage.py @@ -0,0 +1,31 @@ +from collections import deque + + +class MovingAverage: + def __init__(self, window_size: int = 0): + self.window_size = window_size + if window_size > 0: + self.window = deque(maxlen=window_size) + else: + self.sum = 0 + self.count = 0 + + def update(self, value: float) -> None: + if self.window_size > 0: + self.window.append(value) + else: + self.sum += value + self.count += 1 + + def get_average(self) -> float: + if self.window_size > 0: + return sum(self.window) / len(self.window) if self.window else 0 + else: + return self.sum / self.count if self.count > 0 else 0 + + def reset(self) -> None: + if self.window_size > 0: + self.window.clear() + else: + self.sum = 0 + self.count = 0 From 3c31ebf17bb1e99b03f308443be12e60addd864f Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:51:30 +0400 Subject: [PATCH 04/38] fixed: do not return timer before timeline started --- sinner/models/FrameTimeLine.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/sinner/models/FrameTimeLine.py b/sinner/models/FrameTimeLine.py index a57b114d..03ff38a2 100644 --- a/sinner/models/FrameTimeLine.py +++ b/sinner/models/FrameTimeLine.py @@ -47,7 +47,10 @@ def stop(self) -> None: # returns time passed from the start def time(self) -> float: - return time.perf_counter() - self._timer + if self._is_started: + return time.perf_counter() - self._timer + else: + return 0.0 def real_time_position(self) -> float: """ From 7b71250f98834b9a78088b8c5051fc70db331947 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:51:58 +0400 Subject: [PATCH 05/38] todo added --- sinner/models/FrameDirectoryBuffer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sinner/models/FrameDirectoryBuffer.py b/sinner/models/FrameDirectoryBuffer.py index 1a268633..e17981c7 100644 --- a/sinner/models/FrameDirectoryBuffer.py +++ b/sinner/models/FrameDirectoryBuffer.py @@ -73,7 +73,7 @@ def add_frame(self, frame: NumberedFrame) -> None: def get_frame(self, index: int, return_previous: bool = True) -> NumberedFrame | None: filename = str(index).zfill(self.zfill_length) + '.png' filepath = str(os.path.join(self.path, filename)) - if path_exists(filepath): + if path_exists(filepath): # todo: check within indexes should be faster try: return NumberedFrame(index, read_from_image(filepath)) except Exception: From 8f33cb9f14e8871fc3b1d34a4cd6573bdb568935 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:52:23 +0400 Subject: [PATCH 06/38] missing frames counter added --- sinner/models/FrameDirectoryBuffer.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/sinner/models/FrameDirectoryBuffer.py b/sinner/models/FrameDirectoryBuffer.py index e17981c7..35972119 100644 --- a/sinner/models/FrameDirectoryBuffer.py +++ b/sinner/models/FrameDirectoryBuffer.py @@ -13,6 +13,7 @@ class FrameDirectoryBuffer: _zfill_length: int | None _path: str | None = None _indices: List[int] = [] + _miss: int = 0 # the current miss between requested frame and the returned one def __init__(self, source_name: str, target_name: str, temp_dir: str, frames_count: int): self.source_name = source_name @@ -75,6 +76,7 @@ def get_frame(self, index: int, return_previous: bool = True) -> NumberedFrame | filepath = str(os.path.join(self.path, filename)) if path_exists(filepath): # todo: check within indexes should be faster try: + self._miss = 0 return NumberedFrame(index, read_from_image(filepath)) except Exception: pass @@ -85,6 +87,7 @@ def get_frame(self, index: int, return_previous: bool = True) -> NumberedFrame | previous_file_path = os.path.join(self.path, previous_filename) if path_exists(previous_file_path): try: + self._miss = index - previous_number return NumberedFrame(index, read_from_image(previous_file_path)) except Exception: # the file may exist but can be locked in another thread. pass @@ -98,3 +101,7 @@ def init_indices(self) -> None: for entry in entries: if entry.is_file() and entry.name.endswith(".png"): self._indices.append(int(get_file_name(entry.name))) + + @property + def miss(self) -> int: + return self._miss From 42c208ed0022d6c44f2f1f6cc98fec3031eff2da Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:53:05 +0400 Subject: [PATCH 07/38] A bunch of counters added --- sinner/models/FrameTimeLine.py | 36 ++++++++++++++++++++++++++++++++++ 1 file changed, 36 insertions(+) diff --git a/sinner/models/FrameTimeLine.py b/sinner/models/FrameTimeLine.py index 03ff38a2..b9ee8467 100644 --- a/sinner/models/FrameTimeLine.py +++ b/sinner/models/FrameTimeLine.py @@ -110,3 +110,39 @@ def last_returned_index(self) -> int | None: :return: int | None """ return self._last_returned_index + + @property + def frame_lag(self) -> int: + """ + :return: the difference between currently playing frame and the last returned one. Shows the processing lag. + """ + return self.get_frame_index() - (self._last_returned_index or self._start_frame_index) + + @property + def time_lag(self) -> float: + """ + :return: the time difference between currently playing frame and the last requested one. + """ + return self.frame_lag * self._frame_time + + @property + def display_frame_lag(self) -> int: + """ + :return: the difference between current frame and the last returned one. Shows the visible lag. + """ + return (self._last_returned_index or self._start_frame_index) - self._last_added_index + + @property + def display_time_lag(self) -> float: + """ + :return: the time difference between current frame and the last returned one. + """ + return self.display_frame_lag * self._frame_time + + @property + def current_frame_miss(self) -> int: + """ + :return: the current *real* gap between requested frame and returned one + """ + return self._FrameBuffer.miss + From 7453aa1ecb6d35c9363e5244f3d0e5e86f21ae83 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:54:46 +0400 Subject: [PATCH 08/38] Logger added --- sinner/gui/GUIModel.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 3e2e8519..cf08dd53 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -1,3 +1,4 @@ +import logging import os import threading import time @@ -144,6 +145,7 @@ def rules(self) -> Rules: def __init__(self, parameters: Namespace, pb_control: ProgressBarManager, status_callback: Callable[[str, str], Any], on_close_event: Event | None = None): self.parameters = parameters + self.logger = logging.getLogger("GUI Model") super().__init__(parameters) self._processors = {} if self.bootstrap_processors: From b6dae58cb6e0f21a2c632fadd96a848864d35f30 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 12:59:02 +0400 Subject: [PATCH 09/38] Calculate average processing time via MovingAverage _process_frame() also returns frame index --- sinner/gui/GUIModel.py | 28 +++++++++++++++++----------- 1 file changed, 17 insertions(+), 11 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index cf08dd53..5c162a57 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -19,6 +19,7 @@ from sinner.handlers.frame.NoneHandler import NoneHandler from sinner.helpers.FrameHelper import scale from sinner.models.Event import Event +from sinner.models.MovingAverage import MovingAverage from sinner.models.PerfCounter import PerfCounter from sinner.models.State import State from sinner.models.audio.BaseAudioBackend import BaseAudioBackend @@ -65,10 +66,11 @@ class GUIModel(Status): # player counters _framedrop: int = -1 # the manual value of dropped frames - _process_fps: float = 1 + _processing_fps: float = 1 # internal variables _is_target_frames_extracted: bool = False + _average_processing_time: MovingAverage = MovingAverage(window_size=10) # Calculator for the average processing time # threads _process_frames_thread: threading.Thread | None = None @@ -425,15 +427,18 @@ def _process_frames(self, start_frame: int, end_frame: int) -> None: def process_done(future_: Future[float | None]) -> None: if not future_.cancelled(): - process_time = future_.result() - if process_time: - if len(results) >= 30: # limit mean time base to last 30 executions - results.pop(0) - results.append(process_time) - self._process_fps = self._process_fps = self.execution_threads / (sum(results) / len(results)) - self._status("Mean FPS/Last frame/Frame skip", f"{round(self._process_fps, 4)}/{round(1 / process_time, 4)}/{frame_skip - 1}") + result = future_.result() + if result: + process_time, frame_index = result + self._average_processing_time.update(process_time / self.execution_threads) + processing.remove(frame_index) + self._processing_fps = 1 / self._average_processing_time.get_average() + self.logger.info(f"self._processing_fps = {self._processing_fps}") + self._status("Processing FPS/Last frame", f"{round(self._processing_fps, 4)}/{round(1 / process_time, 4)}") + self._status("Frame lag/Play frame lag", f"{self.TimeLine.frame_lag}/{self.TimeLine.display_frame_lag}") futures.remove(future_) + processing: List[int] = [] # list of frames currently being processed futures: list[Future[float | None]] = [] results: list[float] = [] frame_skip: int = 0 @@ -466,11 +471,11 @@ def process_done(future_: Future[float | None]) -> None: self.update_status("_process_frames loop done") - def _process_frame(self, frame_index: int) -> float | None: + def _process_frame(self, frame_index: int) -> tuple[float, int] | None: """ Renders a frame with the current processors set :param frame_index: the frame index - :return: the render time, or None on error + :return: the [render time, frame index], or None on error """ try: n_frame = self.frame_handler.extract_frame(frame_index) @@ -481,8 +486,9 @@ def _process_frame(self, frame_index: int) -> float | None: with PerfCounter() as frame_render_time: for _, processor in self.processors.items(): n_frame.frame = processor.process_frame(n_frame.frame) + self.logger.info(f"Frame processed: {n_frame.index} in {frame_render_time.execution_time}") self.TimeLine.add_frame(n_frame) - return frame_render_time.execution_time + return frame_render_time.execution_time, n_frame.index def _show_frames(self) -> None: last_shown_frame_index: int = -1 From 29b16dd9c4be876b9a204ebe005f97f3e227e542 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 14:48:04 +0400 Subject: [PATCH 10/38] use expected index for counter, not the real one --- sinner/models/FrameTimeLine.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/sinner/models/FrameTimeLine.py b/sinner/models/FrameTimeLine.py index b9ee8467..4ab93a03 100644 --- a/sinner/models/FrameTimeLine.py +++ b/sinner/models/FrameTimeLine.py @@ -77,8 +77,7 @@ def get_frame(self, time_aligned: bool = True) -> NumberedFrame | None: result_frame = self._FrameBuffer.get_frame(self._last_requested_index) if result_frame: - self._last_returned_index = result_frame.index - # print("Last requested/returned frame:", f"{self._last_requested_index}/{self._last_returned_index}") + self._last_returned_index = self._last_requested_index # it is an EXPECTED index, not a real one return result_frame def has_index(self, index: int) -> bool: From edcfe3e517ac2cf1c34cd62c15cd3248a286e698 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 15:13:00 +0400 Subject: [PATCH 11/38] return real frame number instead of expected one --- sinner/models/FrameDirectoryBuffer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sinner/models/FrameDirectoryBuffer.py b/sinner/models/FrameDirectoryBuffer.py index 35972119..d1f0868e 100644 --- a/sinner/models/FrameDirectoryBuffer.py +++ b/sinner/models/FrameDirectoryBuffer.py @@ -88,7 +88,7 @@ def get_frame(self, index: int, return_previous: bool = True) -> NumberedFrame | if path_exists(previous_file_path): try: self._miss = index - previous_number - return NumberedFrame(index, read_from_image(previous_file_path)) + return NumberedFrame(previous_number, read_from_image(previous_file_path)) except Exception: # the file may exist but can be locked in another thread. pass return None From 0e6782f196d55deb299604ddeeaca0c5a78b0d4b Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:11:43 +0400 Subject: [PATCH 12/38] SOLVED: found a good way to synchronize processing and real speed --- sinner/gui/GUIModel.py | 52 +++++++++++++++++++----------------------- 1 file changed, 24 insertions(+), 28 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 5c162a57..04fdd870 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -1,4 +1,5 @@ import logging +import math import os import threading import time @@ -70,7 +71,11 @@ class GUIModel(Status): # internal variables _is_target_frames_extracted: bool = False + _last_requested_frame: int = 0 # the last requested frame inside processing, needed to avoid re-requesting on same frames + _biggest_processed_frame: int = 0 # the last (by number) processed frame index, needed to indicate if processing gap is too big + _largest_miss: int = 0 # experimental _average_processing_time: MovingAverage = MovingAverage(window_size=10) # Calculator for the average processing time + _average_frame_skip: MovingAverage = MovingAverage(window_size=10) # Calculator for the average frame skip # threads _process_frames_thread: threading.Thread | None = None @@ -324,16 +329,6 @@ def set_previews(self, position: int, previews: FramesList) -> None: def clear_previews(self) -> None: self._previews.clear() - @property - def frame_skip(self) -> int: - """ - Returns the count of frames need to skip every time - :return: - """ - if self.framedrop == -1: # auto - return int(self.frame_handler.fps / self._process_fps / self.execution_threads) + 1 - return self.framedrop + 1 - @property def framedrop(self) -> int: return self._framedrop @@ -433,15 +428,15 @@ def process_done(future_: Future[float | None]) -> None: self._average_processing_time.update(process_time / self.execution_threads) processing.remove(frame_index) self._processing_fps = 1 / self._average_processing_time.get_average() - self.logger.info(f"self._processing_fps = {self._processing_fps}") + if self._biggest_processed_frame < frame_index: + self._biggest_processed_frame = frame_index + # self.logger.info(f"self.__last_processed_frame = {self._biggest_processed_frame}") self._status("Processing FPS/Last frame", f"{round(self._processing_fps, 4)}/{round(1 / process_time, 4)}") self._status("Frame lag/Play frame lag", f"{self.TimeLine.frame_lag}/{self.TimeLine.display_frame_lag}") futures.remove(future_) processing: List[int] = [] # list of frames currently being processed futures: list[Future[float | None]] = [] - results: list[float] = [] - frame_skip: int = 0 with ThreadPoolExecutor(max_workers=self.execution_threads) as executor: # this adds processing operations into a queue while start_frame <= end_frame: @@ -449,7 +444,9 @@ def process_done(future_: Future[float | None]) -> None: start_frame = self._event_rewind.tag or 0 self._event_rewind.clear() - if not self.TimeLine.has_index(start_frame): + if start_frame not in processing and not self.TimeLine.has_index(start_frame): + # self.logger.info(f"Submit to processing frame {start_frame}") + processing.append(start_frame) future: Future[float | None] = executor.submit(self._process_frame, start_frame) future.add_done_callback(process_done) futures.append(future) @@ -462,14 +459,13 @@ def process_done(future_: Future[float | None]) -> None: if not self._event_processing.is_set(): executor.shutdown(wait=False, cancel_futures=True) break - frame_skip = self.frame_skip - if self.TimeLine.last_added_index < self.TimeLine.last_requested_index: # if processing is too late - start_frame = frame_skip + self.TimeLine.last_requested_index # push it a little forward - else: - start_frame += self.frame_skip + self._average_frame_skip.update(self.frame_handler.fps / self._processing_fps) + + start_frame += math.ceil(self._average_frame_skip.get_average()) + self.TimeLine.current_frame_miss + self.logger.info(f"NEXT: {start_frame}, MISS: {self.TimeLine.current_frame_miss}, AVG: {self._average_frame_skip.get_average()} ") - self.update_status("_process_frames loop done") + self.logger.info("process_frames loop done") def _process_frame(self, frame_index: int) -> tuple[float, int] | None: """ @@ -486,7 +482,7 @@ def _process_frame(self, frame_index: int) -> tuple[float, int] | None: with PerfCounter() as frame_render_time: for _, processor in self.processors.items(): n_frame.frame = processor.process_frame(n_frame.frame) - self.logger.info(f"Frame processed: {n_frame.index} in {frame_render_time.execution_time}") + self.logger.info(f"DONE: {n_frame.index}") self.TimeLine.add_frame(n_frame) return frame_render_time.execution_time, n_frame.index @@ -498,25 +494,25 @@ def _show_frames(self) -> None: try: n_frame = self.TimeLine.get_frame() except EOFError: - self.update_status("No more frames in the timeline") self._event_playback.clear() break - if n_frame is not None and n_frame.index != last_shown_frame_index: - self.Player.show_frame(n_frame.frame) - last_shown_frame_index = n_frame.index + if n_frame is not None: + if n_frame.index != last_shown_frame_index: # check if frame is really changed + self.logger.info(f"REQ: {self.TimeLine.last_requested_index}, SHOW: {n_frame.index}") + self.Player.show_frame(n_frame.frame) + last_shown_frame_index = n_frame.index if self.TimeLine.last_returned_index is None: self._status("Time position", "There are no ready frames") else: if not self._event_rewind.is_set(): self.position.set(self.TimeLine.last_returned_index) - if self.TimeLine.last_returned_index: self._status("Time position", seconds_to_hmsms(self.TimeLine.last_returned_index * self.frame_handler.frame_time)) - self._status("Last shown/rendered frame", f"{self.TimeLine.last_returned_index}/{self.TimeLine.last_added_index}") + self._status("Last shown/rendered frame/Lag", f"{self.TimeLine.last_returned_index}/{self.TimeLine.last_added_index}/{self.TimeLine.display_frame_lag}") loop_time = time.perf_counter() - start_time # time for the current loop, sec sleep_time = self.frame_handler.frame_time - loop_time # time to wait for the next loop, sec if sleep_time > 0: time.sleep(sleep_time) - self.update_status("_show_frames loop done") + self.logger.info("show_frames loop done") def extract_frames(self) -> bool: if self._prepare_frames is not False and not self._is_target_frames_extracted: From fe6499fb475675125f214e99641c2fa72e088316 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:16:31 +0400 Subject: [PATCH 13/38] parameter renamed --- sinner/gui/GUIModel.py | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 04fdd870..6e33115c 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -388,7 +388,7 @@ def __start_processing(self, start_frame: int) -> None: if not self._event_processing.is_set(): self._event_processing.set() self._process_frames_thread = threading.Thread(target=self._process_frames, name="_process_frames", kwargs={ - 'start_frame': start_frame, + 'next_frame': start_frame, 'end_frame': self.frame_handler.fc }) self._process_frames_thread.daemon = True @@ -413,10 +413,10 @@ def __stop_playback(self) -> None: self._show_frames_thread.join(1) # timeout is required to avoid problem with a wiggling navigation slider self._show_frames_thread = None - def _process_frames(self, start_frame: int, end_frame: int) -> None: + def _process_frames(self, next_frame: int, end_frame: int) -> None: """ renders all frames between start_frame and end_frame - :param start_frame: + :param next_frame: :param end_frame: """ @@ -439,15 +439,15 @@ def process_done(future_: Future[float | None]) -> None: futures: list[Future[float | None]] = [] with ThreadPoolExecutor(max_workers=self.execution_threads) as executor: # this adds processing operations into a queue - while start_frame <= end_frame: + while next_frame <= end_frame: if self._event_rewind.is_set(): - start_frame = self._event_rewind.tag or 0 + next_frame = self._event_rewind.tag or 0 self._event_rewind.clear() - if start_frame not in processing and not self.TimeLine.has_index(start_frame): - # self.logger.info(f"Submit to processing frame {start_frame}") - processing.append(start_frame) - future: Future[float | None] = executor.submit(self._process_frame, start_frame) + if next_frame not in processing and not self.TimeLine.has_index(next_frame): + # self.logger.info(f"Submit to processing frame {next_frame}") + processing.append(next_frame) + future: Future[float | None] = executor.submit(self._process_frame, next_frame) future.add_done_callback(process_done) futures.append(future) @@ -462,8 +462,8 @@ def process_done(future_: Future[float | None]) -> None: self._average_frame_skip.update(self.frame_handler.fps / self._processing_fps) - start_frame += math.ceil(self._average_frame_skip.get_average()) + self.TimeLine.current_frame_miss - self.logger.info(f"NEXT: {start_frame}, MISS: {self.TimeLine.current_frame_miss}, AVG: {self._average_frame_skip.get_average()} ") + next_frame += math.ceil(self._average_frame_skip.get_average()) + self.TimeLine.current_frame_miss + self.logger.info(f"NEXT: {next_frame}, MISS: {self.TimeLine.current_frame_miss}, AVG: {self._average_frame_skip.get_average()} ") self.logger.info("process_frames loop done") From fea0bdb829e2a16debbe57ddd12619be2527edb7 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:22:16 +0400 Subject: [PATCH 14/38] Do not display information which is not really required --- sinner/gui/GUIModel.py | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 6e33115c..6dfde195 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -430,9 +430,7 @@ def process_done(future_: Future[float | None]) -> None: self._processing_fps = 1 / self._average_processing_time.get_average() if self._biggest_processed_frame < frame_index: self._biggest_processed_frame = frame_index - # self.logger.info(f"self.__last_processed_frame = {self._biggest_processed_frame}") - self._status("Processing FPS/Last frame", f"{round(self._processing_fps, 4)}/{round(1 / process_time, 4)}") - self._status("Frame lag/Play frame lag", f"{self.TimeLine.frame_lag}/{self.TimeLine.display_frame_lag}") + self._status("Average processing speed", f"{round(self._processing_fps, 4)} FPS") futures.remove(future_) processing: List[int] = [] # list of frames currently being processed @@ -445,7 +443,6 @@ def process_done(future_: Future[float | None]) -> None: self._event_rewind.clear() if next_frame not in processing and not self.TimeLine.has_index(next_frame): - # self.logger.info(f"Submit to processing frame {next_frame}") processing.append(next_frame) future: Future[float | None] = executor.submit(self._process_frame, next_frame) future.add_done_callback(process_done) @@ -454,7 +451,7 @@ def process_done(future_: Future[float | None]) -> None: if len(futures) >= self.execution_threads: futures[:1][0].result() - self._status("Memory usage(resident/virtual)", self.get_mem_usage()) + self._status("Memory usage (resident/virtual)", self.get_mem_usage()) if not self._event_processing.is_set(): executor.shutdown(wait=False, cancel_futures=True) @@ -507,7 +504,6 @@ def _show_frames(self) -> None: if not self._event_rewind.is_set(): self.position.set(self.TimeLine.last_returned_index) self._status("Time position", seconds_to_hmsms(self.TimeLine.last_returned_index * self.frame_handler.frame_time)) - self._status("Last shown/rendered frame/Lag", f"{self.TimeLine.last_returned_index}/{self.TimeLine.last_added_index}/{self.TimeLine.display_frame_lag}") loop_time = time.perf_counter() - start_time # time for the current loop, sec sleep_time = self.frame_handler.frame_time - loop_time # time to wait for the next loop, sec if sleep_time > 0: From e6f7171ac55f9e0f495f10b57239d88fcade9a10 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:23:07 +0400 Subject: [PATCH 15/38] Remove debug event handlers --- sinner/gui/GUIModel.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 6dfde195..7748aff7 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -167,9 +167,9 @@ def __init__(self, parameters: Namespace, pb_control: ProgressBarManager, status self._status = status_callback self._status("Time position", seconds_to_hmsms(0)) - self._event_processing = Event(on_set_callback=lambda: self.update_status("PROCESSING: ON"), on_clear_callback=lambda: self.update_status("PROCESSING: OFF")) - self._event_playback = Event(on_set_callback=lambda: self.update_status("PLAYBACK: ON"), on_clear_callback=lambda: self.update_status("PLAYBACK: OFF")) - self._event_rewind = Event(on_set_callback=lambda: self.update_status("REWIND EVENT SET"), on_clear_callback=lambda: self.update_status("REWIND EVENT CLEAR")) + self._event_processing = Event() + self._event_playback = Event() + self._event_rewind = Event() def reload_parameters(self) -> None: self.clear_previews() From 8c7de39e44d738e80b4e163ab322257f052ad4db Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:24:03 +0400 Subject: [PATCH 16/38] Remove framedrop property --- sinner/gui/GUIModel.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 7748aff7..f2ee8865 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -329,14 +329,6 @@ def set_previews(self, position: int, previews: FramesList) -> None: def clear_previews(self) -> None: self._previews.clear() - @property - def framedrop(self) -> int: - return self._framedrop - - @framedrop.setter - def framedrop(self, value: int) -> None: - self._framedrop = value - @property def player_is_started(self) -> bool: return self._event_processing.is_set() or self._event_playback.is_set() From 48b0dbdeb2d5609035f3178ee337b0cfae5c3845 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:26:05 +0400 Subject: [PATCH 17/38] remove framedrop controls and handlers --- sinner/gui/GUIForm.py | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/sinner/gui/GUIForm.py b/sinner/gui/GUIForm.py index c44914d9..0dd03fe2 100644 --- a/sinner/gui/GUIForm.py +++ b/sinner/gui/GUIForm.py @@ -176,10 +176,6 @@ def on_self_run_button_press() -> None: self.ControlsFrame = Frame(self.BaseFrame) self.SubControlsFrame = Frame(self.ControlsFrame) - self.FrameDropLabel: Label = Label(self.SubControlsFrame, text="Framedrop (-1 to auto):") - self.FrameDropSpinbox: Spinbox = Spinbox(self.SubControlsFrame, from_=-1, to=9999, increment=1, command=lambda: self.on_framedrop_change()) # -1 for auto - self.FrameDropSpinbox.bind('', lambda event: self.on_framedrop_change()) - self.FrameDropSpinbox.set(-1) self.QualityScaleLabel: Label = Label(self.SubControlsFrame, text="Quality scale:") @@ -295,8 +291,6 @@ def draw_controls(self) -> None: self.ButtonsFrame.pack(anchor=CENTER, expand=False, side=LEFT, fill=BOTH) self.BaseFrame.pack(anchor=NW, expand=False, side=TOP, fill=X) - self.FrameDropLabel.pack(anchor=NW, side=LEFT) - self.FrameDropSpinbox.pack(anchor=NW, side=LEFT) self.QualityScaleLabel.pack(anchor=NW, side=LEFT) self.QualityScaleSpinbox.pack(anchor=NW, expand=False, fill=BOTH, side=LEFT) @@ -404,10 +398,6 @@ def on_quality_scale_change(self, frame_value: int) -> None: # the quality applies only when playing, the preview always renders with 100% resolution self.StatusBar.item('Render size', f"{self.GUIModel.quality}% ({int(self.GUIModel.frame_handler.resolution[0] * self.GUIModel.quality / 100)}x{int(self.GUIModel.frame_handler.resolution[1] * self.GUIModel.quality / 100)})") - def on_framedrop_change(self) -> object | str | list[str] | tuple[str, ...]: - self.GUIModel.framedrop = int(self.FrameDropSpinbox.get()) - return self.FrameDropSpinbox.get() # Required by Tkinter design, but not really used - def library_add(self, paths: List[str], reload: bool = False) -> None: """ Add something to the sources library From 68d779ad23d14a11fab41fb9ccd05ee638751864 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 17:59:25 +0400 Subject: [PATCH 18/38] introduce lookahead delta to adjust frames synchronization --- sinner/gui/GUIModel.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index f2ee8865..e5a5ada4 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -1,5 +1,4 @@ import logging -import math import os import threading import time @@ -427,6 +426,7 @@ def process_done(future_: Future[float | None]) -> None: processing: List[int] = [] # list of frames currently being processed futures: list[Future[float | None]] = [] + processing_delta: int = 0 # additional lookahead to adjust frames synchronization with ThreadPoolExecutor(max_workers=self.execution_threads) as executor: # this adds processing operations into a queue while next_frame <= end_frame: @@ -451,8 +451,13 @@ def process_done(future_: Future[float | None]) -> None: self._average_frame_skip.update(self.frame_handler.fps / self._processing_fps) - next_frame += math.ceil(self._average_frame_skip.get_average()) + self.TimeLine.current_frame_miss - self.logger.info(f"NEXT: {next_frame}, MISS: {self.TimeLine.current_frame_miss}, AVG: {self._average_frame_skip.get_average()} ") + if self._biggest_processed_frame > self.TimeLine.last_requested_index + self.TimeLine.current_frame_miss and processing_delta > 0: + processing_delta -= 1 + elif self._biggest_processed_frame < self.TimeLine.last_requested_index: + processing_delta += 1 + + next_frame += int(self._average_frame_skip.get_average()) + processing_delta + self.logger.info(f"NEXT: {next_frame}, DELTA: {processing_delta}, MISS: {self.TimeLine.current_frame_miss}, AVG: {self._average_frame_skip.get_average()} ") self.logger.info("process_frames loop done") From 8e58a2fea13315d99cbd2202e649f285994e8c32 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 18:00:31 +0400 Subject: [PATCH 19/38] debug logging removed --- sinner/gui/GUIModel.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index e5a5ada4..be8ced64 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -1,4 +1,3 @@ -import logging import os import threading import time @@ -151,7 +150,6 @@ def rules(self) -> Rules: def __init__(self, parameters: Namespace, pb_control: ProgressBarManager, status_callback: Callable[[str, str], Any], on_close_event: Event | None = None): self.parameters = parameters - self.logger = logging.getLogger("GUI Model") super().__init__(parameters) self._processors = {} if self.bootstrap_processors: @@ -457,9 +455,6 @@ def process_done(future_: Future[float | None]) -> None: processing_delta += 1 next_frame += int(self._average_frame_skip.get_average()) + processing_delta - self.logger.info(f"NEXT: {next_frame}, DELTA: {processing_delta}, MISS: {self.TimeLine.current_frame_miss}, AVG: {self._average_frame_skip.get_average()} ") - - self.logger.info("process_frames loop done") def _process_frame(self, frame_index: int) -> tuple[float, int] | None: """ @@ -476,7 +471,6 @@ def _process_frame(self, frame_index: int) -> tuple[float, int] | None: with PerfCounter() as frame_render_time: for _, processor in self.processors.items(): n_frame.frame = processor.process_frame(n_frame.frame) - self.logger.info(f"DONE: {n_frame.index}") self.TimeLine.add_frame(n_frame) return frame_render_time.execution_time, n_frame.index @@ -492,7 +486,6 @@ def _show_frames(self) -> None: break if n_frame is not None: if n_frame.index != last_shown_frame_index: # check if frame is really changed - self.logger.info(f"REQ: {self.TimeLine.last_requested_index}, SHOW: {n_frame.index}") self.Player.show_frame(n_frame.frame) last_shown_frame_index = n_frame.index if self.TimeLine.last_returned_index is None: @@ -505,7 +498,6 @@ def _show_frames(self) -> None: sleep_time = self.frame_handler.frame_time - loop_time # time to wait for the next loop, sec if sleep_time > 0: time.sleep(sleep_time) - self.logger.info("show_frames loop done") def extract_frames(self) -> bool: if self._prepare_frames is not False and not self._is_target_frames_extracted: From b2f234907ce50cbac2a4a3ff9c11170c56727e2c Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 18:08:50 +0400 Subject: [PATCH 20/38] fixme added --- sinner/gui/GUIModel.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index be8ced64..ff1302e6 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -419,7 +419,7 @@ def process_done(future_: Future[float | None]) -> None: self._processing_fps = 1 / self._average_processing_time.get_average() if self._biggest_processed_frame < frame_index: self._biggest_processed_frame = frame_index - self._status("Average processing speed", f"{round(self._processing_fps, 4)} FPS") + self._status("Average processing speed", f"{round(self._processing_fps, 4)} FPS") # fixme: execution-threads=1 prevents value to display futures.remove(future_) processing: List[int] = [] # list of frames currently being processed From ddeb447e5395d1ddc7dc3382330e2eea03497c7a Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 18:20:53 +0400 Subject: [PATCH 21/38] update condition to avoid synchronization troubles --- sinner/gui/GUIModel.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index ff1302e6..7ad27e0d 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -488,12 +488,12 @@ def _show_frames(self) -> None: if n_frame.index != last_shown_frame_index: # check if frame is really changed self.Player.show_frame(n_frame.frame) last_shown_frame_index = n_frame.index - if self.TimeLine.last_returned_index is None: - self._status("Time position", "There are no ready frames") - else: if not self._event_rewind.is_set(): - self.position.set(self.TimeLine.last_returned_index) - self._status("Time position", seconds_to_hmsms(self.TimeLine.last_returned_index * self.frame_handler.frame_time)) + if self.TimeLine.last_returned_index is None: + self._status("Time position", "There are no ready frames") + else: + self.position.set(self.TimeLine.last_returned_index) + self._status("Time position", seconds_to_hmsms(self.TimeLine.last_returned_index * self.frame_handler.frame_time)) loop_time = time.perf_counter() - start_time # time for the current loop, sec sleep_time = self.frame_handler.frame_time - loop_time # time to wait for the next loop, sec if sleep_time > 0: From c9a5d236d2b198adc8dad2ee119897394836fd27 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 18:50:48 +0400 Subject: [PATCH 22/38] return previous code (as it works) --- sinner/gui/GUIModel.py | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 7ad27e0d..c82b21ba 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -488,11 +488,12 @@ def _show_frames(self) -> None: if n_frame.index != last_shown_frame_index: # check if frame is really changed self.Player.show_frame(n_frame.frame) last_shown_frame_index = n_frame.index - if not self._event_rewind.is_set(): - if self.TimeLine.last_returned_index is None: - self._status("Time position", "There are no ready frames") - else: + if self.TimeLine.last_returned_index is None: + self._status("Time position", "There are no ready frames") + else: + if not self._event_rewind.is_set(): self.position.set(self.TimeLine.last_returned_index) + if self.TimeLine.last_returned_index: self._status("Time position", seconds_to_hmsms(self.TimeLine.last_returned_index * self.frame_handler.frame_time)) loop_time = time.perf_counter() - start_time # time for the current loop, sec sleep_time = self.frame_handler.frame_time - loop_time # time to wait for the next loop, sec From 0b999fb5a91550c38a44252cef87e386a02893ae Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 19:14:59 +0400 Subject: [PATCH 23/38] Remove Status.logfile parameter. Use logging module for logging --- sin.py | 2 +- sinner/Status.py | 29 ++++++++++------------------- 2 files changed, 11 insertions(+), 20 deletions(-) diff --git a/sin.py b/sin.py index 9323de52..45f405ba 100644 --- a/sin.py +++ b/sin.py @@ -49,7 +49,7 @@ def run(self) -> None: if __name__ == '__main__': logging.basicConfig( level=logging.DEBUG, - format='%(name)s - %(message)s', + format='%(name)s: %(message)s', filename='debug.log', filemode='w' ) diff --git a/sinner/Status.py b/sinner/Status.py index e2eada5c..d4c7c6f6 100644 --- a/sinner/Status.py +++ b/sinner/Status.py @@ -1,11 +1,11 @@ import locale +import logging import shutil import sys from enum import Enum from colorama import Fore, Back -from sinner.typing import UTF8 from sinner.validators.AttributeLoader import AttributeLoader, Rules @@ -19,18 +19,12 @@ def __str__(self) -> str: class Status(AttributeLoader): - logfile: str + logger: logging.Logger = logging.getLogger("Status") emoji: str = '๐Ÿ˜ˆ' enable_emoji: bool def rules(self) -> Rules: return [ - { - 'parameter': {'log', 'logfile'}, - 'attribute': 'logfile', - 'valid': lambda: self.log_write(), - 'help': 'Path to the log file' - }, { 'parameter': {'enable-emoji'}, 'attribute': 'enable_emoji', @@ -91,15 +85,12 @@ def update_status(self, message: str, caller: str | None = None, mood: Mood = Mo if position is None: sys.stdout.write("\n") self.restore_position(position) - self.log_write(f'{emoji}{caller}: {message}') + log_level = logging.DEBUG + if mood is Mood.GOOD: + log_level = logging.INFO + elif mood is Mood.BAD: + log_level = logging.ERROR + self.logger.log(level=log_level, msg=f"{emoji}{caller}: {message}") - def log_write(self, content: str | None = None) -> bool: - try: - if self.logfile: - with open(self.logfile, "w", encoding=UTF8) as log: - if content: - log.write(content) - return True - except Exception: - pass - return False + def log(self, level=logging.INFO, msg="", *args, **kwargs) -> None: + self.logger.log(level, msg, args, **kwargs) From 28daf0424e4ab0ab3eae3318ab57385add429698 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Mon, 7 Oct 2024 22:58:12 +0400 Subject: [PATCH 24/38] Return back some logging Some adjustments to compensation logic --- sinner/gui/GUIModel.py | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index c82b21ba..385f7d8a 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -449,12 +449,15 @@ def process_done(future_: Future[float | None]) -> None: self._average_frame_skip.update(self.frame_handler.fps / self._processing_fps) - if self._biggest_processed_frame > self.TimeLine.last_requested_index + self.TimeLine.current_frame_miss and processing_delta > 0: + if self.TimeLine.last_added_index > self.TimeLine.last_requested_index + self.TimeLine.current_frame_miss and processing_delta > self._average_frame_skip.get_average(): processing_delta -= 1 - elif self._biggest_processed_frame < self.TimeLine.last_requested_index: + elif self.TimeLine.last_added_index < self.TimeLine.last_requested_index: processing_delta += 1 - - next_frame += int(self._average_frame_skip.get_average()) + processing_delta + step = int(self._average_frame_skip.get_average()) + processing_delta + if step < 1: # preventing going backwards + step = 1 + next_frame += step + self.logger.info(f"NEXT: {next_frame}, STEP: {step}, DELTA: {processing_delta}, LAST: {self.TimeLine.last_added_index}, AVG: {self._average_frame_skip.get_average()} ") def _process_frame(self, frame_index: int) -> tuple[float, int] | None: """ @@ -471,6 +474,7 @@ def _process_frame(self, frame_index: int) -> tuple[float, int] | None: with PerfCounter() as frame_render_time: for _, processor in self.processors.items(): n_frame.frame = processor.process_frame(n_frame.frame) + self.logger.info(f"DONE: {n_frame.index}") self.TimeLine.add_frame(n_frame) return frame_render_time.execution_time, n_frame.index @@ -486,6 +490,7 @@ def _show_frames(self) -> None: break if n_frame is not None: if n_frame.index != last_shown_frame_index: # check if frame is really changed + self.logger.info(f"REQ: {self.TimeLine.last_requested_index}, SHOW: {n_frame.index}, ASYNC: {self.TimeLine.last_requested_index - n_frame.index}") self.Player.show_frame(n_frame.frame) last_shown_frame_index = n_frame.index if self.TimeLine.last_returned_index is None: From dbafec1ea25b4d02e6561c596c965f285e08b80f Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 10:43:55 +0400 Subject: [PATCH 25/38] Unused variable --- sinner/gui/GUIModel.py | 1 - 1 file changed, 1 deletion(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 385f7d8a..948acc40 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -69,7 +69,6 @@ class GUIModel(Status): # internal variables _is_target_frames_extracted: bool = False - _last_requested_frame: int = 0 # the last requested frame inside processing, needed to avoid re-requesting on same frames _biggest_processed_frame: int = 0 # the last (by number) processed frame index, needed to indicate if processing gap is too big _largest_miss: int = 0 # experimental _average_processing_time: MovingAverage = MovingAverage(window_size=10) # Calculator for the average processing time From f440291ff102b4d453049476678ba2b6b2d9a6f1 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 10:44:11 +0400 Subject: [PATCH 26/38] Unused variable --- sinner/gui/GUIModel.py | 1 - 1 file changed, 1 deletion(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 948acc40..00b00c0e 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -70,7 +70,6 @@ class GUIModel(Status): # internal variables _is_target_frames_extracted: bool = False _biggest_processed_frame: int = 0 # the last (by number) processed frame index, needed to indicate if processing gap is too big - _largest_miss: int = 0 # experimental _average_processing_time: MovingAverage = MovingAverage(window_size=10) # Calculator for the average processing time _average_frame_skip: MovingAverage = MovingAverage(window_size=10) # Calculator for the average frame skip From a95e873fded8e179cec4b7cb6cd144411c962e3f Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 11:04:08 +0400 Subject: [PATCH 27/38] Add tests for MovingAverage --- tests/models/test_moving_average.py | 113 ++++++++++++++++++++++++++++ 1 file changed, 113 insertions(+) create mode 100644 tests/models/test_moving_average.py diff --git a/tests/models/test_moving_average.py b/tests/models/test_moving_average.py new file mode 100644 index 00000000..8aecb673 --- /dev/null +++ b/tests/models/test_moving_average.py @@ -0,0 +1,113 @@ +import pytest +from collections import deque +from typing import List + +from sinner.models.MovingAverage import MovingAverage + + +@pytest.fixture +def ma_with_window(): + return MovingAverage(window_size=3) + + +@pytest.fixture +def ma_without_window(): + return MovingAverage() + + +def test_init_with_window(): + ma = MovingAverage(window_size=5) + assert ma.window_size == 5 + assert isinstance(ma.window, deque) + assert ma.window.maxlen == 5 + + +def test_init_without_window(): + ma = MovingAverage() + assert ma.window_size == 0 + assert ma.sum == 0 + assert ma.count == 0 + + +def test_update_with_window(ma_with_window): + ma_with_window.update(1) + ma_with_window.update(2) + ma_with_window.update(3) + ma_with_window.update(4) + assert list(ma_with_window.window) == [2, 3, 4] + + +def test_update_without_window(ma_without_window): + ma_without_window.update(1) + ma_without_window.update(2) + ma_without_window.update(3) + assert ma_without_window.sum == 6 + assert ma_without_window.count == 3 + + +def test_get_average_with_window(ma_with_window): + ma_with_window.update(1) + assert ma_with_window.get_average() == 1 + ma_with_window.update(2) + assert ma_with_window.get_average() == 1.5 + ma_with_window.update(3) + assert ma_with_window.get_average() == 2 + ma_with_window.update(4) + assert ma_with_window.get_average() == 3 + + +def test_get_average_without_window(ma_without_window): + ma_without_window.update(1) + assert ma_without_window.get_average() == 1 + ma_without_window.update(2) + assert ma_without_window.get_average() == 1.5 + ma_without_window.update(3) + assert ma_without_window.get_average() == 2 + + +def test_reset_with_window(ma_with_window): + ma_with_window.update(1) + ma_with_window.update(2) + ma_with_window.reset() + assert len(ma_with_window.window) == 0 + + +def test_reset_without_window(ma_without_window): + ma_without_window.update(1) + ma_without_window.update(2) + ma_without_window.reset() + assert ma_without_window.sum == 0 + assert ma_without_window.count == 0 + + +def test_empty_average(): + ma = MovingAverage(window_size=3) + assert ma.get_average() == 0 + ma = MovingAverage() + assert ma.get_average() == 0 + + +@pytest.mark.parametrize("values, expected", [ + ([1, 2, 3, 4, 5], 4), + ([10, 20, 30], 20), + ([1], 1), + ([], 0) +]) +def test_multiple_updates_with_window(values: List[float], expected: float): + ma = MovingAverage(window_size=3) + for value in values: + ma.update(value) + assert ma.get_average() == expected + + +@pytest.mark.parametrize("values, expected", [ + ([1, 2, 3, 4, 5], 3), + ([10, 20, 30], 20), + ([1], 1), + ([], 0) +]) +def test_multiple_updates_without_window(values: List[float], expected: float): + ma = MovingAverage() + for value in values: + ma.update(value) + assert ma.get_average() == expected From 9ba0e255159259a59f118088d12e944d67e84752 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 12:50:48 +0400 Subject: [PATCH 28/38] remove obsolete test --- tests/test_status.py | 6 ------ 1 file changed, 6 deletions(-) diff --git a/tests/test_status.py b/tests/test_status.py index 109e3c0b..327e153f 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -43,9 +43,3 @@ def test_status_force_emoji() -> None: with open(test_logfile, encoding=UTF8) as file: actual_content = file.read() assert actual_content.find('๐Ÿ˜ˆself: test') != -1 - - -def test_status_error() -> None: - parameters: Namespace = Parameters(f'--log="/dev/random/incorrect:file\\path*?"').parameters - with pytest.raises(LoadingException): - assert Status(parameters=parameters) From bf34b4f3fb512c01988d3d4d0968de6e20b8d0fc Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 12:55:48 +0400 Subject: [PATCH 29/38] remove obsolete test fix tests --- tests/constants.py | 1 - tests/test_status.py | 30 +++++------------------------- 2 files changed, 5 insertions(+), 26 deletions(-) diff --git a/tests/constants.py b/tests/constants.py index 2d4078be..6cf3b9bf 100644 --- a/tests/constants.py +++ b/tests/constants.py @@ -36,4 +36,3 @@ test_config: str = resolve_relative_path('data/test.ini', __file__) test_config_bak: str = resolve_relative_path('data/test.ini.bak', __file__) -test_logfile: str = resolve_relative_path('data/test.log', __file__) diff --git a/tests/test_status.py b/tests/test_status.py index 327e153f..696fef4b 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -1,19 +1,9 @@ -import os from argparse import Namespace from colorama import Fore, Back -from sympy.testing import pytest from sinner.Parameters import Parameters from sinner.Status import Status, Mood -from sinner.typing import UTF8 -from sinner.validators.LoaderException import LoadingException -from tests.constants import test_logfile - - -def setup_function(): - if os.path.exists(test_logfile): - os.remove(test_logfile) def test_status(capsys) -> None: @@ -25,21 +15,11 @@ def test_status(capsys) -> None: assert captured.find(f'{Fore.BLACK}{Back.RED}self: test{Back.RESET}{Fore.RESET}') != -1 -def test_status_log() -> None: - parameters: Namespace = Parameters(f'--log="{test_logfile}" --enable_emoji=0').parameters +def test_status_force_emoji(capsys) -> None: + parameters: Namespace = Parameters(f'--enable_emoji=1').parameters status = Status(parameters=parameters) status.update_status('test', 'self', Mood.BAD) - with open(test_logfile, encoding=UTF8) as file: - actual_content = file.read() - assert actual_content.find('self: test') != -1 - - -def test_status_force_emoji() -> None: - parameters: Namespace = Parameters(f'--log="{test_logfile}" --enable_emoji=1').parameters - status = Status(parameters=parameters) - - status.update_status('test', 'self', Mood.BAD) - with open(test_logfile, encoding=UTF8) as file: - actual_content = file.read() - assert actual_content.find('๐Ÿ˜ˆself: test') != -1 + captured = capsys.readouterr() + captured = captured.out.strip() + assert captured.find('๐Ÿ˜ˆ') != -1 From af5b8e6382c7628aa377030d9972a9369d9121d7 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 12:58:42 +0400 Subject: [PATCH 30/38] remove debugging --- sinner/gui/GUIModel.py | 3 --- 1 file changed, 3 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 00b00c0e..7d97cca5 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -455,7 +455,6 @@ def process_done(future_: Future[float | None]) -> None: if step < 1: # preventing going backwards step = 1 next_frame += step - self.logger.info(f"NEXT: {next_frame}, STEP: {step}, DELTA: {processing_delta}, LAST: {self.TimeLine.last_added_index}, AVG: {self._average_frame_skip.get_average()} ") def _process_frame(self, frame_index: int) -> tuple[float, int] | None: """ @@ -472,7 +471,6 @@ def _process_frame(self, frame_index: int) -> tuple[float, int] | None: with PerfCounter() as frame_render_time: for _, processor in self.processors.items(): n_frame.frame = processor.process_frame(n_frame.frame) - self.logger.info(f"DONE: {n_frame.index}") self.TimeLine.add_frame(n_frame) return frame_render_time.execution_time, n_frame.index @@ -488,7 +486,6 @@ def _show_frames(self) -> None: break if n_frame is not None: if n_frame.index != last_shown_frame_index: # check if frame is really changed - self.logger.info(f"REQ: {self.TimeLine.last_requested_index}, SHOW: {n_frame.index}, ASYNC: {self.TimeLine.last_requested_index - n_frame.index}") self.Player.show_frame(n_frame.frame) last_shown_frame_index = n_frame.index if self.TimeLine.last_returned_index is None: From 7d5568abfc9f85a0c883befb6665516f579265a3 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:12:19 +0400 Subject: [PATCH 31/38] return constant --- tests/constants.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/constants.py b/tests/constants.py index 6cf3b9bf..2d4078be 100644 --- a/tests/constants.py +++ b/tests/constants.py @@ -36,3 +36,4 @@ test_config: str = resolve_relative_path('data/test.ini', __file__) test_config_bak: str = resolve_relative_path('data/test.ini.bak', __file__) +test_logfile: str = resolve_relative_path('data/test.log', __file__) From cbd0fd5d4ad15b4fb49f0a7db78c969e735c8d0a Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:38:48 +0400 Subject: [PATCH 32/38] remove logging initialization --- sin.py | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/sin.py b/sin.py index 45f405ba..d846124b 100644 --- a/sin.py +++ b/sin.py @@ -1,5 +1,4 @@ #!/usr/bin/env python3 -import logging import os import signal import sys @@ -47,15 +46,6 @@ def run(self) -> None: if __name__ == '__main__': - logging.basicConfig( - level=logging.DEBUG, - format='%(name)s: %(message)s', - filename='debug.log', - filemode='w' - ) - logging.getLogger('PIL.PngImagePlugin').setLevel(logging.CRITICAL + 1) - logging.getLogger('PIL.PngImagePlugin').addHandler(logging.NullHandler()) - # todo: remnants of roop code, needs to be checked # single thread doubles cuda performance - needs to be set before torch import if any(arg.startswith('--execution-provider') for arg in sys.argv): From 9336563440f6a0ace32d0fe488bc744f2009c045 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:39:40 +0400 Subject: [PATCH 33/38] return logfile parameter and handle logs with logger module --- sinner/Status.py | 38 ++++++++++++++++++++++++++++++++++---- 1 file changed, 34 insertions(+), 4 deletions(-) diff --git a/sinner/Status.py b/sinner/Status.py index d4c7c6f6..abe1a632 100644 --- a/sinner/Status.py +++ b/sinner/Status.py @@ -19,12 +19,20 @@ def __str__(self) -> str: class Status(AttributeLoader): - logger: logging.Logger = logging.getLogger("Status") + logfile: str | None = None + logger: logging.Logger | None = None emoji: str = '๐Ÿ˜ˆ' enable_emoji: bool def rules(self) -> Rules: return [ + { + 'parameter': {'log', 'logfile'}, + 'attribute': 'logfile', + 'default': None, + 'valid': lambda: self.init_logger(), + 'help': 'Path to the log file' + }, { 'parameter': {'enable-emoji'}, 'attribute': 'enable_emoji', @@ -90,7 +98,29 @@ def update_status(self, message: str, caller: str | None = None, mood: Mood = Mo log_level = logging.INFO elif mood is Mood.BAD: log_level = logging.ERROR - self.logger.log(level=log_level, msg=f"{emoji}{caller}: {message}") + self.log(level=log_level, msg=f"{emoji}{caller}: {message}") + + def log(self, level=logging.INFO, msg="") -> None: + if self.logger: + self.logger.log(level, msg) + + def init_logger(self) -> bool: + try: + if self.logfile: + self.logger = logging.getLogger(__name__) + self.logger.setLevel(logging.DEBUG) + + file_handler = logging.FileHandler(self.logfile, encoding='utf-8') + file_handler.setLevel(logging.DEBUG) - def log(self, level=logging.INFO, msg="", *args, **kwargs) -> None: - self.logger.log(level, msg, args, **kwargs) + formatter = logging.Formatter('%(levelname)s: %(message)s') + file_handler.setFormatter(formatter) + + self.logger.addHandler(file_handler) + # + # logging.getLogger('PIL.PngImagePlugin').setLevel(logging.CRITICAL + 1) + # logging.getLogger('PIL.PngImagePlugin').addHandler(logging.NullHandler()) + return True + except Exception: + pass + return False From f3693c28f96da9751907fbab9d344141ab49eeba Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:39:58 +0400 Subject: [PATCH 34/38] return logger tests --- tests/test_status.py | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/tests/test_status.py b/tests/test_status.py index 696fef4b..11fe2b99 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -1,9 +1,13 @@ from argparse import Namespace +import pytest from colorama import Fore, Back from sinner.Parameters import Parameters from sinner.Status import Status, Mood +from sinner.typing import UTF8 +from sinner.validators.LoaderException import LoadingException +from tests.constants import test_logfile def test_status(capsys) -> None: @@ -23,3 +27,19 @@ def test_status_force_emoji(capsys) -> None: captured = capsys.readouterr() captured = captured.out.strip() assert captured.find('๐Ÿ˜ˆ') != -1 + + +def test_status_log() -> None: + parameters: Namespace = Parameters(f'--log="{test_logfile}" --enable_emoji=0').parameters + status = Status(parameters=parameters) + + status.update_status('test', 'self', Mood.BAD) + with open(test_logfile, encoding=UTF8) as file: + actual_content = file.read() + assert actual_content.find('self: test') != -1 + + +def test_status_error() -> None: + parameters: Namespace = Parameters(f'--log="/dev/random/incorrect:file\\path*?"').parameters + with pytest.raises(LoadingException): + assert Status(parameters=parameters) From 984606e5e9bae81f4ce647a99bf09129c476a6e7 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:41:26 +0400 Subject: [PATCH 35/38] return previous test implementation --- tests/test_status.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tests/test_status.py b/tests/test_status.py index 11fe2b99..ac2411b5 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -19,14 +19,14 @@ def test_status(capsys) -> None: assert captured.find(f'{Fore.BLACK}{Back.RED}self: test{Back.RESET}{Fore.RESET}') != -1 -def test_status_force_emoji(capsys) -> None: - parameters: Namespace = Parameters(f'--enable_emoji=1').parameters +def test_status_force_emoji() -> None: + parameters: Namespace = Parameters(f'--log="{test_logfile}" --enable_emoji=1').parameters status = Status(parameters=parameters) status.update_status('test', 'self', Mood.BAD) - captured = capsys.readouterr() - captured = captured.out.strip() - assert captured.find('๐Ÿ˜ˆ') != -1 + with open(test_logfile, encoding=UTF8) as file: + actual_content = file.read() + assert actual_content.find('๐Ÿ˜ˆself: test') != -1 def test_status_log() -> None: From 23401bffd501db1646032b3a9ea28cf9496adc60 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:47:55 +0400 Subject: [PATCH 36/38] type annotations added --- sinner/models/MovingAverage.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/sinner/models/MovingAverage.py b/sinner/models/MovingAverage.py index 4f129c92..739bcd7b 100644 --- a/sinner/models/MovingAverage.py +++ b/sinner/models/MovingAverage.py @@ -5,10 +5,10 @@ class MovingAverage: def __init__(self, window_size: int = 0): self.window_size = window_size if window_size > 0: - self.window = deque(maxlen=window_size) + self.window: deque[float] = deque(maxlen=window_size) else: - self.sum = 0 - self.count = 0 + self.sum: float = 0 + self.count: int = 0 def update(self, value: float) -> None: if self.window_size > 0: From 78ffa21882fb009581eb994258ed694e80ce9b78 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:49:27 +0400 Subject: [PATCH 37/38] type annotations fixed --- sinner/gui/GUIModel.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/sinner/gui/GUIModel.py b/sinner/gui/GUIModel.py index 7d97cca5..3457c75f 100644 --- a/sinner/gui/GUIModel.py +++ b/sinner/gui/GUIModel.py @@ -407,7 +407,7 @@ def _process_frames(self, next_frame: int, end_frame: int) -> None: :param end_frame: """ - def process_done(future_: Future[float | None]) -> None: + def process_done(future_: Future[tuple[float, int] | None]) -> None: if not future_.cancelled(): result = future_.result() if result: @@ -421,7 +421,7 @@ def process_done(future_: Future[float | None]) -> None: futures.remove(future_) processing: List[int] = [] # list of frames currently being processed - futures: list[Future[float | None]] = [] + futures: list[Future[tuple[float, int] | None]] = [] processing_delta: int = 0 # additional lookahead to adjust frames synchronization with ThreadPoolExecutor(max_workers=self.execution_threads) as executor: # this adds processing operations into a queue @@ -432,7 +432,7 @@ def process_done(future_: Future[float | None]) -> None: if next_frame not in processing and not self.TimeLine.has_index(next_frame): processing.append(next_frame) - future: Future[float | None] = executor.submit(self._process_frame, next_frame) + future: Future[tuple[float, int] | None] = executor.submit(self._process_frame, next_frame) future.add_done_callback(process_done) futures.append(future) From 4fcafffba8b7e2b5f75f5642c3c87c162605e4e2 Mon Sep 17 00:00:00 2001 From: Pozitronik Date: Tue, 8 Oct 2024 13:49:56 +0400 Subject: [PATCH 38/38] type annotations added --- sinner/Status.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sinner/Status.py b/sinner/Status.py index abe1a632..562b40b2 100644 --- a/sinner/Status.py +++ b/sinner/Status.py @@ -100,7 +100,7 @@ def update_status(self, message: str, caller: str | None = None, mood: Mood = Mo log_level = logging.ERROR self.log(level=log_level, msg=f"{emoji}{caller}: {message}") - def log(self, level=logging.INFO, msg="") -> None: + def log(self, level: int = logging.INFO, msg: str = "") -> None: if self.logger: self.logger.log(level, msg)