[System Logging] Feature Branch

setup.py

@@ -123,6 +123,7 @@ def _parse_requirements_file(file_path):
     "requests>=2.26.0",
     "python-multipart>=0.0.5",
     "prometheus-client>=0.14.1",
+    "psutil>=5.9.4",
 ]
 _onnxruntime_deps = [
     "onnxruntime>=1.7.0",

src/deepsparse/loggers/constants.py

@@ -18,9 +18,16 @@
 from enum import Enum
 
 
-__all__ = ["MetricCategories", "validate_identifier"]
+__all__ = [
+    "MetricCategories",
+    "validate_identifier",
+    "REQUEST_DETAILS_IDENTIFIER_PREFIX",
+    "RESOURCE_UTILIZATION_IDENTIFIER_PREFIX",
+]
 
 UNSUPPORTED_IDENTIFIER_CHARS = {".", "[", "]"}
+REQUEST_DETAILS_IDENTIFIER_PREFIX = "request_details"
+RESOURCE_UTILIZATION_IDENTIFIER_PREFIX = "resource_utilization"
 
 
 class MetricCategories(Enum):

src/deepsparse/loggers/function_logger.py

@@ -18,7 +18,7 @@
 from typing import Any, Callable
 
 from deepsparse.loggers import BaseLogger, MetricCategories
-from deepsparse.loggers.helpers import NO_MATCH, match_and_extract
+from deepsparse.loggers.helpers import NO_MATCH, finalize_identifier, match_and_extract
 
 
 __all__ = ["FunctionLogger"]
@@ -80,20 +80,10 @@ def log(self, identifier: str, value: Any, category: MetricCategories):
         if extracted_value != NO_MATCH:
             if self._function_call_counter % self.frequency == 0:
                 mapped_value = self.function(extracted_value)
-                # append remainder to the identifier
-                identifier = (
-                    f"{identifier}.{remainder.split('[')[0]}"
-                    if remainder is not None
-                    else identifier
-                )
-                # append function name to the identifier
-                identifier = (
-                    identifier
-                    if category == MetricCategories.SYSTEM
-                    else f"{identifier}__{self.function_name}"
-                )
                 self.logger.log(
-                    identifier=identifier,
+                    identifier=finalize_identifier(
+                        identifier, category, self.function_name, remainder
+                    ),
                     value=mapped_value,
                     category=category,
                 )

src/deepsparse/loggers/helpers.py

@@ -32,11 +32,42 @@
     "get_function_and_function_name",
     "NO_MATCH",
     "access_nested_value",
+    "finalize_identifier",
 ]
 
 NO_MATCH = "NO_MATCH"
 
 
+def finalize_identifier(
+    identifier: str,
+    category: MetricCategories,
+    function_name: str,
+    remainder: Optional[str] = None,
+) -> str:
+    """
+    Compose the final identifier string from the identifier, category, function name
+
+    :param identifier: The identifier string
+    :param category: The category of the identifier
+    :param function_name: The name of the function applied to the identifier
+    :param remainder: The remainder of the identifier after the matching was applied
+    :return: The final identifier string
+    """
+    if remainder:
+        if category == MetricCategories.DATA:
+            # if remainder has slicing/indexing/access information,
+            # remove the square brackets:
+            remainder = remainder.split("[")[0]
+        # join the identifier and remainder
+        identifier += "." + remainder
+
+    if category == MetricCategories.DATA:
+        # if the category is DATA, add the function name to the identifier
+        identifier += f"__{function_name}"
+
+    return identifier
+
+
 def get_function_and_function_name(
     function_identifier: str,
 ) -> Tuple[Callable[[Any], Any], str]:
@@ -99,11 +130,12 @@ def match_and_extract(
     template: str,
     identifier: str,
     value: Any,
-    category: Optional[MetricCategories] = None,
+    category: MetricCategories,
 ) -> Tuple[Any, Optional[str]]:
     """
-    Attempts to match the template against the identifier. If successful,
-    uses the remainder to extract the item of interest inside `value` data structure.
+    Attempts to match the template against the identifier. If successful, and
+    the category is DATA, uses the remainder to extract the item of interest inside
+    `value` data structure.
 
     :param template: A string that defines the matching criteria
     :param identifier: A string that will be compared with the template, may
@@ -116,11 +148,13 @@ def match_and_extract(
         - Value of interest or string flag that indicates that there was no match
         - An optional remainder string
     """
-    is_match, remainder = check_identifier_match(
-        template, identifier, category=category
-    )
+    is_match, remainder = check_identifier_match(template, identifier)
+
     if is_match:
-        return possibly_extract_value(value, remainder), remainder
+        if category == MetricCategories.SYSTEM:
+            return value, remainder
+        else:
+            return possibly_extract_value(value, remainder), remainder
     else:
         return NO_MATCH, remainder
 
