Additional logs

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,20 +208,25 @@ 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:
+            logging.debug(f"api_client.__call_api response_type {str(response_type)}: {track('query'):.3f}")
             if response_type != (file_type,):
                 encoding = "utf-8"
                 content_type = response_data.getheader("content-type")
                 if content_type is not None:
                     match = re.search(r"charset=([a-zA-Z\-\d]+)[\s\;]?", content_type)
                     if match:
                         encoding = match.group(1)
+                logging.debug(f"api_client.__call_api response_data.data.decode({encoding}): {track('query'):.3f}")
                 response_data.data = response_data.data.decode(encoding)
 
+            logging.debug(f"api_client.__call_api calling self.deserialize: {track('query'):.3f}")
             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
@@ -297,20 +306,27 @@ def deserialize(self, response, response_type, _check_type):
         # handle file downloading
         # save response body into a tmp file and return the instance
         if response_type == (file_type,):
+            logging.debug(f"api_client.deserialize Start: handle file downloading: {track('query'):.3f}")
             content_disposition = response.getheader("Content-Disposition")
-            return deserialize_file(response.data, self.configuration, content_disposition=content_disposition)
+            res = deserialize_file(response.data, self.configuration, content_disposition=content_disposition)
+            logging.debug(f"api_client.deserialize Finish: handle file downloading: {track('query'):.3f}")
+            return res
 
         # fetch data from response object
         try:
+            logging.debug(f"api_client.deserialize Start: fetch data from response object: {track('query'):.3f}")
             received_data = json.loads(response.data)
+            logging.debug(f"api_client.deserialize Finish: fetch data from response object: {track('query'):.3f}")
         except ValueError:
             received_data = response.data
 
         # store our data under the key of 'received_data' so users have some
         # context if they are deserializing a string and the data type is wrong
+        logging.debug(f"api_client.deserialize Start: validate_and_convert_types: {track('query'):.3f}")
         deserialized_data = validate_and_convert_types(
             received_data, response_type, ["received_data"], True, _check_type, configuration=self.configuration
         )
+        logging.debug(f"api_client.deserialize Finish: validate_and_convert_types: {track('query'):.3f}")
         return deserialized_data
 
     def call_api(

pinecone/core/client/model_utils.py

@@ -7,8 +7,6 @@
     Contact: [email protected]
     Generated by: https://openapi-generator.tech
 """
-
-
 from datetime import date, datetime  # noqa: F401
 import inspect
 import io

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]