microsoft / PubSec-Info-Assistant

Information Assistant, built with Azure OpenAI Service, Industry Accelerator
MIT License
263 stars 519 forks source link

Very slow performance to process PDF and Word files #776

Closed rmettupalli closed 23 hours ago

rmettupalli commented 3 days ago

We are experiencing very slow performance to process word and PDF files. It is taking more than 1 hour to complete single word or pdf file with pages ranging from 10 to 50 pages. I have checked our app service plan, pricing tier for Search Service, Doc Intelligence and Multi AI account. All of them are standard tier. Looking for any guidance or help to resolve this issue.

Looking at this cosmosdb statuscontainer, you can clearly see it takes almost 1 hour to complete.

{ "id": "dXBsb2FkL0F6dXJlQmF0Y2gvRFJBRlQgQ29uZmlndXJpbmcgQ0kgJiBDRCBmb3IgQXp1cmUgQmF0Y2ggaW4gQXp1cmUgRGV2T3BzIG9yIEdpdEh1Yi5kb2N4", "file_path": "upload/AzureBatch/DRAFT Configuring CI & CD for Azure Batch in Azure DevOps or GitHub.docx", "file_name": "DRAFT Configuring CI & CD for Azure Batch in Azure DevOps or GitHub.docx", "state": "Complete", "start_timestamp": "2024-06-25 19:19:40", "state_description": "", "state_timestamp": "2024-06-25 20:16:55", "status_updates": [ { "status": "File uploaded from browser to Azure Blob Storage", "status_timestamp": "2024-06-25 19:19:40", "status_classification": "Info" }, { "status": "Pipeline triggered by Blob Upload", "status_timestamp": "2024-06-25 19:19:51", "status_classification": "Info" }, { "status": "FileUploadedFunc - FileUploadedFunc function started", "status_timestamp": "2024-06-25 19:19:51", "status_classification": "Debug" }, { "status": "FileUploadedFunc - docx file sent to submit queue. Visible in 130 seconds", "status_timestamp": "2024-06-25 19:19:51", "status_classification": "Debug" }, { "status": "FileLayoutParsingOther - Starting to parse the non-PDF file", "status_timestamp": "2024-06-25 19:22:34", "status_classification": "Info" }, { "status": "FileLayoutParsingOther - Message received from non-pdf submit queue", "status_timestamp": "2024-06-25 19:22:34", "status_classification": "Debug" }, { "status": "FileLayoutParsingOther - SAS token generated to access the file", "status_timestamp": "2024-06-25 19:22:34", "status_classification": "Debug" }, { "status": "FileLayoutParsingOther - partitioning complete", "status_timestamp": "2024-06-25 19:22:35", "status_classification": "Debug" }, { "status": "FileLayoutParsingOther - chunking complete. 17 chunks created", "status_timestamp": "2024-06-25 19:22:35", "status_classification": "Debug" }, { "status": "FileLayoutParsingOther - chunking stored.", "status_timestamp": "2024-06-25 19:22:36", "status_classification": "Debug" }, { "status": "FileLayoutParsingOther - message sent to enrichment queue", "status_timestamp": "2024-06-25 19:22:36", "status_classification": "Debug" }, { "status": "TextEnrichment - Received message from text-enrichment-queue ", "status_timestamp": "2024-06-25 19:37:38", "status_classification": "Debug" }, { "status": "Ravi - beore headers detect language", "status_timestamp": "2024-06-25 19:37:38", "status_classification": "Debug" }, { "status": "Ravi - Response Status code - 401", "status_timestamp": "2024-06-25 19:37:39", "status_classification": "Debug" }, { "status": "TextEnrichment - Text enrichment is complete", "status_timestamp": "2024-06-25 20:14:48", "status_classification": "Debug" }, { "status": "Embeddings process started with model azure-openai_text-embedding-ada-002", "status_timestamp": "2024-06-25 20:16:50", "status_classification": "Info" }, { "status": "Embeddings process complete", "status_timestamp": "2024-06-25 20:16:55", "status_classification": "Info" } ], "_rid": "1lVRAMYXcZAOAAAAAAAAAA==", "_self": "dbs/1lVRAA==/colls/1lVRAMYXcZA=/docs/1lVRAMYXcZAOAAAAAAAAAA==/", "_etag": "\"0e003d91-0000-0100-0000-667b25b70000\"", "_attachments": "attachments/", "_ts": 1719346615 }

We have deployed Info-Assistant manually using step by step approach manually. Please let me know if I am missing anything to verify.

Ravindra

rmettupalli commented 3 days ago

It is taking almost three minutes to process one chunk file:

