profile support

This commit is contained in:
wenshao
2012-10-07 17:51:11 +08:00
parent 7a7af668f3
commit e1823c2f2c
12 changed files with 415 additions and 82 deletions
@@ -50,6 +50,7 @@ import com.alibaba.druid.stat.JdbcStatementStat;
import com.alibaba.druid.support.json.JSONWriter;
import com.alibaba.druid.support.logging.Log;
import com.alibaba.druid.support.logging.LogFactory;
import com.alibaba.druid.support.profile.Profiler;
/**
* @author wenshao<szujobs@hotmail.com>
@@ -425,6 +426,8 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
}
StatFilterContext.getInstance().executeBefore(sql, inTransaction);
Profiler.enter(sql, Profiler.PROFILE_TYPE_SQL);
}
private final void internalAfterStatementExecute(StatementProxy statement, boolean firstResult,
@@ -433,10 +436,10 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
final JdbcStatementStat.Entry entry = getStatementInfo(statement);
final long nowNano = System.nanoTime();
final long nanoSpan = nowNano - entry.getLastExecuteStartNano();
final long nanos = nowNano - entry.getLastExecuteStartNano();
JdbcDataSourceStat dataSourceStat = statement.getConnectionProxy().getDirectDataSource().getDataSourceStat();
dataSourceStat.getStatementStat().afterExecute(nanoSpan);
dataSourceStat.getStatementStat().afterExecute(nanos);
final JdbcSqlStat sqlStat = statement.getSqlStat();
@@ -444,8 +447,8 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
sqlStat.incrementExecuteSuccessCount();
sqlStat.decrementRunningCount();
sqlStat.addExecuteTime(statement.getLastExecuteType(), firstResult, nanoSpan);
statement.setLastExecuteTimeNano(nanoSpan);
sqlStat.addExecuteTime(statement.getLastExecuteType(), firstResult, nanos);
statement.setLastExecuteTimeNano(nanos);
if ((!statement.isFirstResultSet()) && statement.getLastExecuteType() == StatementExecuteType.Execute) {
try {
int updateCount = statement.getUpdateCount();
@@ -461,7 +464,7 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
}
}
long millis = nanoSpan / (1000 * 1000);
long millis = nanos / (1000 * 1000);
if (millis >= slowSqlMillis) {
String slowParameters = buildSlowParameters(statement);
sqlStat.setLastSlowParameters(slowParameters);
@@ -474,7 +477,9 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
}
String sql = statement.getLastExecuteSql();
StatFilterContext.getInstance().executeAfter(sql, nanoSpan, null);
StatFilterContext.getInstance().executeAfter(sql, nanos, null);
Profiler.release(nanos);
}
@Override
@@ -484,11 +489,11 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
ConnectionProxy connection = statement.getConnectionProxy();
JdbcConnectionStat.Entry connectionCounter = getConnectionInfo(connection);
long nanoSpan = System.nanoTime() - counter.getLastExecuteStartNano();
long nanos = System.nanoTime() - counter.getLastExecuteStartNano();
JdbcDataSourceStat dataSourceStat = statement.getConnectionProxy().getDirectDataSource().getDataSourceStat();
dataSourceStat.getStatementStat().error(error);
dataSourceStat.getStatementStat().afterExecute(nanoSpan);
dataSourceStat.getStatementStat().afterExecute(nanos);
connectionCounter.error(error);
@@ -497,11 +502,12 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean {
if (sqlStat != null) {
sqlStat.error(error);
sqlStat.addExecuteTime(statement.getLastExecuteType(), statement.isFirstResultSet(), nanoSpan);
statement.setLastExecuteTimeNano(nanoSpan);
sqlStat.addExecuteTime(statement.getLastExecuteType(), statement.isFirstResultSet(), nanos);
statement.setLastExecuteTimeNano(nanos);
}
StatFilterContext.getInstance().executeAfter(sql, nanoSpan, error);
StatFilterContext.getInstance().executeAfter(sql, nanos, error);
Profiler.release(nanos);
}
private String buildSlowParameters(StatementProxy statement) {
@@ -18,6 +18,7 @@ package com.alibaba.druid.support.http;
import java.io.IOException;
import java.util.Arrays;
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import javax.servlet.Filter;
@@ -41,6 +42,9 @@ import com.alibaba.druid.support.http.stat.WebSessionStat;
import com.alibaba.druid.support.http.stat.WebURIStat;
import com.alibaba.druid.support.logging.Log;
import com.alibaba.druid.support.logging.LogFactory;
import com.alibaba.druid.support.profile.ProfileEntryKey;
import com.alibaba.druid.support.profile.ProfileEntryReqStat;
import com.alibaba.druid.support.profile.Profiler;
import com.alibaba.druid.util.DruidWebUtils;
import com.alibaba.druid.util.PatternMatcher;
import com.alibaba.druid.util.ServletPathMatcher;
@@ -55,6 +59,7 @@ public class WebStatFilter implements Filter {
private final static Log LOG = LogFactory.getLog(WebStatFilter.class);
public final static String PARAM_NAME_PORFILE_ENABLE = "profileEnable";
public final static String PARAM_NAME_SESSION_STAT_ENABLE = "sessionStatEnable";
public final static String PARAM_NAME_SESSION_STAT_MAX_COUNT = "sessionStatMaxCount";
public static final String PARAM_NAME_EXCLUSIONS = "exclusions";
@@ -75,6 +80,7 @@ public class WebStatFilter implements Filter {
private boolean sessionStatEnable = true;
private int sessionStatMaxCount = DEFAULT_MAX_STAT_SESSION_COUNT;
private boolean createSession = false;
private boolean profileEnable = false;
private String contextPath;
@@ -114,6 +120,10 @@ public class WebStatFilter implements Filter {
}
}
if (isProfileEnable()) {
Profiler.initLocal();
}
// 第一次访问时,uriStat这里为null,是为了防止404攻击。
if (uriStat != null) {
uriStat.beforeInvoke();
@@ -177,6 +187,12 @@ public class WebStatFilter implements Filter {
}
WebRequestStat.set(null);
if (isProfileEnable()) {
Map<ProfileEntryKey, ProfileEntryReqStat> requestStatsMap = Profiler.getStatsMap();
uriStat.getProfiletat().record(requestStatsMap);
Profiler.removeLocal();
}
}
}
@@ -339,6 +355,20 @@ public class WebStatFilter implements Filter {
}
}
}
{
String param = config.getInitParameter(PARAM_NAME_PORFILE_ENABLE);
if (param != null && param.trim().length() != 0) {
param = param.trim();
if ("true".equals(param)) {
this.profileEnable = true;
} else if ("false".equals(param)) {
this.profileEnable = false;
} else {
LOG.error("WebStatFilter Parameter '" + PARAM_NAME_PORFILE_ENABLE + "' config error");
}
}
}
{
String param = config.getInitParameter(PARAM_NAME_SESSION_STAT_MAX_COUNT);
if (param != null && param.trim().length() != 0) {
@@ -376,6 +406,14 @@ public class WebStatFilter implements Filter {
this.sessionStatEnable = sessionStatEnable;
}
public boolean isProfileEnable() {
return profileEnable;
}
public void setProfileEnable(boolean profileEnable) {
this.profileEnable = profileEnable;
}
public WebAppStat getWebAppStat() {
return webAppStat;
}
@@ -21,6 +21,9 @@ import java.util.Map;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;
import com.alibaba.druid.support.profile.ProfileStat;
import com.alibaba.druid.support.profile.Profiler;
public class WebURIStat {
private final String uri;
@@ -54,6 +57,8 @@ public class WebURIStat {
private volatile long lastAccessTimeMillis = -1L;
private ProfileStat profiletat = new ProfileStat();
private final static ThreadLocal<WebURIStat> currentLocal = new ThreadLocal<WebURIStat>();
public WebURIStat(String uri){
@@ -93,6 +98,8 @@ public class WebURIStat {
if (requestStat != null) {
this.setLastAccessTimeMillis(requestStat.getStartMillis());
}
Profiler.enter(uri, Profiler.PROFILE_TYPE_WEB);
}
public void afterInvoke(Throwable error, long nanos) {
@@ -154,16 +161,18 @@ public class WebURIStat {
this.jdbcExecuteErrorCount.addAndGet(localStat.getJdbcExecuteErrorCount());
this.jdbcExecuteTimeNano.addAndGet(localStat.getJdbcExecuteTimeNano());
this.addJdbcPoolConnectionOpenCount(localStat.getJdbcPoolConnectionOpenCount());
this.addJdbcPoolConnectionCloseCount(localStat.getJdbcPoolConnectionCloseCount());
this.addJdbcResultSetOpenCount(localStat.getJdbcResultSetOpenCount());
this.addJdbcResultSetCloseCount(localStat.getJdbcResultSetCloseCount());
}
}
currentLocal.set(null);
Profiler.release(nanos);
}
public int getRunningCount() {
@@ -301,7 +310,7 @@ public class WebURIStat {
public long getJdbcResultSetOpenCount() {
return jdbcResultSetOpenCount.get();
}
public void addJdbcResultSetOpenCount(long delta) {
jdbcResultSetOpenCount.addAndGet(delta);
}
@@ -309,11 +318,15 @@ public class WebURIStat {
public long getJdbcResultSetCloseCount() {
return jdbcResultSetCloseCount.get();
}
public void addJdbcResultSetCloseCount(long delta) {
jdbcResultSetCloseCount.addAndGet(delta);
}
public ProfileStat getProfiletat() {
return profiletat;
}
public Map<String, Object> getStatData() {
Map<String, Object> data = new LinkedHashMap<String, Object>();
@@ -341,10 +354,12 @@ public class WebURIStat {
data.put("JdbcPoolConnectionOpenCount", this.getJdbcPoolConnectionOpenCount());
data.put("JdbcPoolConnectionCloseCount", this.getJdbcPoolConnectionCloseCount());
data.put("JdbcResultSetOpenCount", this.getJdbcResultSetOpenCount());
data.put("JdbcResultSetCloseCount", this.getJdbcResultSetCloseCount());
data.put("Profiles", this.getProfiletat().getStatData());
return data;
}
}
@@ -2,41 +2,51 @@ package com.alibaba.druid.support.profile;
public class ProfileEntry {
private final Key key;
private final String type;
private final ProfileEntry parent;
private final ProfileEntryKey key;
public ProfileEntry(Key key, String type){
super();
private int executeCount = 0;
private long executeTimeNanos = 0;
public ProfileEntry(ProfileEntry parent, ProfileEntryKey key){
this.parent = parent;
this.key = key;
this.type = type;
}
public Key getKey() {
public ProfileEntry getParent() {
return parent;
}
public ProfileEntryKey getKey() {
return key;
}
public String getParentName() {
return key.getParentName();
}
public String getName() {
return key.getName();
}
public String getType() {
return type;
return key.getType();
}
public static class Key {
private String parent;
private String name;
public Key(String parentName, String name){
super();
this.parent = parentName;
this.name = name;
}
public String getParent() {
return parent;
}
public String getName() {
return name;
}
public int getExecuteCount() {
return executeCount;
}
public void incrementExecuteCount() {
this.executeCount++;
}
public long getExecuteTimeNanos() {
return executeTimeNanos;
}
public void addExecuteTimeNanos(long nanos) {
this.executeTimeNanos += nanos;
}
}
@@ -0,0 +1,65 @@
package com.alibaba.druid.support.profile;
public class ProfileEntryKey {
private final String parentName;
private final String name;
private final String type;
public ProfileEntryKey(String parentName, String name, String type){
this.parentName = parentName;
this.name = name;
this.type = type;
}
public String getParentName() {
return parentName;
}
public String getName() {
return name;
}
public String getType() {
return type;
}
@Override
public int hashCode() {
final int prime = 31;
int result = 1;
result = prime * result + ((name == null) ? 0 : name.hashCode());
result = prime * result + ((parentName == null) ? 0 : parentName.hashCode());
return result;
}
@Override
public boolean equals(Object obj) {
if (this == obj) {
return true;
}
if (obj == null) {
return false;
}
if (getClass() != obj.getClass()) {
return false;
}
ProfileEntryKey other = (ProfileEntryKey) obj;
if (name == null) {
if (other.name != null) {
return false;
}
} else if (!name.equals(other.name)) {
return false;
}
if (parentName == null) {
if (other.parentName != null) {
return false;
}
} else if (!parentName.equals(other.parentName)) {
return false;
}
return true;
}
}
@@ -0,0 +1,24 @@
package com.alibaba.druid.support.profile;
public class ProfileEntryReqStat {
private long executeCount;
private long executeTimeNanos;
public long getExecuteCount() {
return executeCount;
}
public void incrementExecuteCount() {
this.executeCount++;
}
public long getExecuteTimeNanos() {
return executeTimeNanos;
}
public void addExecuteTimeNanos(long nanos) {
this.executeTimeNanos += nanos;
}
}
@@ -0,0 +1,33 @@
package com.alibaba.druid.support.profile;
import java.util.concurrent.atomic.AtomicLongFieldUpdater;
public class ProfileEntryStat {
private volatile long executeCount = 0;
private volatile long executeTimeNanos = 0;
private static final AtomicLongFieldUpdater<ProfileEntryStat> executeCountUpdater;
private static final AtomicLongFieldUpdater<ProfileEntryStat> executeTimeNanosUpdater;
static {
executeCountUpdater = AtomicLongFieldUpdater.newUpdater(ProfileEntryStat.class, "executeCount");
executeTimeNanosUpdater = AtomicLongFieldUpdater.newUpdater(ProfileEntryStat.class, "executeTimeNanos");
}
public long getExecuteCount() {
return executeCount;
}
public void addExecuteCount(long delta) {
executeCountUpdater.addAndGet(this, delta);
}
public long getExecuteTimeNanos() {
return executeTimeNanos;
}
public void addExecuteTimeNanos(long delta) {
executeTimeNanosUpdater.addAndGet(this, delta);
}
}
@@ -0,0 +1,55 @@
package com.alibaba.druid.support.profile;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
public class ProfileStat {
private ConcurrentHashMap<ProfileEntryKey, ProfileEntryStat> entries = new ConcurrentHashMap<ProfileEntryKey, ProfileEntryStat>();
public ConcurrentHashMap<ProfileEntryKey, ProfileEntryStat> getEntries() {
return entries;
}
public void record(Map<ProfileEntryKey, ProfileEntryReqStat> requestStatsMap) {
if (requestStatsMap == null) {
return;
}
for (Map.Entry<ProfileEntryKey, ProfileEntryReqStat> entry : requestStatsMap.entrySet()) {
ProfileEntryKey entryKey = entry.getKey();
ProfileEntryReqStat reqEntryStat = entry.getValue();
ProfileEntryStat entryStat = entries.get(entryKey);
if (entryStat == null) {
entries.putIfAbsent(entryKey, new ProfileEntryStat());
entryStat = entries.get(entryKey);
}
entryStat.addExecuteCount(reqEntryStat.getExecuteCount());
entryStat.addExecuteTimeNanos(reqEntryStat.getExecuteTimeNanos());
}
}
public Map<Map<String, Object>, Map<String, Object>> getStatData() {
Map<Map<String, Object>, Map<String, Object>> data = new LinkedHashMap<Map<String, Object>, Map<String, Object>>();
for (Map.Entry<ProfileEntryKey, ProfileEntryStat> entry : entries.entrySet()) {
Map<String, Object> key = new LinkedHashMap<String, Object>();
Map<String, Object> value = new LinkedHashMap<String, Object>();
key.put("Parent", entry.getKey().getParentName());
key.put("Name", entry.getKey().getName());
key.put("Type", entry.getKey().getType());
value.put("ExecuteCount", entry.getValue().getExecuteCount());
value.put("ExecuteTimeNanos", entry.getValue().getExecuteTimeNanos());
data.put(key, value);
}
return data;
}
}
@@ -3,49 +3,34 @@ package com.alibaba.druid.support.profile;
import java.util.HashMap;
import java.util.Map;
import com.alibaba.druid.support.profile.ProfileEntry.Key;
public class Profiler {
public static ThreadLocal<Boolean> enableLocal = new ThreadLocal<Boolean>();
public static final String PROFILE_TYPE_WEB = "WEB";
public static final String PROFILE_TYPE_SPRING = "SPRING";
public static final String PROFILE_TYPE_SQL = "SQL";
private static ThreadLocal<Map<ProfileEntry.Key, ProfileEntry>> entriesLocal = new ThreadLocal<Map<Key, ProfileEntry>>();
private static ThreadLocal<Map<ProfileEntryKey, ProfileEntryReqStat>> statsMapLocal = new ThreadLocal<Map<ProfileEntryKey, ProfileEntryReqStat>>();
private final static ThreadLocal<ProfileEntry> currentLocal = new ThreadLocal<ProfileEntry>();
public static void setThreadLocalEnable() {
enableLocal.set(true);
}
public static void setThreadLocalDisable() {
enableLocal.remove();
}
private final static ThreadLocal<ProfileEntry> currentLocal = new ThreadLocal<ProfileEntry>();
public static boolean isEnable() {
return Boolean.TRUE == enableLocal.get();
return statsMapLocal != null;
}
public static void enter(String name, String type, long startNano) {
public static void enter(String name, String type) {
if (!isEnable()) {
return;
}
ProfileEntry parent = currentLocal.get();
String parentName = null;
if (parent != null) {
parentName = parent.getKey().getName();
parentName = parent.getName();
}
ProfileEntry.Key key = new ProfileEntry.Key(parentName, name);
Map<ProfileEntry.Key, ProfileEntry> entries = entriesLocal.get();
if (entries == null) {
entries = new HashMap<ProfileEntry.Key, ProfileEntry>();
entriesLocal.set(entries);
}
ProfileEntry entry = entries.get(key);
if (entry == null) {
entry = new ProfileEntry(key, type);
entries.put(key, entry);
}
ProfileEntryKey key = new ProfileEntryKey(parentName, name, type);
ProfileEntry entry = new ProfileEntry(parent, key);
currentLocal.set(entry);
}
@@ -53,7 +38,36 @@ public class Profiler {
return currentLocal.get();
}
public static void release(long nanoSpan) {
public static void release(long nanos) {
ProfileEntry current = currentLocal.get();
currentLocal.set(current.getParent());
ProfileEntryReqStat stat = null;
Map<ProfileEntryKey, ProfileEntryReqStat> statsMap = statsMapLocal.get();
if (statsMap == null) {
return;
}
stat = statsMap.get(current.getKey());
if (stat == null) {
stat = new ProfileEntryReqStat();
statsMap.put(current.getKey(), stat);
}
stat.incrementExecuteCount();
stat.addExecuteTimeNanos(nanos);
}
public static Map<ProfileEntryKey, ProfileEntryReqStat> getStatsMap() {
return statsMapLocal.get();
}
public static void initLocal() {
statsMapLocal.set(new HashMap<ProfileEntryKey, ProfileEntryReqStat>());
}
public static void removeLocal() {
statsMapLocal.remove();
}
}
@@ -30,6 +30,8 @@ import com.alibaba.druid.support.logging.LogFactory;
public class DruidStatInterceptor implements MethodInterceptor, InitializingBean, DisposableBean {
public static final String PROP_NAME_PORFILE = "druid.profile";
private final static Log LOG = LogFactory.getLog(DruidStatInterceptor.class);
private static SpringStat springStat = new SpringStat();
@@ -21,6 +21,8 @@ import java.util.Map;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;
import com.alibaba.druid.support.profile.Profiler;
public class SpringMethodStat {
private final static ThreadLocal<SpringMethodStat> currentLocal = new ThreadLocal<SpringMethodStat>();
@@ -72,7 +74,7 @@ public class SpringMethodStat {
jdbcPoolConnectionOpenCount.set(0);
jdbcPoolConnectionCloseCount.set(0);
jdbcResultSetOpenCount.set(0);
jdbcResultSetCloseCount.set(0);
@@ -111,6 +113,8 @@ public class SpringMethodStat {
}
executeCount.incrementAndGet();
Profiler.enter(methodInfo.getSignature(), Profiler.PROFILE_TYPE_SPRING);
}
public void afterInvoke(Throwable error, long nanos) {
@@ -122,6 +126,8 @@ public class SpringMethodStat {
lastError = error;
lastErrorTimeMillis = System.currentTimeMillis();
}
Profiler.release(nanos);
}
public Throwable getLastError() {
@@ -263,15 +269,15 @@ public class SpringMethodStat {
public void incrementJdbcPoolConnectionCloseCount() {
jdbcPoolConnectionCloseCount.incrementAndGet();
}
public long getJdbcResultSetOpenCount() {
return jdbcResultSetOpenCount.get();
}
public void addJdbcResultSetOpenCount(long delta) {
jdbcResultSetOpenCount.addAndGet(delta);
}
public void incrementJdbcResultSetOpenCount() {
jdbcResultSetOpenCount.incrementAndGet();
}
@@ -279,11 +285,11 @@ public class SpringMethodStat {
public long getJdbcResultSetCloseCount() {
return jdbcResultSetCloseCount.get();
}
public void addJdbcResultSetCloseCount(long delta) {
jdbcResultSetCloseCount.addAndGet(delta);
}
public void incrementJdbcResultSetCloseCount() {
jdbcResultSetCloseCount.incrementAndGet();
}
@@ -305,10 +311,10 @@ public class SpringMethodStat {
data.put("JdbcPoolConnectionOpenCount", this.getJdbcPoolConnectionOpenCount());
data.put("JdbcPoolConnectionCloseCount", this.getJdbcPoolConnectionCloseCount());
data.put("JdbcResultSetOpenCount", this.getJdbcResultSetOpenCount());
data.put("JdbcResultSetCloseCount", this.getJdbcResultSetCloseCount());
data.put("JdbcExecuteCount", this.getJdbcExecuteCount());
data.put("JdbcExecuteErrorCount", this.getJdbcExecuteErrorCount());
data.put("JdbcExecuteTimeMillis", this.getJdbcExecuteTimeMillis());
@@ -0,0 +1,65 @@
package com.alibaba.druid.bvt.support.profile;
import junit.framework.Assert;
import junit.framework.TestCase;
import com.alibaba.druid.support.profile.ProfileEntryKey;
import com.alibaba.druid.support.profile.ProfileEntryReqStat;
import com.alibaba.druid.support.profile.Profiler;
public class ProfilerTest extends TestCase {
public void test_profile() throws Exception {
for (int i = 0; i < 10; ++i) {
req();
}
}
private void req() {
Profiler.initLocal();
Profiler.enter("/", Profiler.PROFILE_TYPE_WEB);
for (int i = 0; i < 100; ++i) {
execA();
}
Assert.assertEquals(2, Profiler.getStatsMap().size());
{
ProfileEntryReqStat stat = Profiler.getStatsMap().get(new ProfileEntryKey("/", "com.xxx.a(int)",
Profiler.PROFILE_TYPE_SPRING));
Assert.assertEquals(100, stat.getExecuteCount());
Assert.assertEquals(100, stat.getExecuteTimeNanos());
}
{
ProfileEntryReqStat stat = Profiler.getStatsMap().get(new ProfileEntryKey("com.xxx.a(int)",
"com.xxx.b(int)",
Profiler.PROFILE_TYPE_SPRING));
Assert.assertEquals(1000 * 100, stat.getExecuteCount());
Assert.assertEquals(1000 * 100, stat.getExecuteTimeNanos());
}
Profiler.release(1);
Assert.assertEquals(3, Profiler.getStatsMap().size());
Profiler.removeLocal();
}
private void execA() {
Profiler.enter("com.xxx.a(int)", Profiler.PROFILE_TYPE_SPRING);
for (int i = 0; i < 1000; ++i) {
execB();
}
Profiler.release(1);
}
private void execB() {
Profiler.enter("com.xxx.b(int)", Profiler.PROFILE_TYPE_SPRING);
Profiler.release(1);
}
}