osprofiler

No neutron project api calls in osprofiler trace

Asked by venkata anil

Hi

I am trying to run osprofiler for neutron project, but couldn't see neutron trace.
I followed these steps -

1) I have a devstack setup. Enabled osprofiler like expalined in this link

https://github.com/openstack/osprofiler/tree/master/devstack

2) used this neutron cli patch https://review.openstack.org/#/c/281508/

3) executed neutron commands with --profile option, for example
 neutron --profile SECRET_KEY port-create --name p8 99eefdc0-e5f8-4069-b830-3c8f249676e5

4) osprofiler trace show --html 384caac9-7ae3-4081-8f4a-753ae833c1ed --out myht.html

But that html file is not showing any neutron api. It is showing only keystone project api.

Did anyone tried neutron trace with osprofiler? Please help.

Question information

Language:
English Edit question
Status:
Solved
For:
osprofiler Edit question
Assignee:
No assignee Edit question
Solved by:
Dina Belova
Solved:
Last query:
Last reply:
Revision history for this message
venkata anil (anil-venkata) said : 		#1

content of trace html file

<!doctype html>
<html ng-app="Application">

  <head>
    <script>
        var OSProfilerData = {
  "info": {
    "started": 0,
    "finished": 140,
    "name": "total"
  },
  "stats": {
    "wsgi": {
      "count": 2,
      "duration": 101
    }
  },
  "children": [
    {
      "info": {
        "name": "wsgi",
        "service": "main",
        "started": 0,
        "meta.raw_payload.wsgi-stop": {
          "info": {
            "project": null,
            "host": "vagrant",
            "service": null
          },
          "name": "wsgi-stop",
          "service": "main",
          "timestamp": "2016-11-23T14:03:56.836740",
          "trace_id": "b6bdc0e8-c214-4ac8-8d42-f703bfbd63cd",
          "project": "keystone",
          "parent_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed",
          "base_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed"
        },
        "finished": 7,
        "project": "keystone",
        "host": "vagrant",
        "meta.raw_payload.wsgi-start": {
          "info": {
            "project": null,
            "host": "vagrant",
            "request": {
              "path": "/v2.0",
              "scheme": "http",
              "method": "GET",
              "query": ""
            },
            "service": null
          },
          "name": "wsgi-start",
          "service": "main",
          "timestamp": "2016-11-23T14:03:56.829484",
          "trace_id": "b6bdc0e8-c214-4ac8-8d42-f703bfbd63cd",
          "project": "keystone",
          "parent_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed",
          "base_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed"
        }
      },
      "parent_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed",
      "trace_id": "b6bdc0e8-c214-4ac8-8d42-f703bfbd63cd",
      "children": []
    },
    {
      "info": {
        "name": "wsgi",
        "service": "main",
        "started": 46,
        "meta.raw_payload.wsgi-stop": {
          "info": {
            "project": null,
            "host": "vagrant",
            "service": null
          },
          "name": "wsgi-stop",
          "service": "main",
          "timestamp": "2016-11-23T14:03:56.969504",
          "trace_id": "597f06da-2f4f-48cd-96ac-696080368ff6",
          "project": "keystone",
          "parent_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed",
          "base_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed"
        },
        "finished": 140,
        "project": "keystone",
        "host": "vagrant",
        "meta.raw_payload.wsgi-start": {
          "info": {
            "project": null,
            "host": "vagrant",
            "request": {
              "path": "/identity/v2.0/tokens",
              "scheme": "http",
              "method": "POST",
              "query": ""
            },
            "service": null
          },
          "name": "wsgi-start",
          "service": "main",
          "timestamp": "2016-11-23T14:03:56.876237",
          "trace_id": "597f06da-2f4f-48cd-96ac-696080368ff6",
          "project": "keystone",
          "parent_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed",
          "base_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed"
        }
      },
      "parent_id": "384caac9-7ae3-4081-8f4a-753ae833c1ed",
      "trace_id": "597f06da-2f4f-48cd-96ac-696080368ff6",
      "children": []
    }
  ]
}
    </script>

    <link rel="stylesheet" href="https://maxcdn.bootstrapcdn.com/bootstrap/3.2.0/css/bootstrap.min.css">
    <link rel="stylesheet" href="https://maxcdn.bootstrapcdn.com/bootstrap/3.2.0/css/bootstrap-theme.min.css">

    <script src="https://ajax.googleapis.com/ajax/libs/angularjs/1.2.10/angular.min.js"></script>
    <script src="https://angular-ui.github.io/bootstrap/ui-bootstrap-tpls-0.11.0.js"></script>

    <style>
      .trace {
        min-width: 900px;
        width: 100%;
      }
      .trace tr:hover {
        background-color: #D9EDF7!important;
      }
      .trace tr td {
        width: 14%;
        white-space: nowrap;
        padding: 2px;
        border-right: 1px solid #eee;
      }
      .trace tr td.details {
        width: 10%;
        padding-right: 20px;
      }
      .trace.cursor_pointer_on_hover {
        cursor: pointer;
      }
      .trace .level {
        width: 10%;
        font-weight: bold;
      }
      .bold {
        font-weight: bold;
      }
      .duration {
        width: 25px;
        margin: 0px;
        padding: 0px;
        background-color: #c6eff3;
        border-radius: 4px;
        font-size: 10px;
      }
      .duration div{
        padding-top: 4px;
        padding-bottom: 4px;
        text-align: center;
      }
    </style>

    <script type="text/ng-template" id="tree_item_renderer.html">

        <div ng-init="hide_children=false">
          <table class="trace cursor_pointer_on_hover">
            <tr>
              <td class="level" style="padding-left:{{data.level * 5}}px;">
                <button type="button" class="btn btn-default btn-xs" ng-disabled="data.is_leaf" ng-click="hide_children=!hide_children">
                  <span class="glyphicon glyphicon-{{ (data.is_leaf) ? 'cloud' : ((hide_children) ? 'plus': 'minus')}}"></span>
                  {{data.level || 0}}
                </button>
              </td>
              <td ng-click="display(data);" class="text-center">
               <div class="duration" style="width: {{get_width(data)}}%; margin-left: {{get_started(data)}}%">
                  <div>{{data.info.finished - data.info.started}} ms</div>
                </div>
              </td>
              <td ng-click="display(data);" class="{{ is_important(data) ? 'bold' : ''}} text-right" > {{data.info.name}} </td>
              <td ng-click="display(data);"> {{data.info.project || "n/a"}}</td>
              <td ng-click="display(data);"> {{data.info.service || "n/a" }} </td>
              <td ng-click="display(data);"> {{data.info.host || "n/a"}} </td>
              <td class="details">
                <a href="#" ng-click="display(data);"> Details </a>
              </td>
            </tr>
          </table>

        <div ng-hide="hide_children">
          <div ng-repeat="data in data.children" ng-include="'tree_item_renderer.html'"> </div>
        </div>
      </div>

    </script>

    <script>
      angular.module("Application", ['ui.bootstrap']);

      function ProfilerCtlr($scope, $modal) {

        var convert_input = function(input, level){
          level = (level) ? level : 0;
          input.level = level;
          input.is_leaf = !input.children.length

          for (var i=0; i < input.children.length; i++)
            convert_input(input.children[i], level + 1);
          return input;
        }

        $scope.get_width = function(data){

          var full_duration = $scope.tree[0].info.finished;
          var duration = (data.info.finished - data.info.started) * 100.0 / full_duration;
          return (duration >= 0.5) ? duration : 0.5;
        }

        $scope.get_started = function(data) {
          var full_duration = $scope.tree[0].info.finished;
          return data.info.started * 100.0 / full_duration;
        }

        $scope.is_important = function(data) {
          return ["total", "wsgi", "rpc"].indexOf(data.info.name) != -1;
        }

        $scope.display = function(data){
          var info = angular.copy(data.info);

          var metadata = {};
          angular.forEach(info, function(value, key) {
            var parts = key.split(".");
            if (parts[0] == "meta"){

              if (parts.length == 2){
                this[parts[1]] = value;
              }
              else{
                var group_name = parts[1];
                if (!(group_name in this))
                  this[group_name] = {};

                this[group_name][parts[2]] = value;
              }
            };
          }, metadata);

          info["duration"] = info["finished"] - info["started"]
          info["metadata"] = "<pre>" + JSON.stringify(metadata, "", 4) + "</pre>"

          var trace_data = "<div class='row'>"
          columns = ["name", "project", "service", "host", "started",
                     "finished", "duration", "metadata"];
          for (var i = 0; i < columns.length; i++){
            trace_data += "<div class='col-md-2 text-right text-capitalize'><strong>" + columns[i] + " </strong></div>";
            trace_data += "<div class='col-md-10 text-left'>" + info[columns[i]] + "</div>";
          }
          trace_data += "</div>";

          var output = (
            '<div class="modal-header"> Trace Point Details </div>' +
            '<div class="modal-body">' + trace_data + '</div>' +
            '<div class="modal-footer"> <span class="glyphicon glyphicon-cloud </div>'
          );

          var modal_instance = $modal.open({
            "template": output,
            "size": "lg"
          });
        }

        $scope.tree = [convert_input(OSProfilerData)];
      }

    </script>
  </head>

  <body>
    <div ng-controller="ProfilerCtlr">
      <table class="trace">
        <tr class="bold text-left" style="border-bottom: solid 1px gray">
          <td class="level">Levels</td>
          <td>Duration</td>
          <td class="text-right">Type</td>
          <td>Project</td>
          <td>Service</td>
          <td>Host</td>
          <td class="details">Details</td>
        </tr>
      </table>
      <div ng-repeat="data in tree" ng-include="'tree_item_renderer.html'"></div>
    </div>

  </body>

