perf(analyze): improved performance of code analysis (more then 2x faster)

Author: d-biehl

packages/core/src/robotcode/core/utils/logging.py

@@ -16,6 +16,7 @@
     Dict,
     Iterator,
     List,
+    Mapping,
     Optional,
     Type,
     TypeVar,
@@ -192,20 +193,25 @@ def log(
         *args: Any,
         stacklevel: int = 2,
         context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
         if self.is_enabled_for(level) and condition is not None and condition() or condition is None:
             depth = 0
             if context_name is not None:
                 depth = self._measure_contexts.get(context_name, 0)
 
-            msg = ("  " * depth) + (msg() if callable(msg) else msg)
+            if depth > 0:
+                extra = {**extra} if extra is not None else {}
+                if "indent" not in extra:
+                    extra["indent"] = "  " * depth
 
             self.logger.log(
                 level,
-                msg,
+                msg() if callable(msg) else msg,
                 *args,
                 stacklevel=stacklevel,
+                extra=extra,
                 **kwargs,
             )
 
@@ -215,6 +221,8 @@ def debug(
         condition: Optional[Callable[[], bool]] = None,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
         return self.log(
@@ -223,6 +231,8 @@ def debug(
             condition,
             *args,
             stacklevel=stacklevel,
+            context_name=context_name,
+            extra=extra,
             **kwargs,
         )
 
@@ -236,6 +246,7 @@ def measure_time(
         *args: Any,
         level: int = logging.DEBUG,
         context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> Iterator[None]:
         if self.is_enabled_for(level):
@@ -244,9 +255,19 @@ def measure_time(
             if context_name is not None:
                 depth = self._measure_contexts.get(context_name, 0)
 
-                self._measure_contexts[context_name] = depth + 1
+                self._measure_contexts[context_name] = depth
+
+            self._log_measure_time(
+                level,
+                lambda: f"Start {msg() if callable(msg) else msg}",
+                *args,
+                context_name=context_name,
+                extra=extra,
+                **kwargs,
+            )
 
-            self._log_measure_time(level, f"{'  '*depth}Start {msg() if callable(msg) else msg}", *args, **kwargs)
+            if context_name is not None:
+                self._measure_contexts[context_name] = depth + 1
 
             start_time = time.monotonic()
             try:
@@ -259,8 +280,10 @@ def measure_time(
 
                 self._log_measure_time(
                     level,
-                    f"{'  '*depth}End {msg() if callable(msg) else msg} took {duration} seconds",
+                    lambda: f"End {msg() if callable(msg) else msg} took {duration:.4f} seconds",
                     *args,
+                    context_name=context_name,
+                    extra=extra,
                     **kwargs,
                 )
         else:
@@ -272,16 +295,22 @@ def info(
         condition: Optional[Callable[[], bool]] = None,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
-        return self.log(logging.INFO, msg, condition, *args, stacklevel=stacklevel, **kwargs)
+        return self.log(
+            logging.INFO, msg, condition, *args, stacklevel=stacklevel, context_name=context_name, extra=extra, **kwargs
+        )
 
     def warning(
         self,
         msg: Union[str, Callable[[], str]],
         condition: Optional[Callable[[], bool]] = None,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
         return self.log(
@@ -290,6 +319,8 @@ def warning(
             condition,
             *args,
             stacklevel=stacklevel,
+            context_name=context_name,
+            extra=extra,
             **kwargs,
         )
 
@@ -299,6 +330,8 @@ def error(
         condition: Optional[Callable[[], bool]] = None,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
         return self.log(
@@ -307,6 +340,8 @@ def error(
             condition,
             *args,
             stacklevel=stacklevel,
+            context_name=context_name,
+            extra=extra,
             **kwargs,
         )
 
@@ -316,9 +351,13 @@ def trace(
         condition: Optional[Callable[[], bool]] = None,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
-        return self.log(TRACE, msg, condition, *args, stacklevel=stacklevel, **kwargs)
+        return self.log(
+            TRACE, msg, condition, *args, stacklevel=stacklevel, context_name=context_name, extra=extra, **kwargs
+        )
 
     def exception(
         self,
@@ -327,6 +366,8 @@ def exception(
         exc_info: Any = True,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         level: Optional[int] = None,
         **kwargs: Any,
     ) -> None:
@@ -342,6 +383,8 @@ def exception(
                 *args,
                 exc_info=exc_info,
                 stacklevel=stacklevel,
+                context_name=context_name,
+                extra=extra,
                 **kwargs,
             )
 
@@ -352,6 +395,7 @@ def exception(
             *args,
             exc_info=exc_info,
             stacklevel=stacklevel,
+            extra=extra,
             **kwargs,
         )
 
@@ -361,6 +405,8 @@ def critical(
         condition: Optional[Callable[[], bool]] = None,
         *args: Any,
         stacklevel: int = 3,
+        context_name: Optional[str] = None,
+        extra: Optional[Mapping[str, object]] = None,
         **kwargs: Any,
     ) -> None:
         return self.log(
@@ -369,6 +415,8 @@ def critical(
             condition,
             *args,
             stacklevel=stacklevel,
+            context_name=context_name,
+            extra=extra,
             **kwargs,
         )
 

packages/core/src/robotcode/core/utils/path.py

@@ -19,7 +19,7 @@ def path_is_relative_to(
 _RE_DRIVE_LETTER_PATH = re.compile(r"^[a-zA-Z]:")
 
 
-def normalized_path(path: Union[Path, str, "os.PathLike[Any]"]) -> Path:
+def normalized_path(path: "Union[str, os.PathLike[str]]") -> Path:
     p = os.path.normpath(os.path.abspath(path))
 
     if sys.platform == "win32" and _RE_DRIVE_LETTER_PATH.match(str(p)):
@@ -28,7 +28,7 @@ def normalized_path(path: Union[Path, str, "os.PathLike[Any]"]) -> Path:
     return Path(p)
 
 
-def normalized_path_full(path: Union[Path, str, "os.PathLike[Any]"]) -> Path:
+def normalized_path_full(path: Union[str, "os.PathLike[Any]"]) -> Path:
     p = normalized_path(path)
 
     orig_parents = list(reversed(p.parents))

packages/language_server/src/robotcode/language_server/common/parts/diagnostics.py

@@ -1,6 +1,7 @@
 import concurrent.futures
 import functools
 import itertools
+import logging
 import time
 import uuid
 from concurrent.futures import CancelledError
@@ -337,6 +338,7 @@ def run_workspace_diagnostics(self) -> None:
         self.ensure_workspace_loaded()
 
         while True:
+
             check_current_task_canceled()
 
             self.on_workspace_diagnostics_start(self)
@@ -359,6 +361,7 @@ def run_workspace_diagnostics(self) -> None:
                 with self._logger.measure_time(
                     lambda: f"analyzing workspace for {len(documents)} documents",
                     context_name="workspace_diagnostics",
+                    level=logging.CRITICAL,
                 ):
 
                     self.on_workspace_diagnostics_analyze(self)
@@ -375,13 +378,15 @@ def run_workspace_diagnostics(self) -> None:
                         max=len(documents),
                         start=False,
                     ) as progress:
+                        breaked = False
                         for i, document in enumerate(documents):
                             check_current_task_canceled()
 
-                            if self._break_diagnostics_loop_event.is_set():
+                            if breaked or self._break_diagnostics_loop_event.is_set():
                                 self._logger.debug(
                                     "break workspace diagnostics loop 2", context_name="workspace_diagnostics"
                                 )
+                                breaked = True
                                 self.on_workspace_diagnostics_break(self)
                                 break
 
@@ -409,6 +414,7 @@ def run_workspace_diagnostics(self) -> None:
                                 self._logger.debug(
                                     lambda: f"Analyzing {document.uri} cancelled", context_name="workspace_diagnostics"
                                 )
+                                breaked = True
                             except BaseException as e:
                                 ex = e
                                 self._logger.exception(
@@ -420,7 +426,7 @@ def run_workspace_diagnostics(self) -> None:
                                 with self._current_diagnostics_task_lock:
                                     self._current_diagnostics_task = None
 
-                    if self._break_diagnostics_loop_event.is_set():
+                    if breaked or self._break_diagnostics_loop_event.is_set():
                         self._logger.debug("break workspace diagnostics loop 3", context_name="workspace_diagnostics")
                         self.on_workspace_diagnostics_break(self)
                         continue
@@ -436,13 +442,15 @@ def run_workspace_diagnostics(self) -> None:
                 with self._logger.measure_time(
                     lambda: f"collect workspace diagnostic for {len(documents_to_collect)} documents",
                     context_name="collect_workspace_diagnostics",
+                    level=logging.CRITICAL,
                 ):
-
+                    breaked = False
                     for document in set(documents) - set(documents_to_collect):
                         check_current_task_canceled()
 
-                        if self._break_diagnostics_loop_event.is_set():
+                        if breaked or self._break_diagnostics_loop_event.is_set():
                             self._logger.debug("break workspace diagnostics loop 4")
+                            breaked = True
                             self.on_workspace_diagnostics_break(self)
                             break
 
@@ -456,10 +464,6 @@ def run_workspace_diagnostics(self) -> None:
                         start=False,
                     ) as progress:
                         for i, document in enumerate(documents_to_collect):
-                            self._logger.debug(
-                                lambda: f"collect diagnostics for {document.uri}",
-                                context_name="collect_workspace_diagnostics",
-                            )
                             check_current_task_canceled()
 
                             if self._break_diagnostics_loop_event.is_set():
@@ -503,6 +507,7 @@ def run_workspace_diagnostics(self) -> None:
                                     lambda: f"Collecting diagnostics for {document.uri} cancelled",
                                     context_name="collect_workspace_diagnostics",
                                 )
+                                breaked = True
                             except BaseException as e:
                                 ex = e
                                 self._logger.exception(
@@ -584,8 +589,6 @@ def _get_diagnostics_for_document(
         send_diagnostics: bool,
         collect_slow: bool,
     ) -> None:
-        self._logger.debug(lambda: f"Get diagnostics for {document}")
-
         if debounce:
             check_current_task_canceled(0.75)
 
@@ -661,8 +664,6 @@ def _text_document_diagnostic(
         *args: Any,
         **kwargs: Any,
     ) -> DocumentDiagnosticReport:
-        self._logger.debug("textDocument/diagnostic")
-
         self.parent.ensure_initialized()
 
         try:

packages/language_server/src/robotcode/language_server/robotframework/parts/completion.py

@@ -2068,7 +2068,7 @@ def complete_arguments() -> Optional[List[CompletionItem]]:
                 return None
 
             try:
-                libdoc = self.namespace.get_imported_variables_libdoc(import_node.name, import_node.args)
+                libdoc = self.namespace.get_variables_import_libdoc(import_node.name, import_node.args)
                 if libdoc is not None:
                     init = next((v for v in libdoc.inits.values()), None)
                     if init:

packages/language_server/src/robotcode/language_server/robotframework/parts/diagnostics.py

@@ -79,7 +79,7 @@ def _on_variables_changed(self, sender: Any, variables: List[LibraryDoc]) -> Non
         for doc in self.parent.documents.documents:
             namespace = self.parent.documents_cache.get_only_initialized_namespace(doc)
             if namespace is not None:
-                lib_docs = (e.library_doc for e in namespace.get_imported_variables().values())
+                lib_docs = (e.library_doc for e in namespace.get_variables_imports().values())
                 if any(lib_doc in lib_docs for lib_doc in variables):
                     self.parent.diagnostics.force_refresh_document(doc)
 

packages/language_server/src/robotcode/language_server/robotframework/parts/goto.py

@@ -65,16 +65,17 @@ def collect(
                 )
 
                 if found_range is not None and variable.source:
-                    result.append(
-                        LocationLink(
-                            origin_selection_range=found_range,
-                            target_uri=str(Uri.from_path(variable.source)),
-                            target_range=variable.range,
-                            target_selection_range=(
-                                range_from_token(variable.name_token) if variable.name_token else variable.range
-                            ),
+                    if variable.source:
+                        result.append(
+                            LocationLink(
+                                origin_selection_range=found_range,
+                                target_uri=str(Uri.from_path(variable.source)),
+                                target_range=variable.range,
+                                target_selection_range=(
+                                    range_from_token(variable.name_token) if variable.name_token else variable.range
+                                ),
+                            )
                         )
-                    )
 
             if result:
                 return result

packages/language_server/src/robotcode/language_server/robotframework/parts/inlay_hint.py

@@ -360,7 +360,7 @@ def handle_VariablesImport(  # noqa: N802
         try:
             namespace = self.parent.documents_cache.get_namespace(document)
 
-            lib_doc = namespace.get_imported_variables_libdoc(library_node.name, library_node.args)
+            lib_doc = namespace.get_variables_import_libdoc(library_node.name, library_node.args)
 
             if lib_doc is None or lib_doc.errors:
                 lib_doc = namespace.imports_manager.get_libdoc_for_variables_import(