chore: remove f-strings from logs for performance reasons (#3212)

* Use the %s syntax on all debug messages

* Use the %s syntax on some more debug messages

* Use the %s syntax on info messages

* Use the %s syntax on warning messages

* Use the %s syntax on error and exception messages

* mypy

* pylint

* trogger tutorials execution in CI

* trigger tutorials execution on CI

* black

* remove embeddings from repr

* fix Document `__repr__`

* address feedback

* mypy

Author: ZanSara

haystack/document_stores/deepsetcloud.py

@@ -29,7 +29,7 @@ def wrapper(self, *args, **kwargs):
 
         args_as_kwargs = args_to_kwargs(args, func)
         parameters = {**args_as_kwargs, **kwargs}
-        logger.info(f"Input to {func.__name__}: {parameters}")
+        logger.info("Input to %s: %s", func.__name__, parameters)
 
     return wrapper
 

haystack/document_stores/elasticsearch.py

@@ -200,7 +200,7 @@ def _create_document_index(self, index_name: str, headers: Optional[Dict[str, st
         """
         # Check if index_name refers to an alias
         if self.client.indices.exists_alias(name=index_name):
-            logger.debug(f"Index name {index_name} is an alias.")
+            logger.debug("Index name %s is an alias.", index_name)
 
         # check if the existing index has the embedding field; if not create it
         if self.client.indices.exists(index=index_name, headers=headers):
@@ -949,7 +949,7 @@ def query(
             all_terms_must_match=all_terms_must_match,
         )
 
-        logger.debug(f"Retriever query: {body}")
+        logger.debug("Retriever query: %s", body)
         result = self.client.search(index=index, body=body, headers=headers)["hits"]["hits"]
 
         documents = [
@@ -1086,7 +1086,7 @@ def query_batch(
             body.append(headers)
             body.append(cur_query_body)
 
-        logger.debug(f"Retriever query: {body}")
+        logger.debug("Retriever query: %s", body)
         responses = self.client.msearch(index=index, body=body)
 
         all_documents = []
@@ -1287,7 +1287,7 @@ def query_by_embedding(
         if excluded_meta_data:
             body["_source"] = {"excludes": excluded_meta_data}
 
-        logger.debug(f"Retriever query: {body}")
+        logger.debug("Retriever query: %s", body)
         try:
             result = self.client.search(index=index, body=body, request_timeout=300, headers=headers)["hits"]["hits"]
             if len(result) == 0:
@@ -1458,12 +1458,16 @@ def update_embeddings(
 
         if update_existing_embeddings:
             document_count = self.get_document_count(index=index, headers=headers)
-            logger.info(f"Updating embeddings for all {document_count} docs ...")
         else:
             document_count = self.get_document_count(
                 index=index, filters=filters, only_documents_without_embedding=True, headers=headers
             )
-            logger.info(f"Updating embeddings for {document_count} docs without embeddings ...")
+
+        logger.info(
+            "Updating embeddings for all %s docs %s...",
+            document_count,
+            "without embeddings" if not update_existing_embeddings else "",
+        )
 
         result = self._get_all_documents_in_index(
             index=index,
@@ -1674,7 +1678,7 @@ def delete_index(self, index: str):
     def _delete_index(self, index: str):
         if self.client.indices.exists(index):
             self.client.indices.delete(index=index, ignore=[400, 404])
-            logger.info(f"Index '{index}' deleted.")
+            logger.info("Index '%s' deleted.", index)
 
 
 class ElasticsearchDocumentStore(BaseElasticsearchDocumentStore):

haystack/document_stores/faiss.py

@@ -346,7 +346,7 @@ def update_embeddings(
             logger.warning("Calling DocumentStore.update_embeddings() on an empty index")
             return
 
-        logger.info(f"Updating embeddings for {document_count} docs...")
+        logger.info("Updating embeddings for %s docs...", document_count)
         vector_id = sum(index.ntotal for index in self.faiss_indexes.values())
 
         result = self._query(
@@ -568,7 +568,7 @@ def delete_index(self, index: str):
             )
         if index in self.faiss_indexes:
             del self.faiss_indexes[index]
-            logger.info(f"Index '{index}' deleted.")
+            logger.info("Index '%s' deleted.", index)
         super().delete_index(index)
 
     def query_by_embedding(

haystack/document_stores/memory.py

@@ -451,11 +451,10 @@ def update_embeddings(
         result = self._query(
             index=index, filters=filters, only_documents_without_embedding=not update_existing_embeddings
         )
-        document_count = len(result)
-        logger.info(f"Updating embeddings for {document_count} docs ...")
+        logger.info("Updating embeddings for %s docs ...", len(result) if logger.level > logging.DEBUG else 0)
         batched_documents = get_batches_from_generator(result, batch_size)
         with tqdm(
-            total=document_count, disable=not self.progress_bar, position=0, unit=" docs", desc="Updating Embedding"
+            total=len(result), disable=not self.progress_bar, position=0, unit=" docs", desc="Updating Embedding"
         ) as progress_bar:
             for document_batch in batched_documents:
                 embeddings = retriever.embed_documents(document_batch)  # type: ignore
@@ -782,7 +781,7 @@ def delete_index(self, index: str):
         """
         if index in self.indexes:
             del self.indexes[index]
-            logger.info(f"Index '{index}' deleted.")
+            logger.info("Index '%s' deleted.", index)
 
     def delete_labels(
         self,

haystack/document_stores/memory_knowledgegraph.py

@@ -37,7 +37,7 @@ def create_index(self, index: Optional[str] = None):
         if index not in self.indexes:
             self.indexes[index] = Graph()
         else:
-            logger.warning(f"Index '{index}' is already present.")
+            logger.warning("Index '%s' is already present.", index)
 
     def delete_index(self, index: Optional[str] = None):
         """
@@ -49,7 +49,7 @@ def delete_index(self, index: Optional[str] = None):
 
         if index in self.indexes:
             del self.indexes[index]
-            logger.info(f"Index '{index}' deleted.")
+            logger.info("Index '%s' deleted.", index)
 
     def import_from_ttl_file(self, path: Path, index: Optional[str] = None):
         """

haystack/document_stores/milvus1.py

@@ -313,20 +313,21 @@ def update_embeddings(
         index = index or self.index
         self._create_collection_and_index_if_not_exist(index)
 
-        document_count = self.get_document_count(index=index)
-        if document_count == 0:
-            logger.warning("Calling DocumentStore.update_embeddings() on an empty index")
-            return
-
-        logger.info(f"Updating embeddings for {document_count} docs...")
-
         result = self._query(
             index=index,
             vector_ids=None,
             batch_size=batch_size,
             filters=filters,
             only_documents_without_embedding=not update_existing_embeddings,
         )
+
+        document_count = len(result)
+        if document_count == 0:
+            logger.warning("Calling DocumentStore.update_embeddings() on an empty index")
+            return
+
+        logger.info("Updating embeddings for %s docs...", document_count)
+
         batched_documents = get_batches_from_generator(result, batch_size)
         with tqdm(
             total=document_count, disable=not self.progress_bar, position=0, unit=" docs", desc="Updating Embedding"
@@ -665,10 +666,10 @@ def get_all_vectors(self, index: Optional[str] = None) -> List[np.ndarray]:
         index = index or self.index
         status, collection_info = self.milvus_server.get_collection_stats(collection_name=index)
         if not status.OK():
-            logger.info(f"Failed fetch stats from store ...")
+            logger.info("Failed fetch stats from store ...")
             return list()
 
-        logger.debug(f"collection_info = {collection_info}")
+        logger.debug("collection_info = %s", collection_info)
 
         ids = list()
         partition_list = collection_info["partitions"]
@@ -679,16 +680,16 @@ def get_all_vectors(self, index: Optional[str] = None) -> List[np.ndarray]:
                 status, id_list = self.milvus_server.list_id_in_segment(
                     collection_name=index, segment_name=segment_name
                 )
-                logger.debug(f"{status}: segment {segment_name} has {len(id_list)} vectors ...")
+                logger.debug("%s: segment %s has %s vectors ...", status, segment_name, len(id_list))
                 ids.extend(id_list)
 
         if len(ids) == 0:
-            logger.info(f"No documents in the store ...")
+            logger.info("No documents in the store ...")
             return list()
 
         status, vectors = self.milvus_server.get_entity_by_id(collection_name=index, ids=ids)
         if not status.OK():
-            logger.info(f"Failed fetch document for ids {ids} from store ...")
+            logger.info("Failed fetch document for ids %s from store ...", ids)
             return list()
 
         return vectors

haystack/document_stores/milvus2.py

@@ -204,7 +204,7 @@ def _create_collection_and_index(
 
             for field in custom_fields:
                 if field.name == self.id_field or field.name == self.embedding_field:
-                    logger.warning(f"Skipping `{field.name}` as it is similar to `id_field` or `embedding_field`")
+                    logger.warning("Skipping '%s' as it is similar to 'id_field' or 'embedding_field'", field.name)
                 else:
                     fields.append(field)
 
@@ -353,7 +353,7 @@ def update_embeddings(
             logger.warning("Calling DocumentStore.update_embeddings() on an empty index")
             return
 
-        logger.info(f"Updating embeddings for {document_count} docs...")
+        logger.info("Updating embeddings for %s docs...", document_count)
 
         result = self._query(
             index=index,
@@ -516,7 +516,7 @@ def delete_index(self, index: str):
     def _delete_index(self, index: str):
         if utility.has_collection(collection_name=index):
             utility.drop_collection(collection_name=index)
-            logger.info(f"Index '{index}' deleted.")
+            logger.info("Index '%s' deleted.", index)
         super().delete_index(index)
 
     def get_all_documents_generator(

haystack/document_stores/opensearch.py

@@ -379,7 +379,7 @@ def query_by_embedding(
         if excluded_meta_data:
             body["_source"] = {"excludes": excluded_meta_data}
 
-        logger.debug(f"Retriever query: {body}")
+        logger.debug("Retriever query: %s", body)
         result = self.client.search(index=index, body=body, request_timeout=300, headers=headers)["hits"]["hits"]
 
         documents = [
@@ -396,7 +396,7 @@ def _create_document_index(self, index_name: str, headers: Optional[Dict[str, st
         """
         # Check if index_name refers to an alias
         if self.client.indices.exists_alias(name=index_name):
-            logger.debug(f"Index name {index_name} is an alias.")
+            logger.debug("Index name %s is an alias.", index_name)
 
         # check if the existing index has the embedding field; if not create it
         if self.client.indices.exists(index=index_name, headers=headers):

haystack/document_stores/pinecone.py

@@ -216,7 +216,7 @@ def _create_index(
         stats = index_connection.describe_index_stats()
         dims = stats["dimension"]
         count = stats["namespaces"][""]["vector_count"] if stats["namespaces"].get("") else 0
-        logger.info(f"Index statistics: name: {index}, embedding dimensions: {dims}, record count: {count}")
+        logger.info("Index statistics: name: %s embedding dimensions: %s, record count: %s", index, dims, count)
         # return index connection
         return index_connection
 
@@ -471,7 +471,7 @@ def update_embeddings(
             logger.warning("Calling DocumentStore.update_embeddings() on an empty index")
             return
 
-        logger.info(f"Updating embeddings for {document_count} docs...")
+        logger.info("Updating embeddings for %s docs...", document_count)
 
         # If the embedding namespace is empty or the user does not want to update existing embeddings, we use document namespace
         if self.get_embedding_count(index=index) == 0 or not update_existing_embeddings:
@@ -1003,7 +1003,7 @@ def delete_index(self, index: str):
         index = self._index_name(index)
         if index in pinecone.list_indexes():
             pinecone.delete_index(index)
-            logger.info(f"Index '{index}' deleted.")
+            logger.info("Index '%s' deleted.", index)
         if index in self.pinecone_indexes:
             del self.pinecone_indexes[index]
         if index in self.all_ids:

haystack/document_stores/sql.py

@@ -402,7 +402,7 @@ def write_documents(
                     try:
                         meta_orms.append(MetaDocumentORM(name=key, value=value))
                     except TypeError as ex:
-                        logger.error(f"Document {doc.id} - {ex}")
+                        logger.error("Document %s - %s", doc.id, ex)
                 doc_mapping = {
                     "id": doc.id,
                     "content": doc.to_dict()["content"],
@@ -425,7 +425,7 @@ def write_documents(
             try:
                 self.session.commit()
             except Exception as ex:
-                logger.error(f"Transaction rollback: {ex.__cause__}")
+                logger.error("Transaction rollback: %s", ex.__cause__)
                 # Rollback is important here otherwise self.session will be in inconsistent state and next call will fail
                 self.session.rollback()
                 raise ex
@@ -495,7 +495,7 @@ def update_vector_ids(self, vector_id_map: Dict[str, str], index: Optional[str]
             try:
                 self.session.commit()
             except Exception as ex:
-                logger.error(f"Transaction rollback: {ex.__cause__}")
+                logger.error("Transaction rollback: %s", ex.__cause__)
                 self.session.rollback()
                 raise ex