From 28e53b0f9d39e8edca4073cd84a4fb2082893042 Mon Sep 17 00:00:00 2001 From: poorva1209 Date: Wed, 9 Jul 2025 13:02:38 -0700 Subject: [PATCH 1/2] Update agents.py --- .../field_interface/agents/agents.py | 156 +++++++++++++++++- 1 file changed, 155 insertions(+), 1 deletion(-) diff --git a/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/agents.py b/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/agents.py index caba2ad..ac02eb5 100644 --- a/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/agents.py +++ b/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/agents.py @@ -6,6 +6,13 @@ from datetime import datetime from typing import Dict +import time +import os +from functools import wraps +import sys +import inspect +import atexit + from cimgraph.databases import ConnectionParameters from cimgraph.databases.gridappsd import GridappsdConnection from cimgraph.models import FeederModel @@ -17,12 +24,18 @@ from gridappsd_field_bus.field_interface.gridappsd_field_bus import GridAPPSDMessageBus from gridappsd_field_bus.field_interface.interfaces import (FieldMessageBus, MessageBusDefinition, MessageBusFactory) + CIM_PROFILE = None IEC61970_301 = None cim = None _log = logging.getLogger(__name__) - +decorator_logger = logging.getLogger("decorator_logger") +decorator_logger.setLevel(logging.INFO) +file_handler = logging.FileHandler("compute_req_log.txt") # Log file name +formatter = logging.Formatter('[COMPUTE_REQ] %(asctime)s - %(message)s') +file_handler.setFormatter(formatter) +decorator_logger.addHandler(file_handler) def set_cim_profile(cim_profile: str, iec61970_301: int): global CIM_PROFILE @@ -41,6 +54,147 @@ class AgentRegistrationDetails: upstream_message_bus_id: FieldMessageBus.id downstream_message_bus_id: FieldMessageBus.id +@atexit.register +def call_counter_report(): + decorator_logger.info("Function call counts summary:") + for func_name, count in function_call_counts.items(): + decorator_logger.info(f"{func_name} was called {count} time(s)") + +@atexit.register +def message_size_report(): + decorator_logger.info("Total message size summary:") + for func_name, total_size in message_size_totals.items(): + decorator_logger.info(f"{func_name} total message size: {total_size} bytes") + +def compute_req(cls): + functions = [ + '__init__', + #'on_measurement', + 'on_upstream_message', + 'on_downstream_message', + 'on_request', + 'publish_upstream', + 'publish_downstream', + 'send_control_command' + ] + + def call_counter(func): + name = func.__qualname__ + + @wraps(func) + def wrapper(*args, **kwargs): + if args[0].agent_id+'.'+name not in function_call_counts: + function_call_counts[args[0].agent_id+'.'+name] = 0 + function_call_counts[args[0].agent_id+'.'+name] += 1 + #decorator_logger.info(f"{name} called {function_call_counts[name]} times") + return func(*args, **kwargs) + return wrapper + + def timed(func): + @wraps(func) + def wrapper(*args, **kwargs): + start = time.perf_counter() + result = func(*args, **kwargs) + end = time.perf_counter() + class_name = args[0].__class__.__name__ if args else "" + if func.__name__ == '__init__': + decorator_logger.info(f"{class_name}.{func.__name__}.{args[0].agent_id} took: {end - start:.6f} seconds") + return result + return wrapper + + def get_deep_size(func): + @wraps(func) + def wrapper(*args, **kwargs): + result = func(*args, **kwargs) + + def deep_size(obj, seen=None): + if seen is None: + seen = set() + obj_id = id(obj) + if obj_id in seen: + return 0 + seen.add(obj_id) + size = sys.getsizeof(obj) + if isinstance(obj, dict): + size += sum(deep_size(k, seen) + deep_size(v, seen) for k, v in obj.items()) + elif isinstance(obj, (list, tuple, set, frozenset)): + size += sum(deep_size(i, seen) for i in obj) + elif hasattr(obj, '__dict__'): + for attr_name, attr_value in vars(obj).items(): + if attr_name in ['feeder_area', 'switch_area', 'secondary_area']: + continue + size += deep_size(attr_value, seen) + elif hasattr(obj, '__slots__'): + size += sum(deep_size(getattr(obj, slot), seen) for slot in obj.__slots__ if hasattr(obj, slot)) + return size + + self = args[0] + obj_size = deep_size(self) + decorator_logger.info(f"{self.__class__.__name__}.{func.__name__}.{args[0].agent_id} size is: {obj_size} bytes") + + return result + return wrapper + + def get_graph_size(func): + @wraps(func) + def wrapper(*args, **kwargs): + self = args[0] + result = func(*args, **kwargs) + area_names = ['feeder_area', 'switch_area', 'secondary_area'] + area_found = False + for name in area_names: + area_dict = getattr(self, name, None) + if area_dict is not None and hasattr(area_dict, 'graph'): + graph_keys = [key.__name__ for key in list(area_dict.graph.keys())] + size = len(area_dict.graph.keys()) + decorator_logger.info(f"{self.__class__.__name__}.{func.__name__}.{args[0].agent_id} length of graph: {size}") + decorator_logger.info(f"{self.__class__.__name__}.{name}.{args[0].agent_id} graph keys: {graph_keys}") + area_found = True + break + + if not area_found: + decorator_logger.error(f"{class_name}.{func.__name__}.{args[0].agent_id} No area dictionary (feeder/switch/secondary) found in {self.__class__.__name__}") + return result + return wrapper + + def log_message_size(func): + name = func.__qualname__ + + @wraps(func) + def wrapper(*args, **kwargs): + sig = inspect.signature(func) + bound_args = sig.bind(*args, **kwargs) + bound_args.apply_defaults() + + if 'message' in bound_args.arguments: + msg = bound_args.arguments['message'] + size = sys.getsizeof(msg) + if args[0].agent_id+'.'+name not in message_size_totals: + message_size_totals[args[0].agent_id+'.'+name] = 0 + message_size_totals[args[0].agent_id+'.'+name] += size + + if 'differenceBuilder' in bound_args.arguments: + msg = bound_args.arguments['differenceBuilder'] + size = sys.getsizeof(msg) + if args[0].agent_id+'.'+name not in message_size_totals: + message_size_totals[args[0].agent_id+'.'+name] = 0 + message_size_totals[args[0].agent_id+'.'+name] += size + + return func(*args, **kwargs) + return wrapper + + # Decorate the relevant functions + for attr_name in functions: + if hasattr(cls, attr_name): + original_func = getattr(cls, attr_name) + if callable(original_func): + if attr_name == '__init__': + decorated = get_deep_size(get_graph_size(timed(original_func))) + else: + decorated = call_counter(log_message_size(timed(original_func))) + setattr(cls, attr_name, decorated) + + return cls class DistributedAgent: From 8da8a520eb2ba3ad466c6a4a33d39cb3369df554 Mon Sep 17 00:00:00 2001 From: poorva1209 Date: Wed, 9 Jul 2025 13:05:38 -0700 Subject: [PATCH 2/2] Update __init__.py --- .../gridappsd_field_bus/field_interface/agents/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/__init__.py b/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/__init__.py index f1e2141..af50827 100644 --- a/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/__init__.py +++ b/gridappsd-field-bus-lib/gridappsd_field_bus/field_interface/agents/__init__.py @@ -2,6 +2,6 @@ from gridappsd_field_bus.field_interface.agents.agents import (FeederAgent, DistributedAgent, CoordinatingAgent, SwitchAreaAgent, - SecondaryAreaAgent, SubstationAgent) + SecondaryAreaAgent, SubstationAgent, compute_req) __all__: List[str] = ["FeederAgent", "DistributedAgent", "CoordinatingAgent"]