From 55d66ae85114f1ca223c22109fff58e8cb530cba Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Thu, 26 Oct 2017 23:32:44 +1300 Subject: [PATCH] #1183 - Support transaction profiling, move away from binary encoding --- .../java/io/ebean/config/ProfilingConfig.java | 46 +++++-- .../ebeaninternal/api/ScopedTransaction.java | 2 +- .../java/io/ebeaninternal/api/SpiQuery.java | 8 +- .../io/ebeaninternal/api/SpiTransaction.java | 2 +- .../api/TxnProfileEventCodes.java | 45 +++---- .../server/core/InternalConfiguration.java | 2 +- .../server/core/PersistRequest.java | 8 +- .../server/core/PersistRequestBean.java | 4 +- .../core/PersistRequestCallableSql.java | 2 +- .../server/core/PersistRequestOrmUpdate.java | 2 +- .../server/core/PersistRequestUpdateSql.java | 2 +- .../server/persist/BatchPostExecute.java | 2 +- .../server/persist/BatchedPstmt.java | 2 +- .../io/ebeaninternal/server/query/CQuery.java | 2 +- .../server/querydefn/DefaultOrmQuery.java | 2 +- .../transaction/DefaultProfileHandler.java | 114 +++++++++++++----- .../server/transaction/JdbcTransaction.java | 6 +- .../server/transaction/ProfileStream.java | 96 ++------------- .../transaction/TransactionProfile.java | 99 +++++++++++++-- 19 files changed, 269 insertions(+), 177 deletions(-) diff --git a/src/main/java/io/ebean/config/ProfilingConfig.java b/src/main/java/io/ebean/config/ProfilingConfig.java index f0feb9c2c..f83a02378 100644 --- a/src/main/java/io/ebean/config/ProfilingConfig.java +++ b/src/main/java/io/ebean/config/ProfilingConfig.java @@ -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) { diff --git a/src/main/java/io/ebeaninternal/api/ScopedTransaction.java b/src/main/java/io/ebeaninternal/api/ScopedTransaction.java index 97926b104..a4028904f 100644 --- a/src/main/java/io/ebeaninternal/api/ScopedTransaction.java +++ b/src/main/java/io/ebeaninternal/api/ScopedTransaction.java @@ -81,7 +81,7 @@ public class ScopedTransaction implements SpiTransaction { } @Override - public int profileOffset() { + public long profileOffset() { return transaction.profileOffset(); } diff --git a/src/main/java/io/ebeaninternal/api/SpiQuery.java b/src/main/java/io/ebeaninternal/api/SpiQuery.java index c8dae18c7..6ecedb37b 100644 --- a/src/main/java/io/ebeaninternal/api/SpiQuery.java +++ b/src/main/java/io/ebeaninternal/api/SpiQuery.java @@ -105,13 +105,13 @@ public interface SpiQuery extends Query, 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 extends Query, 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. diff --git a/src/main/java/io/ebeaninternal/api/SpiTransaction.java b/src/main/java/io/ebeaninternal/api/SpiTransaction.java index 5f71919ff..66d7f1fc9 100644 --- a/src/main/java/io/ebeaninternal/api/SpiTransaction.java +++ b/src/main/java/io/ebeaninternal/api/SpiTransaction.java @@ -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. diff --git a/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java b/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java index 22657938f..0c17ad833 100644 --- a/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java +++ b/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java @@ -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"; } diff --git a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java index 681086116..68e8f1a21 100644 --- a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java +++ b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java @@ -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); diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequest.java b/src/main/java/io/ebeaninternal/server/core/PersistRequest.java index d8ad904fb..c74515a7c 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequest.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequest.java @@ -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 diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java index 2eb53569b..3cfca39d7 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java @@ -144,7 +144,7 @@ public final class PersistRequestBean 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 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); } diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java index 651d0000c..7f203678e 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java @@ -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); } diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java index 665de1e24..4a55f9db6 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java @@ -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); } diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java index bf8f038d4..52add1204 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java @@ -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); } diff --git a/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java b/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java index 7e5579219..1f631cd79 100644 --- a/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java +++ b/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java @@ -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); } diff --git a/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java b/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java index 211c56832..c15742ce2 100644 --- a/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java +++ b/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java @@ -36,7 +36,7 @@ public class BatchedPstmt implements SpiProfileTransactionEvent { private final SpiTransaction transaction; - private int profileStart; + private long profileStart; /** * Create with a given statement. diff --git a/src/main/java/io/ebeaninternal/server/query/CQuery.java b/src/main/java/io/ebeaninternal/server/query/CQuery.java index 3aef94ed9..95c3d9767 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQuery.java +++ b/src/main/java/io/ebeaninternal/server/query/CQuery.java @@ -173,7 +173,7 @@ public class CQuery implements DbReadContext, CancelableQuery, SpiProfileTran private final Boolean readOnly; - private int profileOffset; + private long profileOffset; private long startNano; private long executionTimeMicros; diff --git a/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java b/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java index 3f41c6830..e52e7ad3a 100644 --- a/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java +++ b/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java @@ -286,7 +286,7 @@ public class DefaultOrmQuery implements SpiQuery { } @Override - public byte profileEventId() { + public String profileEventId() { switch (mode) { case LAZYLOAD_BEAN: return FIND_ONE_LAZY; case LAZYLOAD_MANY: return FIND_MANY_LAZY; diff --git a/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java b/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java index 903b69e1c..5f353b673 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java +++ b/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java @@ -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(); } } diff --git a/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java b/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java index e7d77cb3c..8dfc4abf1 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java +++ b/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java @@ -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); diff --git a/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java b/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java index 691f6baa1..563fa7461 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java +++ b/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java @@ -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); } diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java index bedf30047..e55be367a 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java @@ -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++; + } } }