(jackrabbit-oak) branch trunk updated: OAK-11606 - indexing-job: throttle messages warning about enqueuing delays in IndexWriterPool

[nfsantos]

This is an automated email from the ASF dual-hosted git repository.

nfsantos pushed a commit to branch trunk
in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git


The following commit(s) were added to refs/heads/trunk by this push:
     new 32d11a8dfa OAK-11606 - indexing-job: throttle messages warning about 
enqueuing delays in IndexWriterPool
32d11a8dfa is described below

commit 32d11a8dfa4e506c08d1fd311acec9411a90ff58
Author: Nuno Santos <nsan...@adobe.com>
AuthorDate: Wed Mar 19 11:33:08 2025 +0100

    OAK-11606 - indexing-job: throttle messages warning about enqueuing delays 
in IndexWriterPool
---
 .../plugins/index/lucene/writer/IndexWriterPool.java   | 18 ++++++++++++------
 1 file changed, 12 insertions(+), 6 deletions(-)

diff --git 
a/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/writer/IndexWriterPool.java
 
b/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/writer/IndexWriterPool.java
index a9d9104c5a..052b33b819 100644
--- 
a/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/writer/IndexWriterPool.java
+++ 
b/oak-lucene/src/main/java/org/apache/jackrabbit/oak/plugins/index/lucene/writer/IndexWriterPool.java
@@ -84,6 +84,7 @@ public class IndexWriterPool {
     private long updateCount = 0;
     private long deleteCount = 0;
     private long totalEnqueueTimeNanos = 0;
+    private long enqueuingDelayMessageLastLoggedMillis = 0;
 
     private static class OperationBatch {
         final long sequenceNumber;
@@ -379,14 +380,19 @@ public class IndexWriterPool {
             if (seqNumber % 1000 == 0) {
                 LOG.info("Enqueuing batch {}, size: {}", seqNumber, 
batch.size());
             }
-            long start = System.nanoTime();
+            long enqueuingStartNanos = System.nanoTime();
             queue.put(new OperationBatch(seqNumber, batch.toArray(new 
Operation[0])));
-            long durationNanos = System.nanoTime() - start;
-            long durationMillis = durationNanos / 1_000_000;
+            long enqueuingEndNanos = System.nanoTime();
+            long durationNanos = enqueuingEndNanos - enqueuingStartNanos;
             totalEnqueueTimeNanos += durationNanos;
-            if (durationMillis > 1) {
-                LOG.info("Enqueuing batch delayed. Seq number: {}, size: {}. 
Delay: {} ms",
-                        seqNumber, batch.size(), durationMillis);
+            long durationMillis = durationNanos / 1_000_000;
+            if (durationMillis > 10) {
+                long currentTimeMillis = enqueuingEndNanos / 1_000_000;
+                if (currentTimeMillis - enqueuingDelayMessageLastLoggedMillis 
> TimeUnit.SECONDS.toMillis(10)) {
+                    LOG.info("Enqueuing batch delayed. Seq number: {}, size: 
{}. Delay: {} ms (These messages are logged every 10 seconds)",
+                            seqNumber, batch.size(), durationMillis);
+                    enqueuingDelayMessageLastLoggedMillis = currentTimeMillis;
+                }
             }
             batch.clear();
             return seqNumber;