</html>

Revision history for this message
Dina Belova (dbelova) said : 		#2

OK, it looks like something wrong happened during neutron (or whatever) modifications. I've installed clear devstack and can confirm that neutron profiling does not work anymore (although it works for keystone in the same trace, for instance).

I took a look on what's passed to the osprofiler here https://github.com/openstack/neutron/blob/master/neutron/db/api.py#L52 and the cfg.CONF object does not contain the information from the [profiler] section of neutron.conf

Here is the pdb session:

(Pdb) cfg.CONF.profiler.enabled
*** NoSuchOptError: no such option profiler in group [DEFAULT]
(Pdb) cfg.CONF
<oslo_config.cfg.ConfigOpts object at 0x7fb34e24c710>
(Pdb) cfg.CONF.__dict__
{'_groups': {'oslo_concurrency': <oslo_config.cfg.OptGroup object at 0x7fb347ef8450>, 'nova': <oslo_config.cfg.OptGroup object at 0x7fb3478cc590>, 'database': <oslo_config.cfg.OptGroup object at 0x7fb3478cc510>}, '_validate_default_values': False, '_namespace': None, '_oparser': None, '_opts': {'default_log_levels': {'opt': <oslo_config.cfg.ListOpt object at 0x7fb348303710>, 'cli': False}, 'advertise_mtu': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de74d0>, 'cli': False}, 'client_socket_timeout': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347f10210>, 'cli': False}, 'verbose': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb3482f8f10>, 'cli': True}, 'global_physnet_mtu': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347de76d0>, 'cli': False}, 'publish_errors': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb3483037d0>, 'cli': False}, 'max_fixed_ips_per_port': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347de1f10>, 'cli': False}, 'ipv6_pd_enabled': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de1f90>, 'cli': False}, 'watch_log_file': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb348303290>, 'cli': True}, 'allow_pagination': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de1bd0>, 'cli': False}, 'tcp_keepidle': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347f04fd0>, 'cli': False}, 'ipam_driver': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de7550>, 'cli': False}, 'logging_default_format_string': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303510>, 'cli': False}, 'service_plugins': {'opt': <oslo_config.cfg.ListOpt object at 0x7fb347de1a10>, 'cli': False}, 'use_stderr': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb348303410>, 'cli': False}, 'api_extensions_path': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de1890>, 'cli': False}, 'wsgi_default_pool_size': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347f10090>, 'cli': False}, 'allow_bulk': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de1b50>, 'cli': False}, 'debug': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb3482f8e90>, 'cli': True}, 'instance_format': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303850>, 'cli': False}, 'wsgi_keep_alive': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347f10190>, 'cli': False}, 'notify_nova_on_port_status_changes': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de7350>, 'cli': False}, 'use_syslog': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb348303310>, 'cli': True}, 'base_mac': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de1ad0>, 'cli': False}, 'log_dir': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb3483031d0>, 'cli': True}, 'wsgi_log_format': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347f04f50>, 'cli': False}, 'syslog_log_facility': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303390>, 'cli': True}, 'logging_debug_format_suffix': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303590>, 'cli': False}, 'logging_context_format_string': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303490>, 'cli': False}, 'allow_overlapping_ips': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de7250>, 'cli': False}, 'auth_strategy': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de1910>, 'cli': False}, 'logging_exception_prefix': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303610>, 'cli': False}, 'default_availability_zones': {'opt': <oslo_config.cfg.ListOpt object at 0x7fb347de1d50>, 'cli': False}, 'dhcp_lease_duration': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347de7050>, 'cli': False}, 'allow_sorting': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de1c50>, 'cli': False}, 'bind_port': {'opt': <oslo_config.cfg.PortOpt object at 0x7fb347de1810>, 'cli': False}, 'max_dns_nameservers': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347de1e10>, 'cli': False}, 'send_events_interval': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347de7450>, 'cli': False}, 'pagination_max_limit': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de1cd0>, 'cli': False}, 'external_dns_driver': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de7150>, 'cli': False}, 'host': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de72d0>, 'cli': False}, 'dns_domain': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de70d0>, 'cli': False}, 'max_subnet_host_routes': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347de1e90>, 'cli': False}, 'log_config_append': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb3482f8f90>, 'cli': True}, 'web_framework': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de7650>, 'cli': False}, 'api_paste_config': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347f04ed0>, 'cli': False}, 'bind_host': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de1750>, 'cli': False}, 'notify_nova_on_port_data_changes': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de73d0>, 'cli': False}, 'state_path': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de7790>, 'cli': True}, 'instance_uuid_format': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb3483038d0>, 'cli': False}, 'max_header_line': {'opt': <oslo_config.cfg.IntOpt object at 0x7fb347f10110>, 'cli': False}, 'vlan_transparent': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de75d0>, 'cli': False}, 'core_plugin': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de1990>, 'cli': False}, 'log_file': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303110>, 'cli': True}, 'dhcp_agent_notification': {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb347de71d0>, 'cli': False}, 'log_date_format': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303090>, 'cli': True}, 'logging_user_identity_format': {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303690>, 'cli': False}}, '_config_opts': [], '_ConfigOpts__cache': {}, '_args': None, '_cli_opts': deque([{'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303390>, 'group': None}, {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb348303310>, 'group': None}, {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb348303290>, 'group': None}, {'opt': <oslo_config.cfg.StrOpt object at 0x7fb3483031d0>, 'group': None}, {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303110>, 'group': None}, {'opt': <oslo_config.cfg.StrOpt object at 0x7fb348303090>, 'group': None}, {'opt': <oslo_config.cfg.StrOpt object at 0x7fb3482f8f90>, 'group': None}, {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb3482f8f10>, 'group': None}, {'opt': <oslo_config.cfg.BoolOpt object at 0x7fb3482f8e90>, 'group': None}, {'opt': <oslo_config.cfg.StrOpt object at 0x7fb347de7790>, 'group': None}]), '_mutate_hooks': set([<function _mutate_hook at 0x7fb34fac8398>]), '_mutable_ns': None}

it looks like there was a bug introduced to the neutron code... Please file a bug and let's contact neutron developers.

Revision history for this message
Dina Belova (dbelova) said : 		#3

although here https://github.com/openstack/neutron/blob/master/neutron/service.py#L72 all options are looking as expected. Really strange.

Revision history for this message
Best Dina Belova (dbelova) said : 		#4

Okay, so I found the issue :) Neutron change was continued and finished not by myself, but by Neutron team themselves. And two things happened in fact:

- they decided not to add osprofiler to the api-paste.ini pipelines by default. And none has fixed OSprofiler devstack to make it happen - and here is this discussion - https://review.openstack.org/#/c/273951/16/etc/api-paste.ini - you need to add osprofiler to the needed place in the [composite:neutronapi_v2_0]
- lately (when new initialization method was introduced to the neutron - https://review.openstack.org/#/c/342505/ - there was a bug introduced. here is a fix - https://review.openstack.org/#/c/401457/ )

Revision history for this message
venkata anil (anil-venkata) said : 		#5

Thanks a lot Dina for the fixes and suggestions.
 With these suggested changes, I could able to capture neutron trace. May be we need to document("how to enable Osprofiler trace for neutron" - in some document?

Revision history for this message
venkata anil (anil-venkata) said : 		#6

Thanks Dina Belova, that solved my question.