/*
* Licensed to the Apache Software Foundation (ASF) under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. The ASF licenses this file
* to you under the Apache License, Version 2.0 (the
* "License"); you may not use this file except in compliance
* with the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package org.apache.ambari.server.logging;
import java.util.Map;
import java.util.TreeMap;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.TimeUnit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.google.common.base.Ticker;
/**
* A helper object for Lock implementations that need logging/profiling.
* <p>
* It collects the time spent waiting for the lock, the time spent holding the lock,
* and the number of times the lock was taken. Lock requests, acquisitions and releases
* are also logged at debug level. The log message for requests contains a filtered stack
* trace, only including methods from org.apache.ambari and subpackages to eliminate the noise.
*/
final class LockProfileDelegate {
private static final Logger LOG = LoggerFactory.getLogger(LockProfileDelegate.class);
private final ThreadLocal<Long> lockRequestTime = new ThreadLocal<>();
private final ThreadLocal<Long> lockAcquireTime = new ThreadLocal<>();
private final ConcurrentMap<String, Long> timeSpentWaitingForLock = new ConcurrentHashMap<>();
private final ConcurrentMap<String, Long> timeSpentLocked = new ConcurrentHashMap<>();
private final ConcurrentMap<String, Integer> lockCount = new ConcurrentHashMap<>();
private final String label;
private final ProfiledLock lock;
private final Ticker ticker;
/**
* @param ticker is the source of time information, replaceable for testing purpose
* @param label is included in log messages (optional, may be empty or null)
* @param lock the lock to profile
*/
LockProfileDelegate(Ticker ticker, String label, ProfiledLock lock) {
this.label = addSpacePostfixIfNeeded(label);
this.lock = lock;
this.ticker = ticker;
}
/**
* @return the label for this lock (including an extra space at the end, if the label is otherwise not empty)
*/
String getLabel() {
return label;
}
/**
* @return time spent waiting for the lock (in milliseconds) by thread name
*/
Map<String, Long> getTimeSpentWaitingForLock() {
return new TreeMap<>(timeSpentWaitingForLock);
}
/**
* @return time spent holding the lock (in milliseconds) by thread name
*/
Map<String, Long> getTimeSpentLocked() {
return new TreeMap<>(timeSpentLocked);
}
/**
* @return the number of times the lock was taken by thread name
*/
Map<String, Integer> getLockCount() {
return new TreeMap<>(lockCount);
}
/**
* Should be called by the lock to indicate that the lock was requested.
*
* @return whether the lock was already owned by the current thread
*/
boolean logRequest() {
boolean alreadyOwned = lock.isHeldByCurrentThread();
if (!alreadyOwned) {
if (LOG.isDebugEnabled()) {
LOG.debug("{}request {} from {}", label, lock, getFilteredStackTrace());
}
lockRequestTime.set(ticker.read());
}
return alreadyOwned;
}
/**
* Should be called by the lock to indicate that the request for the lock was completed,
* either successfully (acquired) or unsuccessfully (not acquired due to timeout, etc.).
*
* @param alreadyOwned whether the current thread already owned the lock before the request (if true, the call is ignored)
* @param acquired whether the lock was acquired by the requestor
*/
void logRequestCompleted(boolean alreadyOwned, boolean acquired) {
if (!alreadyOwned) {
if (acquired) {
long elapsed = storeElapsedTime(lockRequestTime, timeSpentWaitingForLock);
LOG.debug("{}acquired {} after {} ms", label, lock, elapsed);
increment(lockCount);
lockAcquireTime.set(ticker.read());
} else {
LOG.debug("{}failed to acquire {}", label, lock);
}
}
}
/**
* Should be called by the lock to indicate that the lock was unlocked. For reentrant locks this may or may not
* mean the lock was actually released.
*/
void logUnlock() {
boolean released = !lock.isHeldByCurrentThread();
if (released) {
long elapsed = storeElapsedTime(lockAcquireTime, timeSpentLocked);
if (LOG.isDebugEnabled()) {
LOG.debug("{}released {} after {} ms", label, lock, elapsed);
}
}
}
private long storeElapsedTime(ThreadLocal<Long> startHolder, ConcurrentMap<String, Long> map) {
long end = ticker.read();
long elapsed = Long.MIN_VALUE;
Long start = startHolder.get();
if (start != null && start <= end) {
elapsed = TimeUnit.NANOSECONDS.toMillis(end - start);
String name = Thread.currentThread().getName();
map.putIfAbsent(name, 0L);
if (elapsed > 0) {
map.put(name, map.get(name) + elapsed);
}
}
startHolder.remove();
return elapsed;
}
private static void increment(ConcurrentMap<String, Integer> map) {
String name = Thread.currentThread().getName();
map.putIfAbsent(name, 0);
map.put(name, map.get(name) + 1);
}
private static String addSpacePostfixIfNeeded(String label) {
if (label == null) {
return "";
}
label = label.trim();
return label.length() > 0 ? label + " " : label;
}
private static String getFilteredStackTrace() {
StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
StringBuilder sb = new StringBuilder();
for (StackTraceElement element : stackTrace) {
String className = element.getClassName();
if (className.startsWith("org.apache.ambari") && !className.startsWith("org.apache.ambari.server.logging")) {
sb.append(className)
.append("#").append(element.getMethodName())
.append("(").append(element.getFileName())
.append(":").append(element.getLineNumber())
.append(");\t");
}
}
return sb.toString();
}
}