diff --git a/.zuul.yaml b/.zuul.yaml index fd836fdfdef..bf4ddcf8301 100644 --- a/.zuul.yaml +++ b/.zuul.yaml @@ -161,6 +161,11 @@ neutron: https://opendev.org/openstack/neutron devstack_services: neutron-trunk: true + devstack_local_conf: + post-config: + $NEUTRON_CONF: + DEFAULT: + enable_code_profiling: True required-projects: - openstack/rally - openstack/rally-openstack diff --git a/doc/source/contributor/internals/code_profiling.rst b/doc/source/contributor/internals/code_profiling.rst new file mode 100644 index 00000000000..da6126c44dd --- /dev/null +++ b/doc/source/contributor/internals/code_profiling.rst @@ -0,0 +1,197 @@ +.. + Licensed under the Apache License, Version 2.0 (the "License"); you may + not use this file except in compliance with the License. You may obtain + a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, WITHOUT + WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the + License for the specific language governing permissions and limitations + under the License. + + + Convention for heading levels in Neutron devref: + ======= Heading 0 (reserved for the title in a document) + ------- Heading 1 + ~~~~~~~ Heading 2 + +++++++ Heading 3 + ''''''' Heading 4 + (Avoid deeper levels because they do not render well.) + + +Profiling Neutron Code +====================== + +As more functionality is added to Neutron over time, efforts to improve +performance become more difficult, given the rising complexity of the code. +Identifying performance bottlenecks is frequently not straightforward, because +they arise as a result of complex interactions of different code components. + +To help community developers to improve Neutron performance, a Python decorator +has been implemented. Decorating a method or a function with it will result in +profiling data being added to the corresponding Neutron component log file. +These data are generated using `cProfile`_ which is part of the Python standard +library. + +.. _`cProfile`: https://docs.python.org/3/library/profile.html + +Once a method or function has been decorated, every one of its executions will +add to the corresponding log file data grouped in 3 sections: + +#. The top calls (sorted by CPU cumulative time) made by the decorated method + or function. The number of calls included in this section can be controlled + by a configuration option, as explained in + :ref:`config-neutron-for-code-profiling`. Following is a summary example of + this section: + + .. code-block:: console + + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: DEBUG neutron.profiling.profiled_decorator [None req-dc2d428f-4531-4f07-a12d-56843b5f9374 c_rally_8af8f2b4_YbhFJ6Ge c_rally_8af8f2b4_fqvy1XJp] os-profiler parent trace-id c5b30c7f-100b-4e1c-8f07-b2c38f41ad65 trace-id 6324fa85-ea5f-4ae2-9d89-2aabff0dddfc 16928 millisecs elapsed for neutron.plugins.ml2.plugin.create_port((, , {'port': {'tenant_id': '421ab52e126e45af81a3eb1962613e18', 'network_id': 'dc59577a-9589-4617-82b5-6ee31dbdb15d', 'fixed_ips': [{'ip_address': '1.1.5.177', 'subnet_id': 'e15ec947-9edd-4793-bf0f-c463c7ff2f62'}], 'admin_state_up': True, 'device_id': 'f33db890-7958-440e-b07b-432e40bb4049', 'device_owner': 'network:router_interface', 'name': '', 'project_id': '421ab52e126e45af81a3eb1962613e18', 'mac_address': , 'allowed_address_pairs': , 'extra_dhcp_opts': None, 'binding:vnic_type': 'normal', 'binding:host_id': , 'binding:profile': , 'port_security_enabled': , 'description': '', 'security_groups': }}), {}): + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 247612 function calls (238220 primitive calls) in 16.943 seconds + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: Ordered by: cumulative time + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: List reduced from 1861 to 100 due to restriction <100> + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: ncalls tottime percall cumtime percall filename:lineno(function) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 4/2 0.000 0.000 16.932 8.466 /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:132(wrapped) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 16.928 16.928 /opt/stack/neutron/neutron/common/utils.py:678(inner) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 20/9 0.000 0.000 16.884 1.876 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1317() + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 37/17 0.000 0.000 16.867 0.992 /opt/stack/osprofiler/osprofiler/sqlalchemy.py:84(handler) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 37/17 0.000 0.000 16.860 0.992 /opt/stack/osprofiler/osprofiler/profiler.py:86(stop) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 8/3 0.005 0.001 16.844 5.615 /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:224(wrapped) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 16.836 16.836 /opt/stack/neutron/neutron/plugins/ml2/plugin.py:1395(_create_port_db) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 16.836 16.836 /opt/stack/neutron/neutron/db/db_base_plugin_v2.py:1413(create_port_db) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 16.836 16.836 /opt/stack/neutron/neutron/db/db_base_plugin_v2.py:1586(_enforce_device_owner_not_router_intf_or_device_id) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 16.836 16.836 /opt/stack/neutron/neutron/db/l3_db.py:522(get_router) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 16.836 16.836 /opt/stack/neutron/neutron/db/l3_db.py:186(_get_router) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 34/22 0.000 0.000 16.745 0.761 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:35(instances) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 39/8 0.000 0.000 16.727 2.091 /usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py:285(_execute_on_connection) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 39/8 0.001 0.000 16.727 2.091 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:1056(_execute_clauseelement) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 17/13 0.000 0.000 16.704 1.285 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1310(get) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 20/14 0.001 0.000 16.704 1.193 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1315(_load) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 19/14 0.000 0.000 16.703 1.193 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:88() + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 76/23 0.001 0.000 16.699 0.726 /opt/stack/osprofiler/osprofiler/profiler.py:426(_notify) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 39/8 0.001 0.000 16.696 2.087 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:1163(_execute_context) + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 75/23 0.000 0.000 16.686 0.725 /opt/stack/osprofiler/osprofiler/notifier.py:28(notify) + +#. Callers section: all functions or methods that called each function or + method in the resulting profiling data. This is restricted by the configured + number of top calls to log, as explained in + :ref:`config-neutron-for-code-profiling`. Following is a summary example of + this section: + + :: + + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: Ordered by: cumulative time + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: List reduced from 1861 to 100 due to restriction <100> + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: Function was called by... + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: ncalls tottime cumtime + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:132(wrapped) <- 2/0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:224(wrapped) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /opt/stack/neutron/neutron/common/utils.py:678(inner) <- + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1317() <- 3 0.000 0.000 /opt/stack/osprofiler/osprofiler/profiler.py:426(_notify) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 16.883 /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:132(wrapped) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 2 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:69(__init__) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py:1056(_execute_clauseelement) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 16.704 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:3281(one) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:3337(__iter__) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py:3362(_execute_and_instances) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/session.py:1127(_connection_for_bind) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1310(get) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1315(_load) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:2033(load_scalar_from_joined_new_row) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1/0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py:840(_checkin) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1/0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/webob/request.py:1294(send) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /opt/stack/osprofiler/osprofiler/sqlalchemy.py:84(handler) <- 16/0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/event/attr.py:316(__call__) + Oct 20 01:52:40.767003 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /opt/stack/osprofiler/osprofiler/profiler.py:86(stop) <- 16/0 0.000 0.000 /opt/stack/osprofiler/osprofiler/sqlalchemy.py:84(handler) + +#. Callees section: a list of all functions or methods that were called by the + indicated function or method. Again, this is restricted by the configured + number of top calls to log. Following is a summary example of this section: + + :: + + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: Ordered by: cumulative time + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: List reduced from 1861 to 100 due to restriction <100> + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: Function called... + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: ncalls tottime cumtime + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:132(wrapped) -> 1/0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/oslo_db/api.py:135(wrapper) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 16.883 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1317() + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /opt/stack/neutron/neutron/common/utils.py:678(inner) -> 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/neutron_lib/context.py:145(session) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 16.928 /usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py:224(wrapped) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/session.py:2986(is_active) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1317() -> 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py:579(do_execute) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 2 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py:1078(post_exec) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 2 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py:1122(get_result_proxy) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 0 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/event/attr.py:316(__call__) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/event/base.py:266(__getattr__) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 15/3 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/loading.py:35(instances) + Oct 20 01:52:40.788842 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1317() + Oct 20 01:52:40.791161 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 1 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/strategies.py:1318() + Oct 20 01:52:40.791161 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: 3 0.000 0.000 /usr/local/lib/python3.6/dist-packages/sqlalchemy/util/langhelpers.py:852(__get__) + + +.. _config-neutron-for-code-profiling: + +Setting up Neutron for code profiling +-------------------------------------- + +To start profiling Neutron code, the following steps have to be taken: + +#. Add he following line to the ``[default]`` section of + ``/etc/neutron/neutron.conf`` (code profiling is disabled by default): + + .. code-block:: console + + enable_code_profiling = True + +#. Add the following import line to each module to be profiled: + + .. code-block:: python + + from neutron.profiling import profiled_decorator + +#. Decorate each mehtod or function to be profiled as follows: + + .. code-block:: python + + @profiled_decorator.profile + def create_subnet(self, context, subnet): + +#. For each decorated method or function execution, only the top 50 calls by + cumulative CPU time are logged. This can be changed adding the following + line to the ``[default]`` section of ``/etc/neutron/neutron.conf``: + + .. code-block:: console + + code_profiling_calls_to_log = 100 + + +Profiling code with the Neutron Rally job +----------------------------------------- + +Code profiling is enabled for the ``neutron-rally-task`` job in Neutron's check +queue in Zuul. Taking advantage of the fact that ``os-profiler`` is enabled for +this job, the data logged by the ``profiled_decorator.profile`` decorator +includes the ``os-profiler`` ``parent trace-id`` and ``trace-id`` as can be +seen here: + +.. code-block:: console + + Oct 20 01:52:40.759379 ubuntu-bionic-vexxhost-sjc1-0012393267 neutron-server[19578]: DEBUG neutron.profiling.profiled_decorator [None req-dc2d428f-4531-4f07-a12d-56843b5f9374 c_rally_8af8f2b4_YbhFJ6Ge c_rally_8af8f2b4_fqvy1XJp] os-profiler parent trace-id c5b30c7f-100b-4e1c-8f07-b2c38f41ad65 trace-id 6324fa85-ea5f-4ae2-9d89-2aabff0dddfc 16928 millisecs elapsed for neutron.plugins.ml2.plugin.create_port((, , {'port': {'tenant_id': '421ab52e126e45af81a3eb1962613e18', 'network_id': 'dc59577a-9589-4617-82b5-6ee31dbdb15d', 'fixed_ips': [{'ip_address': '1.1.5.177', 'subnet_id': 'e15ec947-9edd-4793-bf0f-c463c7ff2f62'}], 'admin_state_up': True, 'device_id': 'f33db890-7958-440e-b07b-432e40bb4049', 'device_owner': 'network:router_interface', 'name': '', 'project_id': '421ab52e126e45af81a3eb1962613e18', 'mac_address': , 'allowed_address_pairs': , 'extra_dhcp_opts': None, 'binding:vnic_type': 'normal', 'binding:host_id': , 'binding:profile': , 'port_security_enabled': , 'description': '', 'security_groups': }}), {}): + +Community developers wanting to use this to correlate data from ``os-profiler`` +and the ``profiled_decorator.profile`` decorator can submit a ``DNM`` (Do Not +Merge) patch, decorating the functions and methods they want to profile and +optionally: + +#. Configure the number of calls to be logged in the ``neutron-rally-task`` + job definition, as described in :ref:`config-neutron-for-code-profiling`. + +#. Increase the ``timeout`` parameter value of the ``neutron-rally-task`` job + in the `.zuul yaml file`_. The value used for the Neutron gate might be too + short when logging large quantities of profiling data. + +.. _`.zuul yaml file`: https://github.com/openstack/neutron/blob/master/.zuul.yaml + +The ``profiled_decorator.profile`` and ``os-profiler`` data will be found in +the ``neutron-rally-task`` log files and ``HTML report`` respectively. diff --git a/doc/source/contributor/internals/index.rst b/doc/source/contributor/internals/index.rst index cec0b50d70b..81ae9da72b8 100644 --- a/doc/source/contributor/internals/index.rst +++ b/doc/source/contributor/internals/index.rst @@ -35,6 +35,7 @@ Neutron Internals api_extensions api_layer calling_ml2_plugin + code_profiling db_layer db_models dns_order diff --git a/neutron/common/utils.py b/neutron/common/utils.py index fe253679476..cf399bda3db 100644 --- a/neutron/common/utils.py +++ b/neutron/common/utils.py @@ -923,7 +923,7 @@ class Timer(object): return (datetime.datetime.now() - self.start).total_seconds() -def _collect_profiler_info(): +def collect_profiler_info(): p = profiler.get() if p: return { @@ -942,7 +942,7 @@ def spawn(func, *args, **kwargs): but we re-initialize osprofiler in threads spawn()-ed. """ - profiler_info = _collect_profiler_info() + profiler_info = collect_profiler_info() @functools.wraps(func) def wrapper(*args, **kwargs): @@ -956,7 +956,7 @@ def spawn(func, *args, **kwargs): def spawn_n(func, *args, **kwargs): """See spawn() above""" - profiler_info = _collect_profiler_info() + profiler_info = collect_profiler_info() @functools.wraps(func) def wrapper(*args, **kwargs): diff --git a/neutron/conf/profiling.py b/neutron/conf/profiling.py new file mode 100644 index 00000000000..5e5e76fa63a --- /dev/null +++ b/neutron/conf/profiling.py @@ -0,0 +1,31 @@ +# Licensed under the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. You may obtain +# a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the +# License for the specific language governing permissions and limitations +# under the License. + + +from oslo_config import cfg + +from neutron._i18n import _ + + +PROFILER_OPTS = [ + cfg.BoolOpt('enable_code_profiling', + default=False, + help=_('Enable code execution profiling with cProfile. ' + 'Profiling data are logged at DEBUG level.')), + cfg.IntOpt('code_profiling_calls_to_log', + default=50, + help=_('Number of calls from the cProfile report to log')), +] + + +def register_profiling_opts(conf=cfg.CONF): + conf.register_opts(PROFILER_OPTS) diff --git a/neutron/profiling/__init__.py b/neutron/profiling/__init__.py new file mode 100644 index 00000000000..e69de29bb2d diff --git a/neutron/profiling/profiled_decorator.py b/neutron/profiling/profiled_decorator.py new file mode 100644 index 00000000000..8383568d519 --- /dev/null +++ b/neutron/profiling/profiled_decorator.py @@ -0,0 +1,82 @@ +# Licensed under the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. You may obtain +# a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the +# License for the specific language governing permissions and limitations +# under the License. + + +import cProfile +from datetime import datetime +import io +import pstats + +from oslo_config import cfg +from oslo_log import log +import six + +from neutron.common import utils +from neutron.conf import profiling as profiling_conf_opts + +LOG = log.getLogger(__name__) + + +CONF = cfg.CONF +profiling_conf_opts.register_profiling_opts() + + +SORT_BY = 'cumtime' + + +def profile(f): + """Decorator to profile Neutron code. + + This will profile the decorated method or function with cProfile and log + the result. + """ + + @six.wraps(f) + def profile_wrapper(*args, **kwargs): + + try: + if cfg.CONF.enable_code_profiling: + profid = "%s.%s" % (f.__module__, f.__name__) + profiler = cProfile.Profile() + profiler.enable() + start_time = datetime.now() + return f(*args, **kwargs) + finally: + if cfg.CONF.enable_code_profiling: + profiler.disable() + elapsed_time = datetime.now() - start_time + elapsed_time_ms = (elapsed_time.seconds * 1000.0 + + elapsed_time.microseconds / 1000.0) + stream = io.StringIO() + stats = pstats.Stats(profiler, stream=stream).sort_stats( + SORT_BY) + stats.print_stats(cfg.CONF.code_profiling_calls_to_log) + stats.print_callers(cfg.CONF.code_profiling_calls_to_log) + stats.print_callees(cfg.CONF.code_profiling_calls_to_log) + profiler_info = utils.collect_profiler_info() + if not profiler_info: + profiler_info = {'base_id': 'not available', + 'parent_id': 'not available'} + LOG.debug('os-profiler parent trace-id %(parent_id)s ' + 'trace-id %(trace_id)s %(elapsed_time)7d millisecs ' + 'elapsed for %(method)s(*%(args)s, **%(kwargs)s):' + '\n%(profiler_data)s', + {'parent_id': profiler_info['parent_id'], + 'trace_id': profiler_info['base_id'], + 'elapsed_time': elapsed_time_ms, + 'method': profid, + 'args': args, + 'kwargs': kwargs, + 'profiler_data': stream.getvalue()}) + stream.close() + + return profile_wrapper