Logging with times for resource acquisition, flush and merge

Author: ldematte

x-pack/plugin/gpu/src/main/java/org/elasticsearch/xpack/gpu/codec/CuVSResourceManager.java

@@ -130,6 +130,7 @@ private int numLockedResources() {
         @Override
         public ManagedCuVSResources acquire(int numVectors, int dims, CuVSMatrix.DataType dataType) throws InterruptedException {
             try {
+                var started = System.nanoTime();
                 lock.lock();
 
                 boolean allConditionsMet = false;
@@ -181,6 +182,8 @@ public ManagedCuVSResources acquire(int numVectors, int dims, CuVSMatrix.DataTyp
                         enoughResourcesCondition.await();
                     }
                 }
+                var elapsed = started - System.nanoTime();
+                logger.debug("Resource acquired in [{}ms]", elapsed / 1e-6);
                 res.locked = true;
                 return res;
             } finally {

x-pack/plugin/gpu/src/main/java/org/elasticsearch/xpack/gpu/codec/ES92GpuHnswVectorsWriter.java

@@ -162,17 +162,21 @@ public KnnFieldVectorsWriter<?> addField(FieldInfo fieldInfo) throws IOException
     @Override
     // TODO: fix sorted index case
     public void flush(int maxDoc, Sorter.DocMap sortMap) throws IOException {
+        var started = System.nanoTime();
         flatVectorWriter.flush(maxDoc, sortMap);
         try {
             flushFieldsWithoutMemoryMappedFile(sortMap);
         } catch (Throwable t) {
             throw new IOException("Failed to flush GPU index: ", t);
         }
+        var elapsed = started - System.nanoTime();
+        logger.debug("Flush total time [{}ms]", elapsed / 1e-6);
     }
 
     private void flushFieldsWithoutMemoryMappedFile(Sorter.DocMap sortMap) throws IOException, InterruptedException {
         // No tmp file written, or the file cannot be mmapped
         for (FieldWriter field : fields) {
+            var started = System.nanoTime();
             var fieldInfo = field.fieldInfo;
 
             var numVectors = field.flatFieldVectorsWriter.getVectors().size();
@@ -205,6 +209,8 @@ private void flushFieldsWithoutMemoryMappedFile(Sorter.DocMap sortMap) throws IO
                     cuVSResourceManager.release(cuVSResources);
                 }
             }
+            var elapsed = started - System.nanoTime();
+            logger.debug("Flushed [{}] vectors in [{}ms]", numVectors, elapsed / 1e-6);
         }
     }
 
@@ -447,6 +453,7 @@ private static void deleteFilesIgnoringExceptions(Directory dir, String fileName
     @Override
     // fix sorted index case
     public void mergeOneField(FieldInfo fieldInfo, MergeState mergeState) throws IOException {
+        var started = System.nanoTime();
         flatVectorWriter.mergeOneField(fieldInfo, mergeState);
         final int numVectors;
         String tempRawVectorsFileName = null;
@@ -526,6 +533,8 @@ public void mergeOneField(FieldInfo fieldInfo, MergeState mergeState) throws IOE
         } finally {
             deleteFilesIgnoringExceptions(mergeState.segmentInfo.dir, tempRawVectorsFileName);
         }
+        var elapsed = started - System.nanoTime();
+        logger.debug("Merged [{}] vectors in [{}ms]", numVectors, elapsed / 1e-6);
     }
 
     private ByteVectorValues getMergedByteVectorValues(FieldInfo fieldInfo, MergeState mergeState) throws IOException {