diff --git a/gns3server/api/routes/controller/projects.py b/gns3server/api/routes/controller/projects.py index 354c15cfb..eb3e7333e 100644 --- a/gns3server/api/routes/controller/projects.py +++ b/gns3server/api/routes/controller/projects.py @@ -609,11 +609,21 @@ async def create_node_from_template( Required privilege: Node.Allocate """ + import time as _time + _t0 = _time.time() + log.info(f"[CTRL-TIMING] create_node_from_template ENTER template_id={template_id}") template = await TemplatesService(templates_repo).get_template(template_id) + log.info(f"[CTRL-TIMING] get_template done elapsed={_time.time()-_t0:.3f}s") + controller = Controller.instance() project = controller.get_project(str(project_id)) + node = await project.add_node_from_template( template, x=template_usage.x, y=template_usage.y, compute_id=template_usage.compute_id ) - return node.asdict() + log.info(f"[CTRL-TIMING] add_node_from_template done elapsed={_time.time()-_t0:.3f}s") + + result = node.asdict() + log.info(f"[CTRL-TIMING] create_node_from_template DONE total={_time.time()-_t0:.3f}s") + return result diff --git a/gns3server/controller/compute.py b/gns3server/controller/compute.py index 7ec8691a8..a69139cae 100644 --- a/gns3server/controller/compute.py +++ b/gns3server/controller/compute.py @@ -22,6 +22,7 @@ import socket import json import sys import io +import time from fastapi import HTTPException from aiohttp import web @@ -546,9 +547,12 @@ class Compute: data = json.dumps(data).encode("utf-8") try: log.debug(f"Attempting request to compute: {method} {url} {headers}") + _t0 = time.time() response = await self._session().request( method, url, headers=headers, data=data, auth=self._auth, params=params, chunked=chunked, timeout=timeout ) + log.info(f"[CTRL-TIMING] compute._session.request DONE {method} {url.split('/v3')[1] if '/v3' in url else url} " + f"status={response.status} elapsed={_time.time()-_t0:.3f}s") except asyncio.TimeoutError: raise ComputeError(f"Timeout error for {method} call to {url} after {timeout}s") except ( diff --git a/gns3server/controller/node.py b/gns3server/controller/node.py index 3378f055f..44516e3dd 100644 --- a/gns3server/controller/node.py +++ b/gns3server/controller/node.py @@ -402,6 +402,8 @@ class Node: """ Create the node on the compute """ + import time as _time + _t0 = _time.time() data = self._node_data() data["node_id"] = self._id if self._node_type == "docker": @@ -414,6 +416,8 @@ class Node: response = await self._compute.post( f"/projects/{self._project.id}/{self._node_type}/nodes", data=data, timeout=timeout ) + log.info(f"[CTRL-TIMING] Node.create compute_post DONE name={self._name} " + f"type={self._node_type} elapsed={_time.time()-_t0:.3f}s") except ComputeConflictError as e: response = e.response() if response.get("exception") == "ImageMissingError": diff --git a/gns3server/controller/project.py b/gns3server/controller/project.py index 63d3d7ac9..2e27b02bf 100644 --- a/gns3server/controller/project.py +++ b/gns3server/controller/project.py @@ -563,13 +563,14 @@ class Project: """ Create a node from a template. """ + import time as _time + _t0 = _time.time() template["x"] = x template["y"] = y node_type = template.pop("template_type") if compute_id: - # use a custom compute_id compute = self.controller.get_compute(compute_id) else: compute = self.controller.get_compute(template.pop("compute_id")) @@ -580,26 +581,30 @@ class Project: name = default_name_format.replace("{name}", template_name) node_id = str(uuid.uuid4()) node = await self.add_node(compute, name, node_id, node_type=node_type, **template) + log.info(f"[CTRL-TIMING] add_node_from_template DONE name={name} elapsed={_time.time()-_t0:.3f}s") return node async def _create_node(self, compute, name, node_id, node_type=None, **kwargs): + import time as _time + _t0 = _time.time() node = Node(self, compute, name, node_id=node_id, node_type=node_type, **kwargs) + _t1 = _time.time() if compute not in self._project_created_on_compute: - # For a local server we send the project path if compute.id == "local": data = {"name": self._name, "project_id": self._id, "path": self._path} else: data = {"name": self._name, "project_id": self._id} - if self._variables: data["variables"] = self._variables - await compute.post("/projects", data=data) self._project_created_on_compute.add(compute) + log.info(f"[CTRL-TIMING] _create_node project_setup name={name} elapsed={_time.time()-_t0:.3f}s" + f" (node_init={_t1-_t0:.3f}s)") await node.create() self._nodes[node.id] = node + log.info(f"[CTRL-TIMING] _create_node node.create DONE name={name} elapsed={_time.time()-_t0:.3f}s") return node