2024-06-25T21:28:17Z [Information] Request URL: 'https://edavdeviasadoc.blob.core.windows.net/content/AzureBatch/EDAV%20Azure%20Batch%20-%20Customer%20Manual%20Guide.docx/EDAV%20Azure%20Batch%20-%20Customer%20Manual%20Guide-23.json' Request method: 'PUT' Request headers: 'Content-Length': '1098' 'x-ms-blob-type': 'REDACTED' 'x-ms-version': 'REDACTED' 'Content-Type': 'application/octet-stream' 'Accept': 'application/xml' 'User-Agent': 'azsdk-python-storage-blob/12.16.0 Python/3.11.9 (Linux-5.15.153.1-2.cm2-x86_64-with-glibc2.31)' 'x-ms-date': 'REDACTED' 'x-ms-client-request-id': 'd5f92382-3339-11ef-8688-c21a2cb949bc' 'Authorization': 'REDACTED' A body is sent with the request 2024-06-25T21:28:17Z [Information] Response status: 201 Response headers: 'Content-Length': '0' 'Content-MD5': 'REDACTED' 'Last-Modified': 'Tue, 25 Jun 2024 21:28:16 GMT' 'ETag': '"0x8DC955DBA2E8555"' 'Server': 'Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0' 'x-ms-request-id': 'ccd90fc0-c01e-003e-6c46-c760c1000000' 'x-ms-client-request-id': 'd5f92382-3339-11ef-8688-c21a2cb949bc' 'x-ms-version': 'REDACTED' 'x-ms-content-crc64': 'REDACTED' 'x-ms-request-server-encrypted': 'REDACTED' 'Date': 'Tue, 25 Jun 2024 21:28:16 GMT' 2024-06-25T21:28:17Z [Information] Path and SAS token for file in azure storage are now generated 2024-06-25T21:28:18Z [Information] Request URL: 'https://edavdeviasadoc.blob.core.windows.net/content/AzureBatch/EDAV%20Access%20Chart%20and%20Personas%20Customer%20Guide.docx/EDAV%20Access%20Chart%20and%20Personas%20Customer%20Guide-19.json' Request method: 'PUT' Request headers: 'Content-Length': '6592' 'x-ms-blob-type': 'REDACTED' 'x-ms-version': 'REDACTED' 'Content-Type': 'application/octet-stream' 'Accept': 'application/xml' 'User-Agent': 'azsdk-python-storage-blob/12.16.0 Python/3.11.9 (Linux-5.15.153.1-2.cm2-x86_64-with-glibc2.31)' 'x-ms-date': 'REDACTED' 'x-ms-client-request-id': 'd6fd5a14-3339-11ef-9cdb-c21a2cb949bc' 'Authorization': 'REDACTED' A body is sent with the request 2024-06-25T21:28:19Z [Information] Path and SAS token for file in azure storage are now generated 2024-06-25T21:28:19Z [Information] Response status: 201 Response headers: 'Content-Length': '0' 'Content-MD5': 'REDACTED' 'Last-Modified': 'Tue, 25 Jun 2024 21:28:18 GMT' 'ETag': '"0x8DC955DBB3B3AF5"' 'Server': 'Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0' 'x-ms-request-id': '075cf635-401e-001f-0346-c744ba000000' 'x-ms-client-request-id': 'd6fd5a14-3339-11ef-9cdb-c21a2cb949bc' 'x-ms-version': 'REDACTED' 'x-ms-content-crc64': 'REDACTED' 'x-ms-request-server-encrypted': 'REDACTED' 'Date': 'Tue, 25 Jun 2024 21:28:18 GMT'

dayland commented 1 day ago

A significant portion of the time appears to be sitting in queues...

{ "status": "FileLayoutParsingOther - message sent to enrichment queue", "status_timestamp": "2024-06-25 19:22:36", "status_classification": "Debug" }, { "status": "TextEnrichment - Received message from text-enrichment-queue ", "status_timestamp": "2024-06-25 19:37:38", "status_classification": "Debug" },

The system is configured with a minimum number of instances in the App Service Plan with a scale out configuration. The time to scale can vary so if you have uploaded many files at the same time the queues will grow in depth and take time to clear out.

You are welcome to increase the SKUs, increase the number of instances, etc. But you will need to performance test and validate scaling as part of these updates.

rmettupalli commented 23 hours ago

Hello team, We resolved the issue. The issues was related to our private endpoints on Multi AI Service Account. We had two DNS entries pointing to same privatelink and when a call made from text enrichment function app, it was a hit and miss. Whenever retry pinged correct endpoint, it was going thru and other times it was getting rejected. After removing invalid DNS entry, it resolved the issue and started working as expected. Thanks for your response.