/*
* Copyright (c) 2010-2013 Evolveum
*
* Licensed 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 com.evolveum.midpoint.util.aspect;
import com.evolveum.midpoint.util.logging.Trace;
import com.evolveum.midpoint.util.logging.TraceManager;
import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
/**
* This class provides functionality as a holder for method performance statistics. Currently, we are monitoring
* and updating following statistics:
* longest method call - MAX
* quickest method call - MIN
* average length of method call - MEAN
* number of method calls - USAGE_COUNT
*
* We also update these statistics every time specific method call is captured by MidpointInterceptor class and then
* processed by AspectProfilingFilters. This is performed in update() method that is synchronized for obvious
* reasons.
*
* @author shood
* */
public class MethodUsageStatistics {
private static Trace LOGGER = TraceManager.getTrace(ProfilingDataManager.class);
private long min = Long.MAX_VALUE;
private long max = 0;
private long mean = 0;
private long processTimeMean = 0;
private long usageCount = 1;
private long currentTopTenMin = Long.MAX_VALUE;
private ProfilingDataManager.Subsystem subsystem;
private List<ProfilingDataLog> slowestMethodList = Collections.synchronizedList(new ArrayList<ProfilingDataLog>());
public MethodUsageStatistics(ProfilingDataLog logEvent, ProfilingDataManager.Subsystem subsystem){
long estTime = logEvent.getEstimatedTime();
this.min = estTime;
this.max = estTime;
this.usageCount++;
this.currentTopTenMin = estTime;
this.subsystem = subsystem;
this.mean = estTime;
}
public long getProcessTimeMean() {
return processTimeMean;
}
public void setProcessTimeMean(long processTimeMean) {
this.processTimeMean = processTimeMean;
}
public ProfilingDataManager.Subsystem getSubsystem() {
return subsystem;
}
public void setSubsystem(ProfilingDataManager.Subsystem subsystem) {
this.subsystem = subsystem;
}
public long getMin() {
return min;
}
public void setMin(long min) {
this.min = min;
}
public long getMax() {
return max;
}
public void setMax(long max) {
this.max = max;
}
public long getMean() {
return mean;
}
public void setMean(long mean) {
this.mean = mean;
}
public long getUsageCount() {
return usageCount;
}
public void setUsageCount(long usageCount) {
this.usageCount = usageCount;
}
public long getCurrentTopTenMin() {
return currentTopTenMin;
}
public void setCurrentTopTenMin(long currentTopTenMin) {
this.currentTopTenMin = currentTopTenMin;
}
public List<ProfilingDataLog> getSlowestMethodList() {
return slowestMethodList;
}
public void setSlowestMethodList(List<ProfilingDataLog> slowestMethodList) {
this.slowestMethodList = slowestMethodList;
}
public synchronized void update(ProfilingDataLog logEvent){
long currentEst = logEvent.getEstimatedTime();
if(this.min > currentEst)
this.min = currentEst;
if(this.max < currentEst)
this.max = currentEst;
calculateMeanIterative(currentEst);
usageCount++;
}
private void calculateMeanIterative(long currentEst){
this.mean += (currentEst - this.mean)/this.usageCount;
}
public void updateProcessTimeList(long est){
this.processTimeMean += (est - this.processTimeMean)/this.usageCount;
}
public void appendToLogger(boolean afterTest){
ProfilingDataLog log = this.slowestMethodList.get(0);
if(afterTest){
LOGGER.info("{}->{}: CALLS: {} MAX: {} MIN: {} MEAN: {} PROCESS_TIME_MEAN: {}",
new Object[]{log.getClassName(), log.getMethodName(), usageCount, formatExecutionTime(max), formatExecutionTime(min), formatExecutionTime(this.mean),
formatExecutionTime(processTimeMean)});
} else {
LOGGER.debug("{}->{}: CALLS: {} MAX: {} MIN: {} MEAN: {} PROCESS_TIME_MEAN: {}",
new Object[]{log.getClassName(), log.getMethodName(), usageCount, formatExecutionTime(max), formatExecutionTime(min), formatExecutionTime(this.mean),
formatExecutionTime(processTimeMean)});
}
for(ProfilingDataLog l: this.slowestMethodList)
l.appendToLogger(afterTest);
}
private static String formatExecutionTime(long est){
StringBuilder sb = new StringBuilder();
sb.append((long) (est / 1000000));
sb.append('.');
long mikros = (long) (est / 1000) % 1000;
if (mikros < 100) {
sb.append('0');
}
if (mikros < 10) {
sb.append('0');
}
sb.append(mikros);
sb.append(" ms.");
return sb.toString();
}
}