From 4a74992cd327b0a7ac75097677d829dd09f18b41 Mon Sep 17 00:00:00 2001 From: root Date: Wed, 1 Sep 2010 17:34:08 -0700 Subject: [PATCH] Added TRACE level logging for Global capacityCheckerLocks in UserConcentratedAllocator, AlertManagerImpl and StatsCollector. --- .../allocator/impl/UserConcentratedAllocator.java | 8 ++++++++ server/src/com/cloud/alert/AlertManagerImpl.java | 14 +++++++++++--- server/src/com/cloud/server/StatsCollector.java | 12 ++++++++++-- 3 files changed, 29 insertions(+), 5 deletions(-) diff --git a/server/src/com/cloud/agent/manager/allocator/impl/UserConcentratedAllocator.java b/server/src/com/cloud/agent/manager/allocator/impl/UserConcentratedAllocator.java index 3e068adc21e..2ceac8a3392 100755 --- a/server/src/com/cloud/agent/manager/allocator/impl/UserConcentratedAllocator.java +++ b/server/src/com/cloud/agent/manager/allocator/impl/UserConcentratedAllocator.java @@ -155,7 +155,9 @@ public class UserConcentratedAllocator implements PodAllocator { private boolean dataCenterAndPodHasEnoughCapacity(long dataCenterId, long podId, long capacityNeeded, short capacityType, long[] hostCandidate) { List capacities = null; + long start = System.currentTimeMillis(); if (m_capacityCheckLock.lock(120)) { // 2 minutes + long lockTime = System.currentTimeMillis(); try { SearchCriteria sc = _capacityDao.createSearchCriteria(); sc.addAnd("capacityType", SearchCriteria.Op.EQ, capacityType); @@ -164,9 +166,15 @@ public class UserConcentratedAllocator implements PodAllocator { capacities = _capacityDao.search(sc, null); } finally { m_capacityCheckLock.unlock(); + long end = System.currentTimeMillis(); + if (s_logger.isTraceEnabled()) + s_logger.trace("CapacityCheckLock was held for " + (end - lockTime) + " ms; lock was acquired in " + (lockTime - start) + " ms"); } } else { s_logger.error("Unable to acquire synchronization lock for pod allocation"); + long end = System.currentTimeMillis(); + if (s_logger.isTraceEnabled()) + s_logger.trace("CapacityCheckerLock got timed out after " + (end - start) + " ms"); // we now try to enforce reservation-style allocation, waiting time has been adjusted // to 2 minutes diff --git a/server/src/com/cloud/alert/AlertManagerImpl.java b/server/src/com/cloud/alert/AlertManagerImpl.java index eed0586ee99..80391e313dd 100644 --- a/server/src/com/cloud/alert/AlertManagerImpl.java +++ b/server/src/com/cloud/alert/AlertManagerImpl.java @@ -443,8 +443,10 @@ public class AlertManagerImpl implements AlertManager { newCapacities.add(newPrivateIPCapacity); // _capacityDao.persist(newPrivateIPCapacity); } - + + long start = System.currentTimeMillis(); if (m_capacityCheckLock.lock(5)) { // 5 second timeout + long lockTime = System.currentTimeMillis(); try { // delete the old records _capacityDao.clearNonStorageCapacities(); @@ -453,7 +455,10 @@ public class AlertManagerImpl implements AlertManager { _capacityDao.persist(newCapacity); } } finally { - m_capacityCheckLock.unlock(); + m_capacityCheckLock.unlock(); + long end = System.currentTimeMillis(); + if (s_logger.isTraceEnabled()) + s_logger.trace("CapacityCheckLock was held for " + (end - lockTime) + " ms; lock was acquired in " + (lockTime - start) + " ms"); } if (s_logger.isTraceEnabled()) { @@ -462,7 +467,10 @@ public class AlertManagerImpl implements AlertManager { } else { if (s_logger.isTraceEnabled()) { s_logger.trace("Skipping capacity check, unable to lock the capacity table for recalculation."); - } + } + long end = System.currentTimeMillis(); + if (s_logger.isTraceEnabled()) + s_logger.trace("CapacityCheckerLock got timed out after " + (end - start) + " ms"); } } diff --git a/server/src/com/cloud/server/StatsCollector.java b/server/src/com/cloud/server/StatsCollector.java index 37aee1384ad..5242bb82a45 100644 --- a/server/src/com/cloud/server/StatsCollector.java +++ b/server/src/com/cloud/server/StatsCollector.java @@ -337,8 +337,10 @@ public class StatsCollector { newCapacities.add(capacity); // _capacityDao.persist(capacity); } - - if (m_capacityCheckLock.lock(5)) { // 5 second timeout + + long start = System.currentTimeMillis(); + if (m_capacityCheckLock.lock(5)) { // 5 second timeout + long lockTime = System.currentTimeMillis(); if (s_logger.isTraceEnabled()) { s_logger.trace("recalculating system storage capacity"); } @@ -356,6 +358,9 @@ public class StatsCollector { } } finally { m_capacityCheckLock.unlock(); + long end = System.currentTimeMillis(); + if (s_logger.isTraceEnabled()) + s_logger.trace("CapacityCheckLock was held for " + (end - lockTime) + " ms; lock was acquired in " + (lockTime - start) + " ms"); } if (s_logger.isTraceEnabled()) { s_logger.trace("done recalculating system storage capacity"); @@ -364,6 +369,9 @@ public class StatsCollector { if (s_logger.isTraceEnabled()) { s_logger.trace("not recalculating system storage capacity, unable to lock capacity table"); } + long end = System.currentTimeMillis(); + if (s_logger.isTraceEnabled()) + s_logger.trace("CapacityCheckerLock got timed out after " + (end - start) + " ms"); } } catch (Throwable t) { s_logger.error("Error trying to retrieve storage stats", t);