diff --git a/pinecone/core/client/api_client.py b/pinecone/core/client/api_client.py index 8084c5321..16a149e32 100644 --- a/pinecone/core/client/api_client.py +++ b/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,8 +208,10 @@ 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") @@ -213,11 +219,14 @@ def __call_api( 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( diff --git a/pinecone/core/client/model_utils.py b/pinecone/core/client/model_utils.py index 73dc385d5..686864b78 100644 --- a/pinecone/core/client/model_utils.py +++ b/pinecone/core/client/model_utils.py @@ -7,8 +7,6 @@ Contact: support@pinecone.io Generated by: https://openapi-generator.tech """ - - from datetime import date, datetime # noqa: F401 import inspect import io diff --git a/pinecone/core/client/rest.py b/pinecone/core/client/rest.py index b986712be..f7485d1ec 100644 --- a/pinecone/core/client/rest.py +++ b/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: diff --git a/pinecone/index.py b/pinecone/index.py index 64d66d676..5d464dca4 100644 --- a/pinecone/index.py +++ b/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( diff --git a/pinecone/stopwatch.py b/pinecone/stopwatch.py new file mode 100644 index 000000000..f38307629 --- /dev/null +++ b/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]