feat(gdb): add detailed timing logs for GDB operations

Add [GDB] prefixed logs to all GDB session methods:
- _execute_cli: log slow commands (>1s as warning, others as debug)
- _lookup_symbol_impl: log start/done with address and timing
- _search_symbols_impl: log query, result count, and timing
- _resolve_addresses: log unresolved count and resolution stats
- _get_struct_layout_impl: log member count and timing

Add [symbols] prefixed logs to route handlers:
- _lookup_symbol: log GDB lookup timing
- api_search_symbols: log search delegation and results

Signed-off-by: VIFEX <vifextech@foxmail.com>

Author: FASTSHIFT

Tools/WebServer/app/routes/symbols.py

@@ -135,7 +135,14 @@ def _lookup_symbol(sym_name):
         logger.warning("GDB not available, cannot look up symbol")
         return None
 
+    t0 = time.time()
     result = state.gdb_session.lookup_symbol(sym_name)
+    elapsed = time.time() - t0
+
+    if elapsed > 1.0:
+        logger.warning(f"[symbols] GDB lookup_symbol '{sym_name}' took {elapsed:.2f}s")
+    else:
+        logger.info(f"[symbols] GDB lookup_symbol '{sym_name}': {elapsed:.3f}s")
 
     # Cache for future lookups
     if result is not None:
@@ -179,6 +186,8 @@ def api_search_symbols():
 
     query = request.args.get("q", "").strip()
     limit = int(request.args.get("limit", 100))
+    t_start = time.time()
+    logger.info(f"[symbols] search request: query='{query}' limit={limit}")
 
     if not query:
         return jsonify({"success": True, "symbols": [], "total": 0, "filtered": 0})
@@ -220,7 +229,13 @@ def api_search_symbols():
             symbol_list = matched[:limit]
         elif is_gdb_available(state):
             # GDB fast search (~0.01s vs ~3s)
+            logger.info(f"[symbols] delegating search to GDB: '{query}'")
             symbol_list, total = state.gdb_session.search_symbols(query, limit=limit)
+            elapsed = time.time() - t_start
+            logger.info(
+                f"[symbols] GDB search done: '{query}' -> "
+                f"{len(symbol_list)} results ({elapsed:.3f}s)"
+            )
         else:
             symbol_list, total = [], 0
             logger.warning("GDB not available, cannot search symbols")

Tools/WebServer/core/gdb_session.py

