Core: log completion time if > 1.0 seconds per step #2345

Berserker66 · 2023-10-22T06:34:42Z

What is this fixing or adding?

adds rudimentary performance logging, for longer (async) generations it also gives you a bit of a progress/alive signal.

I consider this the first step of multiple towards having some more useful benchmarking.

How was this tested?

with a few thousand worlds

If this makes graphical changes, please attach screenshots.

worlds/AutoWorld.py

alwaysintreble · 2023-10-22T07:42:05Z

worlds/AutoWorld.py

@@ -115,6 +119,10 @@ def call_single(multiworld: "MultiWorld", method_name: str, player: int, *args:
            logging.error(message)
        raise e
    else:
+        taken = time.perf_counter()-start
+        if taken > 0.1:
+            perf_logger.info(f"Took {taken} seconds in {method} for player {player}, "


Suggested change

perf_logger.info(f"Took {taken} seconds in {method} for player {player}, "

perf_logger.info(f"Took {taken} seconds in {multiworld.worlds[player].__class__.__name__}'s {method.__name__} for player {player}.")

maybe?

maybe?

Sounds like you're trying to reinvent method.__qualname__.

I'd be fine with cutting away the ram address, but you're cutting away too much. It also would lose consistency with the error reporting.

Having something shorter (be it qualname or something similar) would make the lines way shorter and easier to understand.
(It doesn't really have to be consistent with error reporting since it's not an error. It's actually something that a normal user might see during normal operation.)
Also, since all values are gonna be greater than 0.1, I'd suggest formatting the numbers to two decimal places; again, to make it easier for the reader to parse the relevant information.

have you tried qualname? Because all it is is "World.set_rules", no matter which world

Strange. I had tested it.
Here's the output I get with {method.__qualname__} (and the threshold removed so that all stages will be printed).
For me it only printed World if it really executed the method of the base class where it was not overridden in the specific world. (And these should never go over the threshold in practice, since they are usually just pass)
(For reference, this was 3.8 on Windows)

tested on 3.11.6 and i'm seeing the same output. one interesting thing to note is that it doesn't show the class for methods where it's assigned rather than overridden, since those functions don't belong to the class.

That's unfortunate. Maybe we have to do something more verbose after all.

el-u · 2023-10-22T11:07:29Z

Are worlds now expected to do each step in less than 0.1s?
Any particular reason why this is not added to call_stage as well?

Berserker66 · 2023-10-22T17:26:02Z

Are worlds now expected to do each step in less than 0.1s?

Any particular reason why this is not added to call_stage as well?

1
No, but if you do it under that time people are less likely to complain. If you need a lot more than that, people might start to take notice. For example, since I introduced this, I learned that ALTTP create_regions gets longer the more other worlds are present, which is probably fixable. Though I have not yet gotten around to do that, it alerted me to that information.

2
oups

worlds/AutoWorld.py

el-u · 2023-10-22T21:29:51Z

worlds/AutoWorld.py

@@ -103,10 +106,23 @@ def __new__(mcs, name: str, bases: Tuple[type, ...], dct: Dict[str, Any]) -> Aut
        return new_class


+def _timed_call(method: Callable, *args: Any, multiworld: "MultiWorld" = None, player: int = None) -> Any:


Suggested change

def _timed_call(method: Callable, *args: Any, multiworld: "MultiWorld" = None, player: int = None) -> Any:

def _timed_call(method: Callable[..., Any], *args: Any,

multiworld: Optional["MultiWorld"] = None, player: Optional[int] = None) -> Any:

el-u

Would have preferred a cleaner output (see comment); functionality is fine.

black-sliver

Lgtm. With >1sec this should be fine on main.

Core: log completion time if > 0.1 seconds per step

b96410a

alwaysintreble reviewed Oct 22, 2023

View reviewed changes

ScootyPuffJr1 added is: refactor/cleanup Improvements to code/output readability or organizization. affects: core Issues/PRs that touch core and may need additional validation. labels Oct 22, 2023

Berserker66 added 2 commits October 22, 2023 19:22

Core: completion time logging refinement

481138e

Core: completion time logging typing

4ee2287

el-u reviewed Oct 22, 2023

View reviewed changes

worlds/AutoWorld.py Show resolved Hide resolved

Core: completion time logging sort stage calls

74ca3da

el-u reviewed Oct 22, 2023

View reviewed changes

Core: log perf typing and adjust to 1 second

539023b

el-u approved these changes Oct 25, 2023

View reviewed changes

Berserker66 changed the title ~~Core: log completion time if > 0.1 seconds per step~~ Core: log completion time if > 1.0 seconds per step Oct 25, 2023

Berserker66 and others added 3 commits October 26, 2023 03:16

use .__qualname__

c5c9cd7

Merge branch 'main' into core_log_perf

d84d4e7

Update AutoWorld.py

43855f5

black-sliver approved these changes Oct 29, 2023

View reviewed changes

Berserker66 merged commit d743d10 into main Oct 30, 2023
21 checks passed

Berserker66 deleted the core_log_perf branch October 30, 2023 03:06

FlySniper pushed a commit to FlySniper/Archipelago that referenced this pull request Nov 14, 2023

Core: log completion time if > 1.0 seconds per step (ArchipelagoMW#2345)

c5f4174

Jouramie pushed a commit to Jouramie/Archipelago that referenced this pull request Feb 28, 2024

Core: log completion time if > 1.0 seconds per step (ArchipelagoMW#2345)

55184c3

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Core: log completion time if > 1.0 seconds per step #2345

Core: log completion time if > 1.0 seconds per step #2345

Berserker66 commented Oct 22, 2023

alwaysintreble Oct 22, 2023 •

edited

Loading

el-u Oct 22, 2023

Berserker66 Oct 22, 2023

el-u Oct 25, 2023

Berserker66 Oct 25, 2023

el-u Oct 25, 2023

alwaysintreble Oct 25, 2023

el-u Oct 29, 2023

el-u commented Oct 22, 2023

Berserker66 commented Oct 22, 2023

el-u Oct 22, 2023

el-u left a comment

black-sliver left a comment

	perf_logger.info(f"Took {taken} seconds in {method} for player {player}, "
	perf_logger.info(f"Took {taken} seconds in {multiworld.worlds[player].__class__.__name__}'s {method.__name__} for player {player}.")

		@@ -103,10 +106,23 @@ def __new__(mcs, name: str, bases: Tuple[type, ...], dct: Dict[str, Any]) -> Aut
		return new_class


		def _timed_call(method: Callable, *args: Any, multiworld: "MultiWorld" = None, player: int = None) -> Any:

	def _timed_call(method: Callable, *args: Any, multiworld: "MultiWorld" = None, player: int = None) -> Any:
	def _timed_call(method: Callable[..., Any], *args: Any,
	multiworld: Optional["MultiWorld"] = None, player: Optional[int] = None) -> Any:

Core: log completion time if > 1.0 seconds per step #2345

Core: log completion time if > 1.0 seconds per step #2345

Conversation

Berserker66 commented Oct 22, 2023

What is this fixing or adding?

How was this tested?

If this makes graphical changes, please attach screenshots.

alwaysintreble Oct 22, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

el-u commented Oct 22, 2023

Berserker66 commented Oct 22, 2023

Choose a reason for hiding this comment

el-u left a comment

Choose a reason for hiding this comment

black-sliver left a comment

Choose a reason for hiding this comment

alwaysintreble Oct 22, 2023 •

edited

Loading