Merge pull request #31 from tcncloud/fix/instance-level-lock-with-timing-logs

Fix/instance level lock with timing logs

Author: iamneal

core/src/main/java/com/tcn/exile/gateclients/v2/GateClientAbstract.java

@@ -35,7 +35,7 @@ public abstract class GateClientAbstract {
   private static final Logger log = LoggerFactory.getLogger(GateClientAbstract.class);
 
   private ManagedChannel sharedChannel;
-  private static final ReentrantLock lock = new ReentrantLock();
+  private final ReentrantLock lock = new ReentrantLock();
 
   private Config currentConfig = null;
   protected final String tenant;
@@ -160,12 +160,32 @@ private void forceShutdownSharedChannel() {
   }
 
   public ManagedChannel getChannel() throws UnconfiguredException {
+    long getChannelStartTime = System.currentTimeMillis();
     // Double-checked locking pattern for thread-safe lazy initialization
     ManagedChannel localChannel = sharedChannel;
     if (localChannel == null || localChannel.isShutdown() || localChannel.isTerminated()) {
 
-      log.debug("getChannel called, aquiring lock");
+      long beforeLockAcquisition = System.currentTimeMillis();
+      log.debug(
+          "[LOCK-TIMING] getChannel attempting to acquire lock for tenant: {} at {}ms",
+          tenant,
+          beforeLockAcquisition);
+
       lock.lock();
+
+      long afterLockAcquisition = System.currentTimeMillis();
+      long lockWaitTime = afterLockAcquisition - beforeLockAcquisition;
+      if (lockWaitTime > 100) {
+        log.warn(
+            "[LOCK-TIMING] getChannel lock acquired for tenant: {} after {}ms WAIT (potential contention!)",
+            tenant,
+            lockWaitTime);
+      } else {
+        log.debug(
+            "[LOCK-TIMING] getChannel lock acquired for tenant: {} after {}ms",
+            tenant,
+            lockWaitTime);
+      }
       try {
         // Double-check condition inside synchronized block
         localChannel = sharedChannel;
@@ -178,8 +198,25 @@ public ManagedChannel getChannel() throws UnconfiguredException {
             localChannel == null,
             shutdown,
             terminated);
+
         if (localChannel == null || localChannel.isShutdown() || localChannel.isTerminated()) {
+          long beforeCreateChannel = System.currentTimeMillis();
+          log.debug(
+              "[LOCK-TIMING] getChannel creating new channel for tenant: {} at {}ms (lock held for {}ms so far)",
+              tenant,
+              beforeCreateChannel,
+              beforeCreateChannel - afterLockAcquisition);
+
           localChannel = createNewChannel();
+
+          long afterCreateChannel = System.currentTimeMillis();
+          log.debug(
+              "[LOCK-TIMING] getChannel channel created for tenant: {} at {}ms (createNewChannel took: {}ms, lock held total: {}ms)",
+              tenant,
+              afterCreateChannel,
+              afterCreateChannel - beforeCreateChannel,
+              afterCreateChannel - afterLockAcquisition);
+
           sharedChannel = localChannel;
         }
       } catch (Exception e) {
@@ -190,7 +227,16 @@ public ManagedChannel getChannel() throws UnconfiguredException {
             e);
         throw new UnconfiguredException("Error creating new static shared gRPC channel", e);
       } finally {
+        long beforeUnlock = System.currentTimeMillis();
         lock.unlock();
+        long afterUnlock = System.currentTimeMillis();
+        long totalLockHeldTime = afterUnlock - afterLockAcquisition;
+        log.debug(
+            "[LOCK-TIMING] getChannel lock released for tenant: {} at {}ms (lock held for {}ms, total getChannel: {}ms)",
+            tenant,
+            afterUnlock,
+            totalLockHeldTime,
+            afterUnlock - getChannelStartTime);
       }
     } else {
       log.debug(