EF-274: Increase vector waiting timeout and add log that we are waiting (#254)

Author: ajcvickers

src/MongoDB.EntityFrameworkCore/Diagnostics/MongoEventId.cs

@@ -49,6 +49,7 @@ private enum Id
         ColumnAttributeWithTypeUsed,
         VectorSearchNeedsIndex,
         VectorSearchReturnedZeroResults,
+        WaitingForVectorIndex,
     }
 
     private static EventId MakeDatabaseCommandId(Id id)
@@ -213,4 +214,16 @@ private static EventId MakeQueryId(Id id)
     ///     <para>This event uses the <see cref="PropertyAndIndexNameEventData" /> payload when used with a <see cref="DiagnosticSource" />.</para>
     /// </remarks>
     public static readonly EventId VectorSearchReturnedZeroResults = MakeQueryId(Id.VectorSearchReturnedZeroResults);
+
+    private static EventId MakeDatabaseId(Id id)
+        => new((int)id, DbLoggerCategory.Database.Name + "." + id);
+
+    /// <summary>
+    /// EF Core is waiting for vector indexes to be ready.
+    /// </summary>
+    /// <remarks>
+    ///     <para>This event is in the <see cref="DbLoggerCategory.Database" /> category.</para>
+    ///     <para>This event uses the <see cref="TimeSpanEventData" /> payload when used with a <see cref="DiagnosticSource" />.</para>
+    /// </remarks>
+    public static readonly EventId WaitingForVectorIndex = MakeDatabaseId(Id.WaitingForVectorIndex);
 }

src/MongoDB.EntityFrameworkCore/Diagnostics/MongoLoggerExtensions.cs

@@ -14,6 +14,7 @@
  */
 
 using System;
+using System.Globalization;
 using System.Linq;
 using Microsoft.EntityFrameworkCore;
 using Microsoft.EntityFrameworkCore.Diagnostics;
@@ -373,4 +374,54 @@ private static EventDefinition<string, string, string> LogVectorSearchReturnedZe
         "Consider disabling index creation in 'DbContext.Database.EnsureCreated' and performing initial ingestion " +
         "of embeddings, before calling 'DbContext.Database.CreateMissingVectorIndexes' and " +
         "'DbContext.Database.WaitForVectorIndexes'.";
+
+
+
+    public static void WaitingForVectorIndex(
+        this IDiagnosticsLogger<DbLoggerCategory.Database> diagnostics,
+        TimeSpan remainingBeforeTimeout)
+    {
+        var definition = LogWaitingForVectorIndex(diagnostics);
+
+        if (diagnostics.ShouldLog(definition))
+        {
+            definition.Log(diagnostics, remainingBeforeTimeout.TotalSeconds.ToString(CultureInfo.InvariantCulture));
+        }
+
+        if (diagnostics.NeedsEventData(definition, out var diagnosticSourceEnabled, out var simpleLogEnabled))
+        {
+            var eventData = new TimeSpanEventData(
+                definition,
+                (d, p) => ((EventDefinition<string>)d).GenerateMessage(
+                    ((TimeSpanEventData)p).TimeSpan.TotalSeconds.ToString(CultureInfo.InvariantCulture)),
+                    remainingBeforeTimeout);
+            diagnostics.DispatchEventData(definition, eventData, diagnosticSourceEnabled, simpleLogEnabled);
+        }
+    }
+
+    private static EventDefinition<string> LogWaitingForVectorIndex(IDiagnosticsLogger logger)
+    {
+        var definition = ((MongoLoggingDefinitions)logger.Definitions).LogWaitingForVectorIndex;
+        if (definition == null)
+        {
+            definition = NonCapturingLazyInitializer.EnsureInitialized(
+                ref ((MongoLoggingDefinitions)logger.Definitions).LogWaitingForVectorIndex,
+                logger,
+                static logger => new EventDefinition<string>(
+                    logger.Options,
+                    MongoEventId.WaitingForVectorIndex,
+                    LogLevel.Information,
+                    "MongoEventId.WaitingForVectorIndex",
+                    level => LoggerMessage.Define<string>(
+                        level,
+                        MongoEventId.WaitingForVectorIndex,
+                        WaitingForVectorIndexString)));
+        }
+
+        return (EventDefinition<string>)definition;
+    }
+
+    private const string WaitingForVectorIndexString =
+        "EF Core is waiting for vector indexes to be ready. The time remaining before failing with a timeout is " +
+        "{secondsRemaining} seconds.";
 }

src/MongoDB.EntityFrameworkCore/Diagnostics/MongoLoggingDefinitions.cs

@@ -45,4 +45,6 @@ internal class MongoLoggingDefinitions : LoggingDefinitions
 
     public EventDefinitionBase? LogVectorSearchNeedsIndex;
     public EventDefinitionBase? LogVectorSearchReturnedZeroResults;
+
+    public EventDefinitionBase? LogWaitingForVectorIndex;
 }

src/MongoDB.EntityFrameworkCore/Diagnostics/TimeSpanEventData.cs

