diff --git a/src/ax_interface/agent.py b/src/ax_interface/agent.py index 82766666a..b20fbc8eb 100644 --- a/src/ax_interface/agent.py +++ b/src/ax_interface/agent.py @@ -8,7 +8,7 @@ class Agent: - def __init__(self, mib_cls, update_frequency, loop): + def __init__(self, mib_cls, enable_dynamic_frequency, update_frequency, loop): if not type(mib_cls) is MIBMeta: raise ValueError("Expected a class with type: {}".format(MIBMeta)) @@ -20,7 +20,7 @@ def __init__(self, mib_cls, update_frequency, loop): self.stopped = asyncio.Event() # Initialize our MIB - self.mib_table = MIBTable(mib_cls, update_frequency) + self.mib_table = MIBTable(mib_cls, enable_dynamic_frequency, update_frequency) # containers self.socket_mgr = SocketManager(self.mib_table, self.run_enabled, self.loop) diff --git a/src/ax_interface/mib.py b/src/ax_interface/mib.py index e50046eae..9aa9b7d62 100644 --- a/src/ax_interface/mib.py +++ b/src/ax_interface/mib.py @@ -18,6 +18,11 @@ """ DEFAULT_REINIT_RATE = 60 +""" +Disable dynamic frequency by default +""" +DEFAULT_ENABLE_DYNAMIC_FREQUENCY = False + class MIBUpdater: """ @@ -27,6 +32,7 @@ class MIBUpdater: def __init__(self): self.run_event = asyncio.Event() self.frequency = DEFAULT_UPDATE_FREQUENCY + self.enable_dynamic_frequency = DEFAULT_ENABLE_DYNAMIC_FREQUENCY self.reinit_rate = DEFAULT_REINIT_RATE // DEFAULT_UPDATE_FREQUENCY self.update_counter = self.reinit_rate + 1 # reinit_data when init @@ -60,30 +66,32 @@ async def start(self): # Any unexpected exception or error, log it and keep running logger.exception("MIBUpdater.start() caught an unexpected exception during update_data()") - """ - On SONiC device with huge interfaces - for example RP card on ethernet chassis, including backend ports, 600+ interfaces - The update_data function could be very slow, especially when 100% CPU utilization. - for example ciscoSwitchQosMIB.QueueStatUpdater, uses 1-3 seconds on normal state. - uses 3-8 seconds on 100% CPU utilization state. - We use Asyncio/Coroutine as the basic framework, - the mib updaters share the same asyncio event loop with the SNMP agent client. - Hence during the updaters executing, the agent client can't receive/respond to new requests, - - The high frequency and the long execution time - causes the SNMP request to be timed out on High CPU utilization. - The stable frequency(generally with default value 5s) - doesn't works well on this huge interfaces situation. - when the execution time is long, - wait for longer time to give back the control of asyncio event loop to SNMP agent - """ - - execution_time = (datetime.now() - start).total_seconds() - next_frequency = get_next_update_interval(execution_time, self.frequency) - - if next_frequency > self.frequency: - logger.debug(f"MIBUpdater type[{type(self)}] slow update detected, " - f"update execution time[{execution_time}], next_frequency[{next_frequency}]") + if self.enable_dynamic_frequency: + """ + On SONiC device with huge interfaces + for example RP card on ethernet chassis, including backend ports, 600+ interfaces + The update_data function could be very slow, especially when 100% CPU utilization. + for example ciscoSwitchQosMIB.QueueStatUpdater, uses 1-3 seconds on normal state. + uses 3-8 seconds on 100% CPU utilization state. + We use Asyncio/Coroutine as the basic framework, + the mib updaters share the same asyncio event loop with the SNMP agent client. + Hence during the updaters executing, the agent client can't receive/respond to new requests, + + The high frequency and the long execution time + causes the SNMP request to be timed out on High CPU utilization. + The stable frequency(generally with default value 5s) + doesn't works well on this huge interfaces situation. + when the execution time is long, + wait for longer time to give back the control of asyncio event loop to SNMP agent + """ + execution_time = (datetime.now() - start).total_seconds() + next_frequency = get_next_update_interval(execution_time, self.frequency) + + if next_frequency > self.frequency: + logger.debug(f"MIBUpdater type[{type(self)}] slow update detected, " + f"update execution time[{execution_time}], next_frequency[{next_frequency}]") + else: + next_frequency = self.frequency # wait based on our update frequency before executing again. # randomize to avoid concurrent update storms. @@ -303,10 +311,11 @@ class MIBTable(dict): Simplistic LUT for Get/GetNext OID. Interprets iterables as keys and implements the same interfaces as dict's. """ - def __init__(self, mib_cls, update_frequency=DEFAULT_UPDATE_FREQUENCY): + def __init__(self, mib_cls, enable_dynamic_frequency, update_frequency=DEFAULT_UPDATE_FREQUENCY): if type(mib_cls) is not MIBMeta: raise ValueError("Supplied object is not a MIB class instance.") super().__init__(getattr(mib_cls, MIBMeta.KEYSTORE)) + self.enable_dynamic_frequency = enable_dynamic_frequency self.update_frequency = update_frequency self.updater_instances = getattr(mib_cls, MIBMeta.UPDATERS) self.prefixes = getattr(mib_cls, MIBMeta.PREFIXES) @@ -324,6 +333,7 @@ def start_background_tasks(self, event): tasks = [] for updater in self.updater_instances: updater.frequency = self.update_frequency + updater.enable_dynamic_frequency = self.enable_dynamic_frequency updater.run_event = event fut = asyncio.ensure_future(updater.start()) fut.add_done_callback(MIBTable._done_background_task_callback) diff --git a/src/sonic_ax_impl/__main__.py b/src/sonic_ax_impl/__main__.py index d9f117db0..a4b24bab4 100644 --- a/src/sonic_ax_impl/__main__.py +++ b/src/sonic_ax_impl/__main__.py @@ -5,11 +5,12 @@ import shutil import sys -import sonic_py_common.util from swsscommon import swsscommon import ax_interface import sonic_ax_impl + +from .utils.arg_parser import process_options from . import mibs LOG_FORMAT = "snmp-subagent [%(name)s] %(levelname)s: %(message)s" @@ -70,7 +71,7 @@ def logging_level_to_swss_level(log_level): sys.exit(0) # import command line arguments - args = sonic_py_common.util.process_options("sonic_ax_impl") + args = process_options("sonic_ax_impl") # configure logging. If debug '-d' is specified, logs to stdout at designated level. syslog/INFO otherwise. log_level = log_level_sdk = args.get('log_level') @@ -110,4 +111,4 @@ def logging_level_to_swss_level(log_level): from .main import main - main(update_frequency=args.get('update_frequency')) + main(enable_dynamic_frequency=args.get('enable_dynamic_frequency'), update_frequency=args.get('update_frequency')) diff --git a/src/sonic_ax_impl/main.py b/src/sonic_ax_impl/main.py index 281ab601b..c798ab690 100644 --- a/src/sonic_ax_impl/main.py +++ b/src/sonic_ax_impl/main.py @@ -54,14 +54,14 @@ def shutdown(signame, agent): shutdown_task = event_loop.create_task(agent.shutdown()) -def main(update_frequency=None): +def main(enable_dynamic_frequency=False, update_frequency=None): global event_loop try: Namespace.init_sonic_db_config() # initialize handler and set update frequency (or use the default) - agent = ax_interface.Agent(SonicMIB, update_frequency or DEFAULT_UPDATE_FREQUENCY, event_loop) + agent = ax_interface.Agent(SonicMIB, enable_dynamic_frequency, update_frequency or DEFAULT_UPDATE_FREQUENCY, event_loop) # add "shutdown" signal handlers # https://docs.python.org/3.5/library/asyncio-eventloop.html#set-signal-handlers-for-sigint-and-sigterm diff --git a/src/sonic_ax_impl/utils/__init__.py b/src/sonic_ax_impl/utils/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/src/sonic_ax_impl/utils/arg_parser.py b/src/sonic_ax_impl/utils/arg_parser.py new file mode 100644 index 000000000..60f856a36 --- /dev/null +++ b/src/sonic_ax_impl/utils/arg_parser.py @@ -0,0 +1,70 @@ +""" +Syslog and daemon script utility library. +""" + +from __future__ import print_function +import json +import logging +import logging.config +import sys +from getopt import getopt + + +# TODO: move to dbsync project. +def usage(script_name): + print('Usage: python ', script_name, + '-t [host] -p [port] -s [unix_socket_path] -d [logging_level] -f [update_frequency] -h [help]') + + +# TODO: move to dbsync project. +def process_options(script_name): + """ + Process command line options + """ + options, remainders = getopt(sys.argv[1:], "t:p:s:d:f:rh", ["host=", "port=", "unix_socket_path=", "debug=", "frequency=", "enable_dynamic_frequency", "help"]) + + args = {} + for (opt, arg) in options: + try: + if opt in ('-d', '--debug'): + args['log_level'] = int(arg) + elif opt in ('-t', '--host'): + args['host'] = arg + elif opt in ('-p', '--port'): + args['port'] = int(arg) + elif opt in ('-s', 'unix_socket_path'): + args['unix_socket_path'] = arg + elif opt in ('-f', '--frequency'): + args['update_frequency'] = int(arg) + elif opt in ('-r', '--enable_dynamic_frequency'): + args['enable_dynamic_frequency'] = True + elif opt in ('-h', '--help'): + usage(script_name) + sys.exit(0) + except ValueError as e: + print('Invalid option for {}: {}'.format(opt, e)) + sys.exit(1) + + return args + + +# TODO: move +def setup_logging(config_file_path, log_level=logging.INFO): + """ + Logging configuration helper. + + :param config_file_path: file path to logging configuration file. + https://docs.python.org/3/library/logging.config.html#object-connections + :param log_level: defaults to logging.INFO + :return: None - access the logger by name as described in the config--or the "root" logger as a backup. + """ + try: + with open(config_file_path, 'rt') as f: + config = json.load(f) + logging.config.dictConfig(config) + except (ValueError, IOError, OSError): + # json.JSONDecodeError is throwable in Python3.5+ -- subclass of ValueError + logging.basicConfig(log_level=log_level) + logging.root.exception( + "Could not load specified logging configuration '{}'. Verify the filepath exists and is compliant with: " + "[https://docs.python.org/3/library/logging.config.html#object-connections]".format(config_file_path))