Add [CTRL-TIMING] logs to controller create_node flow

Timing logs cover:
- create_node_from_template (entry, get_template, add_node, total)
- add_node_from_template (entry to done)
- _create_node (project_setup, node.create, total)
- Node.create (compute_post timing)
- compute._session.request (actual HTTP to compute)

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

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 (

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":

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