@@ -331,9 +331,16 @@ def _execute_mi(self, cmd: str, timeout: float = GDB_CMD_TIMEOUT) -> Optional[st
 
     def _execute_cli(self, cmd: str, timeout: float = GDB_CMD_TIMEOUT) -> Optional[str]:
         """Execute a GDB CLI command and return console output lines."""
+        t0 = time.time()
         raw = self._execute_mi(cmd, timeout)
+        elapsed = time.time() - t0
         if raw is None:
+            logger.warning(f"[GDB] command timed out ({elapsed:.2f}s): {cmd}")
             return None
+        if elapsed > 1.0:
+            logger.warning(f"[GDB] slow command ({elapsed:.2f}s): {cmd}")
+        else:
+            logger.debug(f"[GDB] command ({elapsed:.3f}s): {cmd}")
         return self._extract_console_output(raw)
 
     def _read_until_prompt(self, timeout: float = 5.0) -> Optional[str]:
@@ -415,13 +422,20 @@ def _extract_console_output(raw: str) -> str:
 
     def _lookup_symbol_impl(self, sym_name: str) -> Optional[dict]:
         """Internal implementation of lookup_symbol."""
+        t_start = time.time()
+        logger.info(f"[GDB] lookup_symbol start: '{sym_name}'")
+
         # Use 'info address' to get symbol address
         output = self._execute_cli(f"info address {sym_name}")
         if not output or "No symbol" in output:
+            logger.info(f"[GDB] lookup_symbol: '{sym_name}' not found")
             return None
 
         addr = self._parse_address_from_info(output)
         if addr is None:
+            logger.warning(
+                f"[GDB] lookup_symbol: cannot parse address for '{sym_name}'"
+            )
             return None
 
         # Get size via 'print sizeof(sym_name)'
@@ -445,6 +459,12 @@ def _lookup_symbol_impl(self, sym_name: str) -> Optional[dict]:
                 if ptype_out and re.match(r"type\s*=\s*const\b", ptype_out):
                     sym_type = "const"
 
+        elapsed = time.time() - t_start
+        logger.info(
+            f"[GDB] lookup_symbol done: '{sym_name}' -> "
+            f"0x{addr:08X} size={size} type={sym_type} ({elapsed:.3f}s)"
+        )
+
         return {
             "addr": addr,
             "size": size,
@@ -456,6 +476,8 @@ def _search_symbols_impl(
         self, query: str, limit: int = 100
     ) -> Tuple[List[dict], int]:
         """Internal implementation of search_symbols."""
+        t_start = time.time()
+        logger.info(f"[GDB] search_symbols start: query='{query}' limit={limit}")
         query_lower = query.lower().strip()
         is_addr = query_lower.startswith("0x") or (
             len(query_lower) >= 4 and all(c in "0123456789abcdef" for c in query_lower)
@@ -498,10 +520,21 @@ def _search_symbols_impl(
                 seen.add(r["name"])
                 unique.append(r)
 
+        t_parse = time.time()
+        logger.info(
+            f"[GDB] search_symbols: found {len(unique)} unique symbols, "
+            f"resolving addresses... (parse took {t_parse - t_start:.3f}s)"
+        )
+
         # Resolve missing addresses via 'info address'
         self._resolve_addresses(unique)
 
         unique.sort(key=lambda x: x["name"])
+        elapsed = time.time() - t_start
+        logger.info(
+            f"[GDB] search_symbols done: query='{query}' -> "
+            f"{len(unique)} results ({elapsed:.3f}s)"
+        )
         return unique[:limit], len(unique)
 
     def _get_symbols_impl(self) -> Dict[str, dict]:
@@ -551,15 +584,27 @@ def _get_struct_layout_impl(self, sym_name: str) -> Optional[List[dict]]:
 
         Uses 'ptype /o <sym>' which shows struct members with offsets.
         """
+        t0 = time.time()
+        logger.info(f"[GDB] get_struct_layout start: '{sym_name}'")
+
         output = self._execute_cli(f"ptype /o {sym_name}")
         if not output:
+            logger.info(f"[GDB] get_struct_layout: no output for '{sym_name}'")
             return None
 
         # Check if it's a struct/union
         if "type = struct" not in output and "type = union" not in output:
+            logger.info(f"[GDB] get_struct_layout: '{sym_name}' is not struct/union")
             return None
 
-        return self._parse_ptype_output(output)
+        result = self._parse_ptype_output(output)
+        elapsed = time.time() - t0
+        member_count = len(result) if result else 0
+        logger.info(
+            f"[GDB] get_struct_layout done: '{sym_name}' -> "
+            f"{member_count} members ({elapsed:.3f}s)"
+        )
+        return result
 
     def _read_symbol_value_impl(self, sym_name: str) -> Optional[bytes]:
         """Internal implementation of read_symbol_value.
@@ -627,6 +672,14 @@ def _resolve_addresses(self, symbols: List[dict]):
         addresses. This method queries 'info address <name>' for each symbol
         with addr "0x00000000" to fill in the real address and section.
         """
+        unresolved = [s for s in symbols if s["addr"] == "0x00000000"]
+        if unresolved:
+            logger.info(
+                f"[GDB] _resolve_addresses: {len(unresolved)}/{len(symbols)} "
+                f"symbols need address resolution"
+            )
+        t0 = time.time()
+        resolved_count = 0
         for sym in symbols:
             if sym["addr"] != "0x00000000":
                 continue
@@ -636,6 +689,7 @@ def _resolve_addresses(self, symbols: List[dict]):
             addr = self._parse_address_from_info(output)
             if addr is not None:
                 sym["addr"] = f"0x{addr:08X}"
+                resolved_count += 1
                 # Also fix section and type from info address output
                 section = self._get_symbol_section(output)
                 if section:
@@ -650,6 +704,13 @@ def _resolve_addresses(self, symbols: List[dict]):
                         # Preserve const classification from declaration
                         sym["type"] = "variable"
 
+        if unresolved:
+            elapsed = time.time() - t0
+            logger.info(
+                f"[GDB] _resolve_addresses done: resolved {resolved_count}/{len(unresolved)} "
+                f"({elapsed:.3f}s)"
+            )
+
     @staticmethod
     def _parse_address_from_info(output: str) -> Optional[int]:
         """Parse address from 'info address' output.