#1183 - Support transaction profiling, move away from binary encoding

This commit is contained in:
Rob Bygrave
2017-10-26 23:32:44 +13:00
parent 37d001f754
commit 55d66ae851
19 changed files with 269 additions and 177 deletions
@@ -8,12 +8,17 @@ public class ProfilingConfig {
/**
* When true transaction profiling is enabled.
*/
private boolean transactionProfiling;
private boolean enabled;
/**
* Set true for verbose mode.
*/
private boolean verbose;
/**
* The minimum transaction execution time to be included in profiling.
*/
private long minimumTransactionMicros;
private long minimumMicros;
/**
* A specific set of profileIds to include in profiling.
@@ -30,29 +35,43 @@ public class ProfilingConfig {
/**
* Return true if transaction profiling is enabled.
*/
public boolean isTransactionProfiling() {
return transactionProfiling;
public boolean isEnabled() {
return enabled;
}
/**
* Set to true to enable transaction profiling.
*/
public void setTransactionProfiling(boolean transactionProfiling) {
this.transactionProfiling = transactionProfiling;
public void setEnabled(boolean enabled) {
this.enabled = enabled;
}
/**
* Return true if verbose mode is used.
*/
public boolean isVerbose() {
return verbose;
}
/**
* Set to true to use verbose mode.
*/
public void setVerbose(boolean verbose) {
this.verbose = verbose;
}
/**
* Return the minimum transaction execution to be included in profiling.
*/
public long getMinimumTransactionMicros() {
return minimumTransactionMicros;
public long getMinimumMicros() {
return minimumMicros;
}
/**
* Set the minimum transaction execution to be included in profiling.
*/
public void setMinimumTransactionMicros(long minimumTransactionMicros) {
this.minimumTransactionMicros = minimumTransactionMicros;
public void setMinimumMicros(long minimumMicros) {
this.minimumMicros = minimumMicros;
}
/**
@@ -103,10 +122,13 @@ public class ProfilingConfig {
* Load setting from properties.
*/
public void loadSettings(PropertiesWrapper p, String name) {
transactionProfiling = p.getBoolean("profiling.transactionProfiling", transactionProfiling);
enabled = p.getBoolean("profiling", enabled);
verbose = p.getBoolean("profiling.verbose", verbose);
directory = p.get("profiling.directory", directory);
profilesPerFile = p.getLong("profiling.profilesPerFile", profilesPerFile);
minimumTransactionMicros = p.getLong("profiling.minimumTransactionMicros", minimumTransactionMicros);
minimumMicros = p.getLong("profiling.minimumMicros", minimumMicros);
String includeIds = p.get("profiling.includeProfileIds");
if (includeIds != null) {
@@ -81,7 +81,7 @@ public class ScopedTransaction implements SpiTransaction {
}
@Override
public int profileOffset() {
public long profileOffset() {
return transaction.profileOffset();
}
@@ -105,13 +105,13 @@ public interface SpiQuery<T> extends Query<T>, TxnProfileEventCodes {
*/
UPDATE(FIND_UPDATE);
byte profileEventId;
String profileEventId;
Type(byte profileEventId) {
Type(String profileEventId) {
this.profileEventId = profileEventId;
}
public byte profileEventId() {
public String profileEventId() {
return profileEventId;
}
}
@@ -153,7 +153,7 @@ public interface SpiQuery<T> extends Query<T>, TxnProfileEventCodes {
/**
* Return the profile event id based on query mode and type.
*/
byte profileEventId();
String profileEventId();
/**
* Return the id used to identify a particular query for the given bean type.
@@ -287,7 +287,7 @@ public interface SpiTransaction extends Transaction {
/**
* Return the offset time from the start of the transaction.
*/
int profileOffset();
long profileOffset();
/**
* Check if the event should be added to a profiling transaction.
@@ -2,34 +2,35 @@ package io.ebeaninternal.api;
/**
* Event codes used in transaction profiling.
*
* These appear in verbose transaction profile logs.
*/
public interface TxnProfileEventCodes {
byte EVT_END = 0;
byte EVT_COMMIT = 1;
byte EVT_ROLLBACK = 2;
String EVT_COMMIT = "c";
String EVT_ROLLBACK = "r";
byte EVT_INSERT = 10;
byte EVT_UPDATE = 11;
byte EVT_DELETE = 12;
byte EVT_SOFT_DELETE = 13;
byte EVT_DELETE_PERMANENT = 14;
byte EVT_ORMUPDATE = 15;
byte FIND_UPDATE = 16;
byte FIND_DELETE = 17;
String EVT_INSERT = "i";
String EVT_UPDATE = "u";
String EVT_DELETE = "d";
String EVT_SOFT_DELETE = "ds";
String EVT_DELETE_PERMANENT = "dp";
String EVT_ORMUPDATE = "uo";
String FIND_UPDATE = "uq";
String FIND_DELETE = "dq";
byte EVT_UPDATESQL = 20;
byte EVT_CALLABLESQL = 21;
String EVT_UPDATESQL = "su";
String EVT_CALLABLESQL = "sc";
byte FIND_ONE = 30;
byte FIND_MANY = 31;
byte FIND_ITERATE = 34;
byte FIND_ID_LIST = 35;
byte FIND_ATTRIBUTE = 36;
byte FIND_COUNT = 37;
byte FIND_SUBQUERY = 38;
String FIND_ONE = "fo";
String FIND_MANY = "fm";
String FIND_ITERATE = "fe";
String FIND_ID_LIST = "fi";
String FIND_ATTRIBUTE = "fa";
String FIND_COUNT = "fc";
String FIND_SUBQUERY = "fs";
byte FIND_ONE_LAZY = 40;
byte FIND_MANY_LAZY = 41;
String FIND_MANY_LAZY = "lm";
String FIND_ONE_LAZY = "lo";
}
@@ -373,7 +373,7 @@ public class InternalConfiguration {
private SpiProfileHandler profileHandler() {
ProfilingConfig profilingConfig = serverConfig.getProfilingConfig();
if (!profilingConfig.isTransactionProfiling()) {
if (!profilingConfig.isEnabled()) {
return new NoopProfileHandler();
}
SpiProfileHandler handler = serverConfig.service(SpiProfileHandler.class);
@@ -21,8 +21,8 @@ public abstract class PersistRequest extends BeanRequest implements BatchPostExe
DELETE_PERMANENT(EVT_DELETE_PERMANENT),
UPDATESQL(EVT_UPDATESQL),
CALLABLESQL(EVT_CALLABLESQL);
byte profileEventId;
Type(byte profileEventId) {
String profileEventId;
Type(String profileEventId) {
this.profileEventId = profileEventId;
}
}
@@ -54,8 +54,8 @@ public abstract class PersistRequest extends BeanRequest implements BatchPostExe
*/
public abstract int executeNow();
void profileBase(byte event, int offset, short beanTypeId, int beanCount) {
transaction.profileStream().addEvent(event, offset, beanTypeId, beanCount);
void profileBase(String event, long offset, short beanTypeId, int beanCount) {
transaction.profileStream().addPersistEvent(event, offset, beanTypeId, beanCount);
}
@Override
@@ -144,7 +144,7 @@ public final class PersistRequestBean<T> extends PersistRequest implements BeanP
private long now;
private int profileOffset;
private long profileOffset;
/**
* Flag set when request is added to JDBC batch registered as a "getter callback" to automatically flush batch.
@@ -191,7 +191,7 @@ public final class PersistRequestBean<T> extends PersistRequest implements BeanP
* Add to profile as batched bean insert, update or delete.
*/
@Override
public void profile(int offset, int flushCount) {
public void profile(long offset, int flushCount) {
profileBase(type.profileEventId, offset, beanDescriptor.getProfileId(), flushCount);
}
@@ -40,7 +40,7 @@ public final class PersistRequestCallableSql extends PersistRequest {
}
@Override
public void profile(int offset, int flushCount) {
public void profile(long offset, int flushCount) {
profileBase(EVT_CALLABLESQL, offset, (short)0, flushCount);
}
@@ -33,7 +33,7 @@ public final class PersistRequestOrmUpdate extends PersistRequest {
}
@Override
public void profile(int offset, int flushCount) {
public void profile(long offset, int flushCount) {
profileBase(EVT_ORMUPDATE, offset, beanDescriptor.getProfileId(), flushCount);
}
@@ -39,7 +39,7 @@ public final class PersistRequestUpdateSql extends PersistRequest {
}
@Override
public void profile(int offset, int flushCount) {
public void profile(long offset, int flushCount) {
profileBase(EVT_UPDATESQL, offset, (short)0, flushCount);
}
@@ -33,5 +33,5 @@ public interface BatchPostExecute {
/**
* Add as event to the profiling.
*/
void profile(int offset, int batchSize);
void profile(long offset, int batchSize);
}
@@ -36,7 +36,7 @@ public class BatchedPstmt implements SpiProfileTransactionEvent {
private final SpiTransaction transaction;
private int profileStart;
private long profileStart;
/**
* Create with a given statement.
@@ -173,7 +173,7 @@ public class CQuery<T> implements DbReadContext, CancelableQuery, SpiProfileTran
private final Boolean readOnly;
private int profileOffset;
private long profileOffset;
private long startNano;
private long executionTimeMicros;
@@ -286,7 +286,7 @@ public class DefaultOrmQuery<T> implements SpiQuery<T> {
}
@Override
public byte profileEventId() {
public String profileEventId() {
switch (mode) {
case LAZYLOAD_BEAN: return FIND_ONE_LAZY;
case LAZYLOAD_MANY: return FIND_MANY_LAZY;
@@ -8,10 +8,11 @@ import io.ebeaninternal.api.SpiProfileHandler;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.FileWriter;
import java.io.IOException;
import java.io.Writer;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.time.format.DateTimeFormatterBuilder;
@@ -23,6 +24,7 @@ import java.util.concurrent.TimeUnit;
import static java.time.temporal.ChronoField.DAY_OF_MONTH;
import static java.time.temporal.ChronoField.HOUR_OF_DAY;
import static java.time.temporal.ChronoField.MILLI_OF_SECOND;
import static java.time.temporal.ChronoField.MINUTE_OF_HOUR;
import static java.time.temporal.ChronoField.MONTH_OF_YEAR;
import static java.time.temporal.ChronoField.SECOND_OF_MINUTE;
@@ -53,6 +55,8 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
.appendValue(HOUR_OF_DAY, 2)
.appendValue(MINUTE_OF_HOUR, 2)
.appendValue(SECOND_OF_MINUTE, 2)
.appendLiteral('-')
.appendValue(MILLI_OF_SECOND, 3)
.toFormatter();
}
@@ -71,6 +75,8 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
private final long profilesPerFile;
private final boolean verbose;
private volatile boolean shutdown;
private long profileCounter;
@@ -80,10 +86,11 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
*/
private int sleepBackoff;
private FileOutputStream out;
private Writer out;
public DefaultProfileHandler(ProfilingConfig config) {
this.minMicros = config.getMinimumTransactionMicros();
this.verbose = config.isVerbose();
this.minMicros = config.getMinimumMicros();
this.includeIds = config.getIncludeProfileIds();
this.profilesPerFile = config.getProfilesPerFile();
@@ -91,7 +98,7 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
// profiling and writing it to file(s)
this.executor = Executors.newSingleThreadExecutor();
this.dir = new File(config.getDirectory());
if (!dir.mkdirs()) {
if (!dir.exists() && !dir.mkdirs()) {
log.error("failed to mkdirs " + dir.getAbsolutePath());
}
incrementFile();
@@ -118,26 +125,28 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
}
if (includeIds.length == 0) {
return new ProfileStream(profileId);
return new DefaultProfileStream(profileId, verbose);
}
// check if we are profiling this specific transaction profileId, just
// perform linear search as this is expected to be a small array
for (int includeId : includeIds) {
if (includeId == profileId) {
return new ProfileStream(profileId);
return new DefaultProfileStream(profileId, verbose);
}
}
return null;
}
private void flushCurrentFile() {
if (out != null) {
try {
out.flush();
out.close();
} catch (IOException e) {
log.error("Failed to flush and close transaction profiling file ", e);
synchronized (this) {
if (out != null) {
try {
out.close();
out = null;
} catch (IOException e) {
log.error("Failed to flush and close transaction profiling file ", e);
}
}
}
}
@@ -146,13 +155,15 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
* Move to the next file to write to.
*/
private void incrementFile() {
flushCurrentFile();
try {
String now = DTF.format(LocalDateTime.now());
File file = new File(dir, "txprofile-" + now + ".tprofile");
out = new FileOutputStream(file);
} catch (FileNotFoundException e) {
log.error("Not expected", e);
synchronized (this) {
flushCurrentFile();
try {
String now = DTF.format(LocalDateTime.now());
File file = new File(dir, "txprofile-" + now + ".tprofile");
out = new BufferedWriter(new FileWriter(file));
} catch (IOException e) {
log.error("Not expected", e);
}
}
}
@@ -160,14 +171,19 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
* Main loop for polling the queue and processing profiling messages.
*/
private void collect() {
while (!shutdown) {
TransactionProfile profile = queue.poll();
if (profile == null) {
sleep();
try {
while (!shutdown) {
TransactionProfile profile = queue.poll();
if (profile == null) {
sleep();
} else if (include(profile)) {
write(profile);
} else if (include(profile)) {
write(profile);
}
}
flushCurrentFile();
} catch (Exception e) {
log.warn("Error on collect", e);
}
}
@@ -178,7 +194,24 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
try {
sleepBackoff = 0;
++profileCounter;
out.write(profile.getBytes());
StringBuilder sb = new StringBuilder(80);
// header
sb.append(profile.getStartTime()).append(' ')
.append(profile.getProfileId()).append(' ')
.append(profile.getTotalMicros()).append(' ');
// summary
appendSummary(profile, sb);
out.write(sb.toString());
if (verbose) {
out.write(' ');
out.write(profile.getData());
}
out.write('\n');
if (profileCounter % profilesPerFile == 0) {
incrementFile();
log.debug("profiled {} transactions", profileCounter);
@@ -188,6 +221,29 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
}
}
private void appendSummary(TransactionProfile profile, StringBuilder sb) {
TransactionProfile.Summary summary = profile.getSummary();
sb.append("z:").append(rate(profile.getTotalMicros(), (summary.persistCount + summary.queryCount))).append(' ');
sb.append("pr:").append(rate(summary.persistMicros, summary.persistBeans)).append(' ');
sb.append("qr:").append(rate(summary.queryMicros, summary.queryBeans)).append(' ');
sb.append("qa:").append(rate(summary.queryMicros, summary.queryCount)).append(' ');
sb.append("qm:").append(summary.queryMax).append(' ');
sb.append("qc:").append(summary.queryCount).append(' ');
sb.append("qt:").append(summary.queryMicros).append(' ');
sb.append("po:").append(summary.persistOneCount).append(' ');
sb.append("pb:").append(rate(summary.persistBeans, summary.persistCount)).append(' ');
sb.append("pc:").append(summary.persistCount).append(' ');
sb.append("pt:").append(summary.persistMicros);
}
private int rate(long micros, long count) {
return count < 1 ? 0 : (int) (micros / count);
}
/**
* Return true if the profile should be included (or false for ignored).
*/
@@ -231,8 +287,7 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
@Override
public void shutdown() {
shutdown = true;
log.trace("shutting down profiling consumer");
flushCurrentFile();
log.trace("shutting down");
try {
executor.shutdown();
if (!executor.awaitTermination(4, TimeUnit.SECONDS)) {
@@ -243,5 +298,6 @@ public class DefaultProfileHandler implements SpiProfileHandler, Plugin {
Thread.currentThread().interrupt();
log.warn("Interrupt on shutdown", e);
}
flushCurrentFile();
}
}
@@ -214,7 +214,7 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
}
@Override
public int profileOffset() {
public long profileOffset() {
return (profileStream == null) ? 0 : profileStream.offset();
}
@@ -948,7 +948,7 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
* Perform the actual rollback on the connection.
*/
protected void performRollback() throws SQLException {
int offset = profileOffset();
long offset = profileOffset();
connection.rollback();
if (profileStream != null) {
profileStream.addEvent(EVT_ROLLBACK, offset);
@@ -959,7 +959,7 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes {
* Perform the actual commit on the connection.
*/
protected void performCommit() throws SQLException {
int offset = profileOffset();
long offset = profileOffset();
connection.commit();
if (profileStream != null) {
profileStream.addEvent(EVT_COMMIT, offset);
@@ -1,102 +1,32 @@
package io.ebeaninternal.server.transaction;
import io.ebeaninternal.api.TxnProfileEventCodes;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.io.ByteArrayOutputStream;
import java.io.DataOutputStream;
import java.io.IOException;
/**
* A binary encoding of the transaction profiling events.
* Collects the events of a transaction being profiled.
*/
public class ProfileStream implements TxnProfileEventCodes {
private static final Logger logger = LoggerFactory.getLogger(ProfileStream.class);
private final int profId;
private final long startNanos;
private final DataOutputStream out;
private final ByteArrayOutputStream profileBuffer;
public ProfileStream(int profId) {
this.profId = profId;
this.startNanos = System.nanoTime();
this.profileBuffer = new ByteArrayOutputStream(200);
this.out = new DataOutputStream(profileBuffer);
try {
out.writeLong(System.currentTimeMillis());
out.writeInt(profId);
} catch (IOException e) {
throw new RuntimeException("Unexpected error starting transaction profiling", e);
}
}
public interface ProfileStream {
/**
* Return the time offset from the beginning of the transaction.
* Return the offset in micros from the start of the transaction.
*/
public int offset() {
// int max of 2,147,483,648 as micros = 35 minutes
// use 10_000 to get 100th of millis to max at 357 minutes (almost 6 hours)
// not micros so we can reasonably use int rather than long
return (int)((System.nanoTime() - startNanos) / 10_000L);
}
long offset();
/**
* Add the commit/rollback event.
* Add a query event.
*/
public void addEvent(byte event, int startOffset) {
try {
out.writeByte(event);
out.writeInt(startOffset);
out.writeInt(offset() - startOffset);
} catch (IOException e) {
logger.error("Error writing event to transaction profiling", e);
}
}
/**
* Add a query execution event.
*/
public void addQueryEvent(byte event, int offset, short beanTypeId, int beanCount, short queryId) {
add(event, offset, beanTypeId, beanCount, queryId);
}
void addQueryEvent(String event, long offset, short beanTypeId, int beanCount, short queryId);
/**
* Add a persist event.
*/
public void addEvent(byte event, int offset, short beanTypeId, int beanCount) {
add(event, offset, beanTypeId, beanCount, (short)0);
}
private void add(byte event, int offset, short beanTypeId, int beanCount, short queryId) {
try {
out.writeByte(event);
out.writeInt(offset);
out.writeInt(offset() - offset);
out.writeShort(beanTypeId);
out.writeInt(beanCount);
out.writeShort(queryId);
} catch (IOException e) {
logger.error("Error writing event to transaction profiling", e);
}
}
void addPersistEvent(String event, long offset, short beanTypeId, int beanCount);
/**
* End the transaction profiling.
* Add the commit/rollback event.
*/
public void end(TransactionManager manager) {
try {
long totalMicros = ((System.nanoTime() - startNanos) / 1_000L);
out.writeByte(EVT_END);
out.writeLong(totalMicros);
out.flush();
out.close();
manager.profileCollect(new TransactionProfile(profId, totalMicros, profileBuffer.toByteArray()));
} catch (IOException e) {
logger.error("Error flushing and collecting profiling", e);
}
}
void addEvent(String event, long startOffset);
/**
* Transaction completed collect the profiling information.
*/
void end(TransactionManager manager);
}
@@ -5,28 +5,44 @@ package io.ebeaninternal.server.transaction;
*/
public class TransactionProfile {
private long startTime;
/**
* The profileId of the transaction (On @Transactional explicitly or can be automatically set by enhancement).
*/
private final int profileId;
private int profileId;
/**
* The total execution time of the transaction (for filtering out small/short transactions).
*/
private final long totalMicros;
private long totalMicros;
/**
* The binary encoding of the transaction profiling events.
*/
private final byte[] bytes;
private String data;
private Summary summary;
/**
* Create with profileId, total micros and encoded profile data.
*/
public TransactionProfile(int profileId, long totalMicros, byte[] bytes) {
public TransactionProfile(long startTime, int profileId) {
this.startTime = startTime;
this.profileId = profileId;
this.totalMicros = totalMicros;
this.bytes = bytes;
this.summary = new Summary();
}
/**
* Construct for JSON tools.
*/
public TransactionProfile(){
}
/**
* Return the transaction start time.
*/
public long getStartTime() {
return startTime;
}
/**
@@ -46,7 +62,74 @@ public class TransactionProfile {
/**
* Return the profiling data in encoded form.
*/
public byte[] getBytes() {
return bytes;
public String getData() {
return data;
}
/**
* Set start time (for JSON tools).
*/
public void setStartTime(long startTime) {
this.startTime = startTime;
}
/**
* Set profileId (for JSON tools).
*/
public void setProfileId(int profileId) {
this.profileId = profileId;
}
/**
* Set total micros (for JSON tools).
*/
public void setTotalMicros(long totalMicros) {
this.totalMicros = totalMicros;
}
/**
* Set raw data (for JSON tools).
*/
public void setData(String data) {
this.data = data;
}
public Summary getSummary() {
return summary;
}
public void setSummary(Summary summary) {
this.summary = summary;
}
public static class Summary {
public long queryMicros;
public long queryCount;
public long queryBeans;
public long queryMax;
public long persistMicros;
public long persistCount;
public long persistBeans;
public long persistOneCount;
public long commitMicros;
void addPersist(long micros, int beanCount) {
persistMicros += micros;
persistBeans += beanCount;
persistCount++;
if (beanCount == 1) {
persistOneCount++;
}
}
void addQuery(long micros, int beanCount) {
queryMax = Math.max(queryMax, micros);
queryMicros += micros;
queryBeans += beanCount;
queryCount++;
}
}
}