@@ -0,0 +1,49 @@
+/* Copyright 2023-present MongoDB Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+using System;
+using System.Diagnostics;
+using Microsoft.EntityFrameworkCore.Diagnostics;
+
+namespace MongoDB.EntityFrameworkCore.Diagnostics;
+
+/// <summary>
+/// A <see cref="DiagnosticSource" /> event payload class for events holding an amount of time.
+/// </summary>
+/// <remarks>
+/// See <see href="https://aka.ms/efcore-docs-diagnostics">Logging, events, and diagnostics</see> for more information and examples.
+/// </remarks>
+public class TimeSpanEventData : EventData
+{
+    /// <summary>
+    /// Constructs the event payload.
+    /// </summary>
+    /// <param name="eventDefinition">The event definition.</param>
+    /// <param name="messageGenerator">A delegate that generates a log message for this event.</param>
+    /// <param name="timeSpan">The amount of time.</param>
+    public TimeSpanEventData(
+        EventDefinitionBase eventDefinition,
+        Func<EventDefinitionBase, EventData, string> messageGenerator,
+        TimeSpan timeSpan)
+        : base(eventDefinition, messageGenerator)
+    {
+        TimeSpan = timeSpan;
+    }
+
+    /// <summary>
+    /// The amount of time.
+    /// </summary>
+    public virtual TimeSpan TimeSpan { get; }
+}

src/MongoDB.EntityFrameworkCore/Extensions/MongoDatabaseFacadeExtensions.cs

@@ -101,7 +101,7 @@ public static Task CreateMissingVectorIndexesAsync(this DatabaseFacade databaseF
     /// </summary>
     /// <param name="databaseFacade">The <see cref="DatabaseFacade"/> from the EF Core <see cref="Microsoft.EntityFrameworkCore.DbContext"/>.</param>
     /// <param name="timeout">The minimum amount of time to wait for all indexes to be 'READY' before aborting.
-    /// The default is 15 seconds. Zero seconds means no timeout.</param>
+    /// The default is 60 seconds. Zero seconds means no timeout.</param>
     /// <exception cref="InvalidOperationException">if the timeout expires before all indexes are 'READY'.</exception>
     public static void WaitForVectorIndexes(this DatabaseFacade databaseFacade, TimeSpan? timeout = null)
         => GetDatabaseCreator(databaseFacade).WaitForVectorIndexes(timeout);
@@ -111,7 +111,7 @@ public static void WaitForVectorIndexes(this DatabaseFacade databaseFacade, Time
     /// </summary>
     /// <param name="databaseFacade">The <see cref="DatabaseFacade"/> from the EF Core <see cref="Microsoft.EntityFrameworkCore.DbContext"/>.</param>
     /// <param name="timeout">The minimum amount of time to wait for all indexes to be 'READY' before aborting.
-    /// The default is 15 seconds. Zero seconds means no timeout.</param>
+    /// The default is 60 seconds. Zero seconds means no timeout.</param>
     /// <param name="cancellationToken">A <see cref="CancellationToken"/> that can be used to cancel this asynchronous request.</param>
     /// <returns>A <see cref="Task"/> to track this async operation.</returns>
     /// <exception cref="InvalidOperationException">if the timeout expires before all indexes are 'READY'.</exception>

src/MongoDB.EntityFrameworkCore/Metadata/MongoDatabaseCreationOptions.cs

@@ -27,7 +27,7 @@ namespace MongoDB.EntityFrameworkCore.Metadata;
 /// <param name="CreateMissingVectorIndexes">Creates any MongoDB Atlas vector indexes that do not already exist. The default is true.</param>
 /// <param name="WaitForVectorIndexes">Waits all MongoDB Atlas vector indexes to be 'READY' before continuing. The default is true.</param>
 /// <param name="IndexCreationTimeout">The minimum amount of time to wait for all indexes to be 'READY' before aborting.
-/// The default is 15 seconds. Zero seconds means no timeout.</param>
+/// The default is 60 seconds. Zero seconds means no timeout.</param>
 public readonly record struct MongoDatabaseCreationOptions(
     bool CreateMissingCollections = true,
     bool CreateMissingIndexes = true,

src/MongoDB.EntityFrameworkCore/Storage/IMongoDatabaseCreator.cs

@@ -107,15 +107,15 @@ public interface IMongoDatabaseCreator : IDatabaseCreator
     /// Blocks until all vector indexes in the mapped collections are reporting the 'READY' state.
     /// </summary>
     /// <param name="timeout">The minimum amount of time to wait for all indexes to be 'READY' before aborting.
-    /// The default is 15 seconds. Zero seconds means no timeout.</param>
+    /// The default is 60 seconds. Zero seconds means no timeout.</param>
     /// <exception cref="InvalidOperationException">if the timeout expires before all indexes are 'READY'.</exception>
     void WaitForVectorIndexes(TimeSpan? timeout = null);
 
     /// <summary>
     /// Blocks until all vector indexes in the mapped collections are reporting the 'READY' state.
     /// </summary>
     /// <param name="timeout">The minimum amount of time to wait for all indexes to be 'READY' before aborting.
-    /// The default is 15 seconds. Zero seconds means no timeout.</param>
+    /// The default is 60 seconds. Zero seconds means no timeout.</param>
     /// <param name="cancellationToken">A <see cref="CancellationToken"/> that can be used to cancel this asynchronous request.</param>
     /// <returns>A <see cref="Task"/> to track this async operation.</returns>
     /// <exception cref="InvalidOperationException">if the timeout expires before all indexes are 'READY'.</exception>

src/MongoDB.EntityFrameworkCore/Storage/MongoDatabaseCreator.cs

@@ -20,12 +20,14 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.EntityFrameworkCore;
+using Microsoft.EntityFrameworkCore.Diagnostics;
 using Microsoft.EntityFrameworkCore.Metadata;
 using Microsoft.EntityFrameworkCore.Metadata.Internal;
 using Microsoft.EntityFrameworkCore.Storage;
 using Microsoft.EntityFrameworkCore.Update;
 using MongoDB.Bson;
 using MongoDB.Driver;
+using MongoDB.EntityFrameworkCore.Diagnostics;
 using MongoDB.EntityFrameworkCore.Extensions;
 using MongoDB.EntityFrameworkCore.Metadata;
 
@@ -41,7 +43,8 @@ public class MongoDatabaseCreator(
     IMongoClientWrapper clientWrapper,
     IDesignTimeModel designTimeModel,
     IUpdateAdapterFactory updateAdapterFactory,
-    IDatabase database)
+    IDatabase database,
+    IDiagnosticsLogger<DbLoggerCategory.Database> logger)
     : IMongoDatabaseCreator
 {
     private bool _useDatabaseNameFilter = true;
@@ -376,8 +379,11 @@ public void WaitForVectorIndexes(TimeSpan? timeout = null)
                             $"Failed to build the vector index '{indexModel["name"]}' for path '{indexModel["latestDefinition"]["fields"][0]["path"]}'.");
                     }
 
-                    if (status != "READY")
+                    var remainingBeforeTimeout = failAfter - DateTime.UtcNow;
+                    if (status != "READY" && remainingBeforeTimeout > TimeSpan.Zero)
                     {
+                        logger.WaitingForVectorIndex(remainingBeforeTimeout);
+
                         isReady = false;
                         Thread.Sleep(delay *= 2);
                         break;
@@ -395,11 +401,10 @@ public void WaitForVectorIndexes(TimeSpan? timeout = null)
 
     private static DateTimeOffset CalculateTimeoutDateTime(TimeSpan? timeout)
     {
-        timeout ??= TimeSpan.FromSeconds(15);
-        var failAfter = timeout.Value == TimeSpan.Zero
+        timeout ??= TimeSpan.FromSeconds(60);
+        return timeout.Value == TimeSpan.Zero
             ? DateTime.MaxValue
-            : DateTimeOffset.UtcNow.Add(timeout.Value);
-        return failAfter;
+            : DateTime.UtcNow.Add(timeout.Value);
     }
 
     /// <inheritdoc />
@@ -508,8 +513,11 @@ public async Task WaitForVectorIndexesAsync(TimeSpan? timeout = null, Cancellati
                             $"Failed to build the vector index '{indexModel["name"]}' for path '{indexModel["latestDefinition"]["fields"][0]["path"]}'.");
                     }
 
-                    if (status != "READY")
+                    var remainingBeforeTimeout = failAfter - DateTime.UtcNow;
+                    if (status != "READY" && remainingBeforeTimeout > TimeSpan.Zero)
                     {
+                        logger.WaitingForVectorIndex(remainingBeforeTimeout);
+
                         isReady = false;
                         await Task.Delay(delay *= 2, cancellationToken).ConfigureAwait(false);
                         break;

tests/MongoDB.EntityFrameworkCore.FunctionalTests/Storage/IndexTests.cs

@@ -114,8 +114,8 @@ public async Task Create_vector_index_after_EnsureCreated(bool async)
 
             Assert.Equal(0, GetVectorIndexCount(collection));
 
-            await db.Database.CreateMissingVectorIndexesAsync();
-            await db.Database.WaitForVectorIndexesAsync();
+            db.Database.CreateMissingVectorIndexes();
+            db.Database.WaitForVectorIndexes();
         }
 
         ValidateIndex("FloatsVectorIndex", collection, "Floats", 2, "cosine", expectedFilterPaths: null);
@@ -189,8 +189,8 @@ public async Task Create_vector_index_on_nested_entity_after_EnsureCreated(bool
 
             Assert.Equal(0, GetVectorIndexCount(collection));
 
-            await db.Database.CreateMissingVectorIndexesAsync();
-            await db.Database.WaitForVectorIndexesAsync();
+            db.Database.CreateMissingVectorIndexes();
+            db.Database.WaitForVectorIndexes();
         }
 
         ValidateIndex("DoublesVectorIndex", collection, "Nested.Nested.Doubles", 2, "cosine", expectedFilterPaths: null);