@@ -225,7 +259,8 @@ def access_nested_value(
 
 
 def check_identifier_match(
-    template: str, identifier: str, category: Optional[MetricCategories] = None
+    template: str,
+    identifier: str,
 ) -> Tuple[bool, Optional[str]]:
     """
     Match the template against the identifier
@@ -236,13 +271,12 @@ def check_identifier_match(
         by `category:`
 
     :param identifier: A string in the format:
+        <string_n-t>/<string_n-t+1)>/<...>/<string_n>
+        If template and identifier do not share any first
+        <string_n-t+k> components, there is no match.
 
-        1.  <string_n-t>/<string_n-t+1)>/<...>/<string_n>
-        2.
-            if template and identifier do not share any first
-            <string_n-t+k> components, there is no match
-
-    :param category: optional MetricCategory of the value logged value
+    Note: if identifier is longer than a template, and both share the
+    first string components, there is a match with no remainder.
 
     :return: A tuple that consists of:
         - a boolean (True if match, False otherwise)
@@ -251,17 +285,13 @@ def check_identifier_match(
     if template[:3] == "re:":
         pattern = template[3:]
         return re.match(pattern, identifier) is not None, None
-    if template.startswith("category:") and category is not None:
-        template_category = template[9:]
-        template_category = MetricCategories(template_category)  # parse into Enum
-        category = MetricCategories(category)  # ensure in Enum form
-        return template_category == category, None
     if template == identifier:
         return True, None
     if template.startswith(identifier):
         remainder = template.replace(identifier, "")
         return True, remainder if remainder.startswith("[") else remainder[1:]
-
+    if template in identifier:
+        return True, None
     return False, None
 
 

src/deepsparse/pipeline.py

@@ -28,7 +28,13 @@
 from deepsparse import Context, Engine, MultiModelEngine, Scheduler
 from deepsparse.benchmark import ORTEngine
 from deepsparse.cpu import cpu_details
-from deepsparse.loggers import BaseLogger, MetricCategories, validate_identifier
+from deepsparse.loggers import (
+    REQUEST_DETAILS_IDENTIFIER_PREFIX,
+    RESOURCE_UTILIZATION_IDENTIFIER_PREFIX,
+    BaseLogger,
+    MetricCategories,
+    validate_identifier,
+)
 from deepsparse.tasks import SupportedTasks, dynamic_import_task
 from deepsparse.timing import InferencePhases, Timer
 
@@ -187,6 +193,12 @@ def __init__(
 
         self._batch_size = self._batch_size or 1
 
+        self.log(
+            identifier=f"{RESOURCE_UTILIZATION_IDENTIFIER_PREFIX}/num_cores",
+            value=num_cores,
+            category=MetricCategories.SYSTEM,
+        )
+
     def __call__(self, *args, **kwargs) -> BaseModel:
         if "engine_inputs" in kwargs:
             raise ValueError(
@@ -227,7 +239,9 @@ def __call__(self, *args, **kwargs) -> BaseModel:
             category=MetricCategories.DATA,
         )
         self.log(
-            identifier=InferencePhases.PRE_PROCESS,
+            # note, will be replaced by a reference instead of "bare" string
+            # with the upcoming PR for system logging
+            identifier=f"prediction_latency/{InferencePhases.PRE_PROCESS}",
             value=timer.time_delta(InferencePhases.PRE_PROCESS),
             category=MetricCategories.SYSTEM,
         )
@@ -244,13 +258,23 @@ def __call__(self, *args, **kwargs) -> BaseModel:
         engine_outputs = self.join_engine_outputs(batch_outputs)
         timer.stop(InferencePhases.ENGINE_FORWARD)
 
+        self.log(
+            identifier=f"{REQUEST_DETAILS_IDENTIFIER_PREFIX}/input_batch_size",
+            # to get the batch size of the inputs, we need to look
+            # to multiply the engine batch size (self._batch_size)
+            # by the number of batches processed by the engine during
+            # a single inference call
+            value=len(batch_outputs) * self._batch_size,
+            category=MetricCategories.SYSTEM,
+        )
+
         self.log(
             identifier="engine_outputs",
             value=engine_outputs,
             category=MetricCategories.DATA,
         )
         self.log(
-            identifier=InferencePhases.ENGINE_FORWARD,
+            identifier=f"prediction_latency/{InferencePhases.ENGINE_FORWARD}",
             value=timer.time_delta(InferencePhases.ENGINE_FORWARD),
             category=MetricCategories.SYSTEM,
         )
@@ -274,12 +298,12 @@ def __call__(self, *args, **kwargs) -> BaseModel:
             category=MetricCategories.DATA,
         )
         self.log(
-            identifier=InferencePhases.POST_PROCESS,
+            identifier=f"prediction_latency/{InferencePhases.POST_PROCESS}",
             value=timer.time_delta(InferencePhases.POST_PROCESS),
             category=MetricCategories.SYSTEM,
         )
         self.log(
-            identifier=InferencePhases.TOTAL_INFERENCE,
+            identifier=f"prediction_latency/{InferencePhases.TOTAL_INFERENCE}",
             value=timer.time_delta(InferencePhases.TOTAL_INFERENCE),
             category=MetricCategories.SYSTEM,
         )
@@ -700,22 +724,32 @@ def to_config(self) -> "PipelineConfig":
             kwargs=kwargs,
         )
 
-    def log(self, identifier: str, value: Any, category: str):
+    def log(
+        self,
+        identifier: str,
+        value: Any,
+        category: str,
+    ):
         """
-        Pass the logged data to the DeepSparse logger object (if present)
+        Pass the logged data to the DeepSparse logger object (if present).
 
         :param identifier: The string name assigned to the logged value
         :param value: The logged data structure
         :param category: The metric category that the log belongs to
         """
-        identifier = f"{self.alias or self.task}/{identifier}"
+        if not self.logger:
+            return
+
+        if not hasattr(self, "task"):
+            self.task = None
+
+        identifier = f"{self.alias or self.task or 'unknown_pipeline'}/{identifier}"
         validate_identifier(identifier)
-        if self.logger:
-            self.logger.log(
-                identifier=identifier,
-                value=value,
-                category=category,
-            )
+        self.logger.log(
+            identifier=identifier,
+            value=value,
+            category=category,
+        )
         return
 
     def parse_inputs(self, *args, **kwargs) -> BaseModel: