Additional logs

Author: YuraLukashik

pinecone/core/client/api_client.py

@@ -11,6 +11,7 @@
 
 import json
 import atexit
+import logging
 import mimetypes
 from multiprocessing.pool import ThreadPool
 import io
@@ -38,6 +39,7 @@
     none_type,
     validate_and_convert_types,
 )
+from pinecone.stopwatch import track
 
 
 class ApiClient(object):
@@ -181,6 +183,7 @@ def __call_api(
             url = _host + resource_path
 
         try:
+            logging.debug(f"api_client.__call_api calling self.request: {track('query'):.3f}")
             # perform request and return response
             response_data = self.request(
                 method,
@@ -195,6 +198,7 @@ def __call_api(
         except ApiException as e:
             e.body = e.body.decode("utf-8")
             raise e
+        logging.debug(f"api_client.__call_api finished the request: {track('query'):.3f}")
 
         self.last_response = response_data
 
@@ -204,6 +208,7 @@ def __call_api(
             return return_data
             return return_data
 
+        logging.debug(f"api_client.__call_api starting deserialization: {track('query'):.3f}")
         # deserialize response data
         if response_type:
             if response_type != (file_type,):
@@ -218,6 +223,7 @@ def __call_api(
             return_data = self.deserialize(response_data, response_type, _check_type)
         else:
             return_data = None
+        logging.debug(f"api_client.__call_api finished deserialization: {track('query'):.3f}")
 
         if _return_http_data_only:
             return return_data

pinecone/core/client/rest.py

@@ -26,7 +26,7 @@
     ServiceException,
     ApiValueError,
 )
-
+from pinecone.stopwatch import track
 
 logger = logging.getLogger(__name__)
 
@@ -112,6 +112,7 @@ def request(
         _preload_content=True,
         _request_timeout=None,
     ):
+        logging.debug(f"Starting rest[{method}] request: {track('query'):.3f}")
         """Perform requests.
 
         :param method: http request method
@@ -211,9 +212,11 @@ def request(
                     raise ApiException(status=0, reason=msg)
             # For `GET`, `HEAD`
             else:
+                logging.debug(f"Calling pool_manager for [{method}] request: {track('query'):.3f}")
                 r = self.pool_manager.request(
                     method, url, fields=query_params, preload_content=_preload_content, timeout=timeout, headers=headers
                 )
+                logging.debug(f"pool_manager returned a response for [{method}] request: {track('query'):.3f}")
         except urllib3.exceptions.SSLError as e:
             msg = "{0}\n{1}".format(type(e).__name__, str(e))
             raise ApiException(status=0, reason=msg)
@@ -223,6 +226,7 @@ def request(
 
             # log response body
             logger.debug("response body: %s", r.data)
+            logging.debug(f"Response body for [{method}] request: {track('query'):.3f}")
 
         if not 200 <= r.status <= 299:
             if r.status == 401:

pinecone/index.py

@@ -1,3 +1,5 @@
+import logging
+
 from tqdm.autonotebook import tqdm
 from importlib.util import find_spec
 import numbers
@@ -54,6 +56,7 @@
 
 from .core.utils.constants import REQUIRED_VECTOR_FIELDS, OPTIONAL_VECTOR_FIELDS
 from .core.utils.error_handling import validate_and_convert_errors
+from .stopwatch import track, reset
 
 _OPENAPI_ENDPOINT_PARAMS = (
     "_return_http_data_only",
@@ -455,6 +458,7 @@ def query(
         Returns: QueryResponse object which contains the list of the closest vectors as ScoredVector objects,
                  and namespace name.
         """
+        logging.debug(f"Started executing a Pinecone query: {track('query'):.3f}")
 
         def _query_transform(item):
             if isinstance(item, QueryVector):
@@ -494,7 +498,11 @@ def _query_transform(item):
             ),
             **{k: v for k, v in kwargs.items() if k in _OPENAPI_ENDPOINT_PARAMS},
         )
-        return parse_query_response(response, vector is not None or id)
+        logging.debug(f"Vector API returned a response: {track('query'):.3f}")
+        parsed_response = parse_query_response(response, vector is not None or id)
+        logging.debug(f"Parsed query response: {track('query'):.3f}")
+        reset("query")
+        return parsed_response
 
     @validate_and_convert_errors
     def update(

pinecone/stopwatch.py

@@ -0,0 +1,14 @@
+import time
+
+stopwatches = {}
+
+
+def track(name: str) -> float:
+    if name not in stopwatches:
+        stopwatches[name] = time.time_ns()
+        return 0.
+    return (time.time_ns() - stopwatches[name]) / 10**9
+
+
+def reset(name: str):
+    del stopwatches[name]