Menu
▾
▴
[Rhq-commits] [rhq-project.org rhq] [4710] add more logging to know how long it took to lock things and how long the lock was acquired
|
From: <ma...@rh...> - 2009-08-04 03:43:32
|
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.1//EN" "http://www.w3.org/TR/xhtml11/DTD/xhtml11.dtd"> <html xmlns="http://www.w3.org/1999/xhtml"> <head><style type="text/css"><!-- #msg DL { border : 1px #006 solid; background-color : #369; padding : 6px; color : #fff; } #msg DT { float : left; width : 6em; font-weight : bold; } #msg DL, #msg DT, #msg UL, #msg LI { font-family : arial,helvetica,sans-serif; font-size : 10pt; } h3 { font-family : arial,helvetica,sans-serif; font-size : 10pt; font-weight : bold; } #msg PRE { overflow : auto; white-space : normal; background-color : #ffc; border : 1px #fc0 solid; padding : 6px; } #msg UL, PRE, .diff { overflow : auto; } #patch h4 { font-family : arial,helvetica,sans-serif; font-size : 10pt; } #patch h4 { padding: 8px; background : #369; color : #fff; margin : 0; } #patch .propset h4, #patch .binary h4 {margin: 0;} #patch pre {padding:0;line-height:1.2em;margin:0;} #patch .diff {background:#eeeeee;padding: 0 0 10px 0;} #patch .propset .diff, #patch .binary .diff {padding: 10px 0;} #patch span {display:block;padding:0 10px;} #patch .modfile, #patch .addfile, #patch .delfile, #patch .propset, #patch .binary, #patch .copfile {border:1px solid #ccc;margin:10px 0;} #patch .add {background:#ddffdd;} #patch .rem {background:#ffdddd;} #patch .lines, .info {color:#888888;background:#ffffff;} .diff { width : 100%; } #msg DL { border : 1px #006 solid; background-color : #369; padding : 6px; color : #fff; } #msg DT { float : left; width : 6em; font-weight : bold; } #msg DL, #msg DT, #msg UL, #msg LI { font-family : arial,helvetica,sans-serif; font-size : 10pt; } h3 { font-family : arial,helvetica,sans-serif; font-size : 10pt; font-weight : bold; } #msg PRE { overflow : auto; white-space : normal; background-color : #ffc; border : 1px #fc0 solid; padding : 6px; } #msg UL, PRE, .diff { overflow : auto; } #patch h4 { font-family : arial,helvetica,sans-serif; font-size : 10pt; } #patch h4 { padding: 8px; background : #369; color : #fff; margin : 0; } #patch .propset h4, #patch .binary h4 {margin: 0;} #patch pre {padding:0;line-height:1.2em;margin:0;} #patch .diff {background:#eeeeee;padding: 0 0 10px 0;} #patch .propset .diff, #patch .binary .diff {padding: 10px 0;} #patch span {display:block;padding:0 10px;} #patch .modfile, #patch .addfile, #patch .delfile, #patch .propset, #patch .binary, #patch .copfile {border:1px solid #ccc;margin:10px 0;} #patch .add {background:#ddffdd;} #patch .rem {background:#ffdddd;} #patch .lines, .info {color:#888888;background:#ffffff;} .diff { width : 100%; } --></style> <title>[rhq-project.org rhq] [4710] add more logging to know how long it took to lock things and how long the lock was acquired</title> </head> <body> <div id="msg"> <dl> <dt>Revision</dt> <dd>4710</dd> <dt>Author</dt> <dd>mazz</dd> <dt>Date</dt> <dd>2009-08-03 22:43:21 -0500 (Mon, 03 Aug 2009)</dd> </dl> <h3>Log Message</h3> <pre>add more logging to know how long it took to lock things and how long the lock was acquired</pre> <h3>Modified Paths</h3> <ul> <li><a href="#rhqtrunkmodulesenterpriseserverjarsrcmainjavaorgrhqenterpriseserverutilconcurrentAlertSerializerjava">rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AlertSerializer.java</a></li> <li><a href="#rhqtrunkmodulesenterpriseserverjarsrcmainjavaorgrhqenterpriseserverutilconcurrentAvailabilityReportSerializerjava">rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AvailabilityReportSerializer.java</a></li> </ul> </div> <div id="patch"> <h3>Diff</h3> <a id="rhqtrunkmodulesenterpriseserverjarsrcmainjavaorgrhqenterpriseserverutilconcurrentAlertSerializerjava"></a> <div class="modfile"><h4>Modified: rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AlertSerializer.java (4709 => 4710)</h4> <pre class="diff"> <span class="info">--- rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AlertSerializer.java 2009-08-04 03:32:13 UTC (rev 4709) +++ rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AlertSerializer.java 2009-08-04 03:43:21 UTC (rev 4710) </span><span class="lines">@@ -18,6 +18,7 @@ </span><span class="cx"> */ package org.rhq.enterprise.server.util.concurrent; </span><span class="add">+import java.util.Collections; </span><span class="cx"> import java.util.HashMap; import java.util.Map; import java.util.concurrent.locks.ReentrantReadWriteLock; </span><span class="lines">@@ -29,6 +30,7 @@ </span><span class="cx"> private final Log log = LogFactory.getLog(AlertSerializer.class); private static Map<Integer, ReentrantReadWriteLock> locks = new HashMap<Integer, ReentrantReadWriteLock>(); </span><span class="add">+ private static Map<Integer, Long> lockTimes = Collections.synchronizedMap(new HashMap<Integer, Long>()); </span><span class="cx"> private static AlertSerializer singleton = new AlertSerializer();; // synchronize so only one thread creates our singleton </span><span class="lines">@@ -37,40 +39,64 @@ </span><span class="cx"> } public void lock(int alertDefinitionId) { </span><span class="rem">- ReentrantReadWriteLock lock = null; - </span><span class="cx"> String msg = "tid= " + Thread.currentThread().getId() + ": alertDefinitionId=" + alertDefinitionId; </span><span class="add">+ boolean debug = this.log.isDebugEnabled(); </span><span class="cx"> </span><span class="rem">- /* - * synchronize on only what is needed - */ - log.debug(msg + ": about to synchronize"); </span><span class="add">+ ReentrantReadWriteLock lock = null; + logDebug(debug, msg, ": about to synchronize"); </span><span class="cx"> synchronized (this) { </span><span class="rem">- log.debug(msg + ": synchronized"); - lock = locks.get(alertDefinitionId); </span><span class="add">+ logDebug(debug, msg, ": synchronized"); + lock = AlertSerializer.locks.get(alertDefinitionId); </span><span class="cx"> if (lock == null) { </span><span class="rem">- log.debug(msg + ": creating new lock"); </span><span class="add">+ logDebug(debug, msg, ": creating new lock"); </span><span class="cx"> lock = new ReentrantReadWriteLock(); </span><span class="rem">- locks.put(alertDefinitionId, lock); </span><span class="add">+ AlertSerializer.locks.put(alertDefinitionId, lock); </span><span class="cx"> } } </span><span class="rem">- log.debug(msg + ": acquiring write lock"); </span><span class="add">+ logDebug(debug, msg, ": acquiring write lock"); + long start = System.currentTimeMillis(); </span><span class="cx"> lock.writeLock().lock(); </span><span class="rem">- log.debug(msg + ": acquired write lock"); </span><span class="add">+ long end = System.currentTimeMillis(); + long duration = end - start; + AlertSerializer.lockTimes.put(alertDefinitionId, Long.valueOf(end)); + if (duration < 5000L) { + logDebug(debug, msg, ": acquired write lock in millis=" + duration); + } else { + this.log.info(msg + ": acquired write lock in millis=" + duration); + } + + return; </span><span class="cx"> } public void unlock(int alertDefinitionId) { </span><span class="rem">- ReentrantReadWriteLock lock = locks.get(alertDefinitionId); - </span><span class="cx"> String msg = "tid= " + Thread.currentThread().getId() + ": alertDefinitionId=" + alertDefinitionId; </span><span class="add">+ boolean debug = this.log.isDebugEnabled(); </span><span class="cx"> </span><span class="add">+ ReentrantReadWriteLock lock = AlertSerializer.locks.get(alertDefinitionId); + </span><span class="cx"> if (lock != null) { </span><span class="rem">- log.debug(msg + ": releasing write lock"); </span><span class="add">+ Long lockedTime = AlertSerializer.lockTimes.get(alertDefinitionId); + long duration = System.currentTimeMillis() - ((lockedTime != null) ? lockedTime : Long.MAX_VALUE); + + if (duration < 5000L) { + logDebug(debug, msg, ": releasing write lock after being locked for millis=" + duration); + } else { + this.log.info(msg + ": releasing write lock after being locked for millis=" + duration); + } + </span><span class="cx"> lock.writeLock().unlock(); </span><span class="rem">- log.debug(msg + ": released write lock"); </span><span class="add">+ logDebug(debug, msg, ": released write lock"); </span><span class="cx"> } else { </span><span class="rem">- log.warn(msg + ": cannot release write lock"); </span><span class="add">+ this.log.warn(msg + ": cannot release write lock"); </span><span class="cx"> } </span><span class="add">+ + return; </span><span class="cx"> } </span><span class="add">+ + private void logDebug(boolean enabled, String arg1, String arg2) { + if (enabled) { + this.log.debug(arg1 + arg2); + } + } </span><span class="cx"> } \ No newline at end of file </span></pre></div> <a id="rhqtrunkmodulesenterpriseserverjarsrcmainjavaorgrhqenterpriseserverutilconcurrentAvailabilityReportSerializerjava"></a> <div class="modfile"><h4>Modified: rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AvailabilityReportSerializer.java (4709 => 4710)</h4> <pre class="diff"> <span class="info">--- rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AvailabilityReportSerializer.java 2009-08-04 03:32:13 UTC (rev 4709) +++ rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/util/concurrent/AvailabilityReportSerializer.java 2009-08-04 03:43:21 UTC (rev 4710) </span><span class="lines">@@ -18,9 +18,11 @@ </span><span class="cx"> */ package org.rhq.enterprise.server.util.concurrent; </span><span class="add">+import java.util.Collections; </span><span class="cx"> import java.util.HashMap; import java.util.Map; import java.util.concurrent.locks.ReentrantReadWriteLock; </span><span class="add">+ </span><span class="cx"> import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; </span><span class="lines">@@ -28,6 +30,7 @@ </span><span class="cx"> private final Log log = LogFactory.getLog(AvailabilityReportSerializer.class); private static Map<String, ReentrantReadWriteLock> locks = new HashMap<String, ReentrantReadWriteLock>(); </span><span class="add">+ private static Map<String, Long> lockTimes = Collections.synchronizedMap(new HashMap<String, Long>()); </span><span class="cx"> private static AvailabilityReportSerializer singleton = new AvailabilityReportSerializer(); public static AvailabilityReportSerializer getSingleton() { </span><span class="lines">@@ -35,37 +38,64 @@ </span><span class="cx"> } public void lock(String agentName) { </span><span class="rem">- ReentrantReadWriteLock lock = null; - </span><span class="cx"> String msg = "tid=" + Thread.currentThread().getId() + "; agent=" + agentName; </span><span class="add">+ boolean debug = this.log.isDebugEnabled(); </span><span class="cx"> </span><span class="rem">- log.debug(msg + ": about to synchronize"); </span><span class="add">+ ReentrantReadWriteLock lock = null; + logDebug(debug, msg, ": about to synchronize"); </span><span class="cx"> synchronized (this) { </span><span class="rem">- log.debug(msg + ": synchronized"); - lock = locks.get(agentName); </span><span class="add">+ logDebug(debug, msg, ": synchronized"); + lock = AvailabilityReportSerializer.locks.get(agentName); </span><span class="cx"> if (lock == null) { </span><span class="rem">- log.debug(msg + ": creating new lock"); </span><span class="add">+ logDebug(debug, msg, ": creating new lock"); </span><span class="cx"> lock = new ReentrantReadWriteLock(); </span><span class="rem">- locks.put(agentName, lock); </span><span class="add">+ AvailabilityReportSerializer.locks.put(agentName, lock); </span><span class="cx"> } } </span><span class="rem">- log.debug(msg + ": acquiring write lock"); </span><span class="add">+ logDebug(debug, msg, ": acquiring write lock"); + long start = System.currentTimeMillis(); </span><span class="cx"> lock.writeLock().lock(); </span><span class="rem">- log.debug(msg + ": acquired write lock"); </span><span class="add">+ long end = System.currentTimeMillis(); + long duration = end - start; + AvailabilityReportSerializer.lockTimes.put(agentName, Long.valueOf(end)); + if (duration < 5000L) { + logDebug(debug, msg, ": acquired write lock in millis=" + duration); + } else { + this.log.info(msg + ": acquired write lock in millis=" + duration); + } + + return; </span><span class="cx"> } public void unlock(String agentName) { </span><span class="rem">- ReentrantReadWriteLock lock = locks.get(agentName); - </span><span class="cx"> String msg = "tid=" + Thread.currentThread().getId() + "; agent=" + agentName; </span><span class="add">+ boolean debug = this.log.isDebugEnabled(); </span><span class="cx"> </span><span class="add">+ ReentrantReadWriteLock lock = AvailabilityReportSerializer.locks.get(agentName); + </span><span class="cx"> if (lock != null) { </span><span class="rem">- log.debug(msg + ": releasing write lock"); </span><span class="add">+ Long lockedTime = AvailabilityReportSerializer.lockTimes.get(agentName); + long duration = System.currentTimeMillis() - ((lockedTime != null) ? lockedTime : Long.MAX_VALUE); + + if (duration < 5000L) { + logDebug(debug, msg, ": releasing write lock after being locked for millis=" + duration); + } else { + this.log.info(msg + ": releasing write lock after being locked for millis=" + duration); + } + </span><span class="cx"> lock.writeLock().unlock(); </span><span class="rem">- log.debug(msg + ": released write lock"); </span><span class="add">+ logDebug(debug, msg, ": released write lock"); </span><span class="cx"> } else { </span><span class="rem">- log.warn(msg + ": cannot release write lock"); </span><span class="add">+ this.log.warn(msg + ": cannot release write lock"); </span><span class="cx"> } </span><span class="add">+ + return; </span><span class="cx"> } </span><span class="add">+ + private void logDebug(boolean enabled, String arg1, String arg2) { + if (enabled) { + this.log.debug(arg1 + arg2); + } + } </span><span class="cx"> } \ No newline at end of file </span> </pre> </div> </div> </body> </html> |