From 7ebef518595a6423d5a060780aa202b8ea39c1ea Mon Sep 17 00:00:00 2001 From: rob bygrave Date: Wed, 25 Oct 2017 01:07:00 +1300 Subject: [PATCH] #1183 - ENH: Add support for transaction profiling --- .gitignore | 2 +- pom.xml | 4 +- src/main/java/io/ebean/Query.java | 11 + src/main/java/io/ebean/TxScope.java | 17 ++ .../java/io/ebean/config/ProfilingConfig.java | 126 +++++++++ .../java/io/ebean/config/ServerConfig.java | 18 ++ src/main/java/io/ebean/plugin/BeanType.java | 5 + .../ebeaninternal/api/ScopedTransaction.java | 16 ++ .../ebeaninternal/api/SpiProfileHandler.java | 30 +++ .../api/SpiProfileTransactionEvent.java | 12 + .../java/io/ebeaninternal/api/SpiQuery.java | 52 ++-- .../io/ebeaninternal/api/SpiTransaction.java | 16 ++ .../api/TxnProfileEventCodes.java | 35 +++ .../server/core/DefaultServer.java | 10 +- .../server/core/InternalConfiguration.java | 19 +- .../server/core/PersistRequest.java | 19 +- .../server/core/PersistRequestBean.java | 30 ++- .../core/PersistRequestCallableSql.java | 5 + .../server/core/PersistRequestOrmUpdate.java | 5 + .../server/core/PersistRequestUpdateSql.java | 5 + .../server/deploy/BeanDescriptor.java | 12 +- .../server/deploy/BeanDescriptorManager.java | 21 +- .../deploy/meta/DeployBeanDescriptor.java | 16 ++ .../server/persist/BatchPostExecute.java | 4 + .../server/persist/BatchedPstmt.java | 24 +- .../server/persist/PstmtFactory.java | 4 +- .../server/persist/dml/DmlHandler.java | 2 +- .../io/ebeaninternal/server/query/CQuery.java | 13 +- .../server/querydefn/DefaultOrmQuery.java | 25 ++ .../AutoCommitTransactionManager.java | 2 +- .../transaction/DefaultProfileHandler.java | 247 ++++++++++++++++++ .../DocStoreTransactionManager.java | 6 +- .../ExplicitTransactionManager.java | 2 +- .../server/transaction/JdbcTransaction.java | 48 +++- .../transaction/NoopProfileHandler.java | 20 ++ .../server/transaction/ProfileStream.java | 102 ++++++++ .../transaction/TransactionFactory.java | 2 +- .../transaction/TransactionFactoryBasic.java | 10 +- .../transaction/TransactionFactoryTenant.java | 10 +- .../transaction/TransactionManager.java | 20 +- .../TransactionManagerOptions.java | 9 +- .../transaction/TransactionProfile.java | 52 ++++ src/main/resources/META-INF/ebean-version.mf | 1 + .../DefaultProfileHandlerTest.java | 34 +++ .../org/ebeantest/LoggedSqlCollector.java | 6 +- ...estPersistenceContextScopeUsingOrders.java | 2 +- 46 files changed, 1063 insertions(+), 68 deletions(-) create mode 100644 src/main/java/io/ebean/config/ProfilingConfig.java create mode 100644 src/main/java/io/ebeaninternal/api/SpiProfileHandler.java create mode 100644 src/main/java/io/ebeaninternal/api/SpiProfileTransactionEvent.java create mode 100644 src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java create mode 100644 src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java create mode 100644 src/main/java/io/ebeaninternal/server/transaction/NoopProfileHandler.java create mode 100644 src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java create mode 100644 src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java create mode 100644 src/main/resources/META-INF/ebean-version.mf create mode 100644 src/test/java/io/ebeaninternal/server/transaction/DefaultProfileHandlerTest.java diff --git a/.gitignore b/.gitignore index 1bd192a39..0d96b2f95 100644 --- a/.gitignore +++ b/.gitignore @@ -13,7 +13,7 @@ ebean-profiling*.xml /db /mydb.db !src/test/ddl-review/*.sql - +profiling/ # Intellij project files *.iml diff --git a/pom.xml b/pom.xml index 267291237..31d5c2130 100644 --- a/pom.xml +++ b/pom.xml @@ -9,7 +9,7 @@ io.ebean ebean - 11.2.4-SNAPSHOT + 11.3.1-SNAPSHOT jar ebean @@ -87,7 +87,7 @@ io.ebean ebean-annotation - 3.1 + 3.2 diff --git a/src/main/java/io/ebean/Query.java b/src/main/java/io/ebean/Query.java index 60a0c341f..b69bc778e 100644 --- a/src/main/java/io/ebean/Query.java +++ b/src/main/java/io/ebean/Query.java @@ -1331,6 +1331,17 @@ public interface Query { return setUseQueryCache(enabled ? CacheMode.ON : CacheMode.OFF); } + /** + * Set an id to identify this query for profiling purposes. + *

+ * The profileId is expected to be unique for a given bean type. + *

+ *

+ * Note that the profileId is treated as a short internally and has a MAX value of 32,767. + *

+ */ + Query setProfileId(int profileId); + /** * Set to true if this query should execute against the doc store. *

diff --git a/src/main/java/io/ebean/TxScope.java b/src/main/java/io/ebean/TxScope.java index f0deca42d..6cbfee3ce 100644 --- a/src/main/java/io/ebean/TxScope.java +++ b/src/main/java/io/ebean/TxScope.java @@ -25,6 +25,8 @@ import java.util.concurrent.Callable; */ public final class TxScope { + int profileId; + TxType type; String serverName; @@ -168,6 +170,21 @@ public final class TxScope { return this; } + /** + * Return the transaction profile id. + */ + public int getProfileId() { + return profileId; + } + + /** + * Set the transaction profile id. + */ + public TxScope setProfileId(int profileId) { + this.profileId = profileId; + return this; + } + /** * Return the batch mode. */ diff --git a/src/main/java/io/ebean/config/ProfilingConfig.java b/src/main/java/io/ebean/config/ProfilingConfig.java new file mode 100644 index 000000000..f0feb9c2c --- /dev/null +++ b/src/main/java/io/ebean/config/ProfilingConfig.java @@ -0,0 +1,126 @@ +package io.ebean.config; + +/** + * Configuration for transaction profiling. + */ +public class ProfilingConfig { + + /** + * When true transaction profiling is enabled. + */ + private boolean transactionProfiling; + + /** + * The minimum transaction execution time to be included in profiling. + */ + private long minimumTransactionMicros; + + /** + * A specific set of profileIds to include in profiling. + */ + private int[] includeProfileIds = {}; + + /** + * The number of profiles to write per file. + */ + private long profilesPerFile = 1000; + + private String directory = "profiling"; + + /** + * Return true if transaction profiling is enabled. + */ + public boolean isTransactionProfiling() { + return transactionProfiling; + } + + /** + * Set to true to enable transaction profiling. + */ + public void setTransactionProfiling(boolean transactionProfiling) { + this.transactionProfiling = transactionProfiling; + } + + /** + * Return the minimum transaction execution to be included in profiling. + */ + public long getMinimumTransactionMicros() { + return minimumTransactionMicros; + } + + /** + * Set the minimum transaction execution to be included in profiling. + */ + public void setMinimumTransactionMicros(long minimumTransactionMicros) { + this.minimumTransactionMicros = minimumTransactionMicros; + } + + /** + * Return the specific set of profileIds to include in profiling. + * When not set all transactions with profileIds are included. + */ + public int[] getIncludeProfileIds() { + return includeProfileIds; + } + + /** + * Set a specific set of profileIds to include in profiling. + * When not set all transactions with profileIds are included. + */ + public void setIncludeProfileIds(int[] includeProfileIds) { + this.includeProfileIds = includeProfileIds; + } + + /** + * Return the number of profiles to write to a single file. + */ + public long getProfilesPerFile() { + return profilesPerFile; + } + + /** + * Set the number of profiles to write to a single file. + */ + public void setProfilesPerFile(long profilesPerFile) { + this.profilesPerFile = profilesPerFile; + } + + /** + * Return the directory profiling files are put into. + */ + public String getDirectory() { + return directory; + } + + /** + * Set the directory profiling files are put into. + */ + public void setDirectory(String directory) { + this.directory = directory; + } + + /** + * Load setting from properties. + */ + public void loadSettings(PropertiesWrapper p, String name) { + transactionProfiling = p.getBoolean("profiling.transactionProfiling", transactionProfiling); + directory = p.get("profiling.directory", directory); + profilesPerFile = p.getLong("profiling.profilesPerFile", profilesPerFile); + minimumTransactionMicros = p.getLong("profiling.minimumTransactionMicros", minimumTransactionMicros); + + String includeIds = p.get("profiling.includeProfileIds"); + if (includeIds != null) { + includeProfileIds = parseIds(includeIds); + } + } + + private int[] parseIds(String includeIds) { + + String[] ids = includeIds.split(","); + int[] vals = new int[ids.length]; + for (int i = 0; i < ids.length; i++) { + vals[i] = Integer.parseInt(ids[i]); + } + return vals; + } +} diff --git a/src/main/java/io/ebean/config/ServerConfig.java b/src/main/java/io/ebean/config/ServerConfig.java index d37e071d2..f2d41b0ea 100644 --- a/src/main/java/io/ebean/config/ServerConfig.java +++ b/src/main/java/io/ebean/config/ServerConfig.java @@ -450,6 +450,9 @@ public class ServerConfig { */ private SlowQueryListener slowQueryListener; + + private ProfilingConfig profilingConfig = new ProfilingConfig(); + /** * Construct a Server Configuration for programmatically creating an EbeanServer. */ @@ -1021,6 +1024,20 @@ public class ServerConfig { this.readAuditPrepare = readAuditPrepare; } + /** + * Return the configuration for profiling. + */ + public ProfilingConfig getProfilingConfig() { + return profilingConfig; + } + + /** + * Set the configuration for profiling. + */ + public void setProfilingConfig(ProfilingConfig profilingConfig) { + this.profilingConfig = profilingConfig; + } + /** * Return the DB migration configuration. */ @@ -2546,6 +2563,7 @@ public class ServerConfig { */ protected void loadSettings(PropertiesWrapper p) { + profilingConfig.loadSettings(p, name); migrationConfig.loadSettings(p, name); boolean quotedIdentifiers = p.getBoolean("allQuotedIdentifiers", allQuotedIdentifiers); diff --git a/src/main/java/io/ebean/plugin/BeanType.java b/src/main/java/io/ebean/plugin/BeanType.java index 1bb5c0bfa..2f00cd0af 100644 --- a/src/main/java/io/ebean/plugin/BeanType.java +++ b/src/main/java/io/ebean/plugin/BeanType.java @@ -20,6 +20,11 @@ public interface BeanType { */ String getName(); + /** + * Return the profileId of the bean type. + */ + short getProfileId(); + /** * Return the full name of the bean type. */ diff --git a/src/main/java/io/ebeaninternal/api/ScopedTransaction.java b/src/main/java/io/ebeaninternal/api/ScopedTransaction.java index 087cfabc5..97926b104 100644 --- a/src/main/java/io/ebeaninternal/api/ScopedTransaction.java +++ b/src/main/java/io/ebeaninternal/api/ScopedTransaction.java @@ -10,6 +10,7 @@ import io.ebeaninternal.server.core.PersistDeferredRelationship; import io.ebeaninternal.server.core.PersistRequest; import io.ebeaninternal.server.core.PersistRequestBean; import io.ebeaninternal.server.persist.BatchControl; +import io.ebeaninternal.server.transaction.ProfileStream; import io.ebeanservice.docstore.api.DocStoreTransaction; import javax.persistence.PersistenceException; @@ -79,6 +80,21 @@ public class ScopedTransaction implements SpiTransaction { } } + @Override + public int profileOffset() { + return transaction.profileOffset(); + } + + @Override + public void profileEvent(SpiProfileTransactionEvent event) { + transaction.profileEvent(event); + } + + @Override + public ProfileStream profileStream() { + return transaction.profileStream(); + } + @Override public void setTenantId(Object tenantId) { transaction.setTenantId(tenantId); diff --git a/src/main/java/io/ebeaninternal/api/SpiProfileHandler.java b/src/main/java/io/ebeaninternal/api/SpiProfileHandler.java new file mode 100644 index 000000000..e5008a428 --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/SpiProfileHandler.java @@ -0,0 +1,30 @@ +package io.ebeaninternal.api; + +import io.ebeaninternal.server.transaction.ProfileStream; +import io.ebeaninternal.server.transaction.TransactionProfile; + +/** + * Handle the logging or processing of transaction profiling information that is collected. + */ +public interface SpiProfileHandler { + + /** + * Process the collected transaction profiling information. + *

+ * Note that profileId and totalMicros are part of the profilingData but passed separately as the handler + * may filter what it processed based on this information (ignore short transactions, only process specific + * profileId transactions etc). + *

+ * + * @param transactionProfile The transaction profile that has just been collected + */ + void collectTransactionProfile(TransactionProfile transactionProfile); + + /** + * Create a profiling stream if we are profiling this transaction. + * Return null if we are not profiling this transaction. + * + * @param profileId The transaction profileId + */ + ProfileStream createProfileStream(int profileId); +} diff --git a/src/main/java/io/ebeaninternal/api/SpiProfileTransactionEvent.java b/src/main/java/io/ebeaninternal/api/SpiProfileTransactionEvent.java new file mode 100644 index 000000000..8c8322627 --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/SpiProfileTransactionEvent.java @@ -0,0 +1,12 @@ +package io.ebeaninternal.api; + +/** + * Event that adds to a profiling transaction. + */ +public interface SpiProfileTransactionEvent { + + /** + * Add the event information to the profiling transaction. + */ + void profile(); +} diff --git a/src/main/java/io/ebeaninternal/api/SpiQuery.java b/src/main/java/io/ebeaninternal/api/SpiQuery.java index 3d73b9574..c8dae18c7 100644 --- a/src/main/java/io/ebeaninternal/api/SpiQuery.java +++ b/src/main/java/io/ebeaninternal/api/SpiQuery.java @@ -29,7 +29,7 @@ import java.util.Set; /** * Object Relational query - Internal extension to Query object. */ -public interface SpiQuery extends Query { +public interface SpiQuery extends Query, TxnProfileEventCodes { enum Mode { NORMAL(false), LAZYLOAD_MANY(false), LAZYLOAD_BEAN(true), REFRESH_BEAN(true); @@ -53,57 +53,67 @@ public interface SpiQuery extends Query { /** * Find by Id or unique returning a single bean. */ - BEAN, - - /** - * Find iterate type query - findEach(), findIterate() etc. - */ - ITERATE, + BEAN(FIND_ONE), /** * Find returning a List. */ - LIST, + LIST(FIND_MANY), /** * Find returning a Set. */ - SET, + SET(FIND_MANY), /** * Find returning a Map. */ - MAP, + MAP(FIND_MANY), + + /** + * Find iterate type query - findEach(), findIterate() etc. + */ + ITERATE(FIND_ITERATE), /** * Find the Id's. */ - ID_LIST, + ID_LIST(FIND_ID_LIST), /** * Find single attribute. */ - ATTRIBUTE, + ATTRIBUTE(FIND_ATTRIBUTE), /** * Find rowCount. */ - COUNT, + COUNT(FIND_COUNT), /** * A subquery used as part of a where clause. */ - SUBQUERY, + SUBQUERY(FIND_SUBQUERY), /** * Delete query. */ - DELETE, + DELETE(FIND_DELETE), /** * Update query. */ - UPDATE, + UPDATE(FIND_UPDATE); + + byte profileEventId; + + Type(byte profileEventId) { + this.profileEventId = profileEventId; + } + + public byte profileEventId() { + return profileEventId; + } } enum TemporalMode { @@ -140,6 +150,16 @@ public interface SpiQuery extends Query { } } + /** + * Return the profile event id based on query mode and type. + */ + byte profileEventId(); + + /** + * Return the id used to identify a particular query for the given bean type. + */ + short getProfileId(); + /** * Check for a single "equal to" expression for the Id. */ diff --git a/src/main/java/io/ebeaninternal/api/SpiTransaction.java b/src/main/java/io/ebeaninternal/api/SpiTransaction.java index f9e4ed399..5f71919ff 100644 --- a/src/main/java/io/ebeaninternal/api/SpiTransaction.java +++ b/src/main/java/io/ebeaninternal/api/SpiTransaction.java @@ -9,6 +9,7 @@ import io.ebeaninternal.server.core.PersistDeferredRelationship; import io.ebeaninternal.server.core.PersistRequest; import io.ebeaninternal.server.core.PersistRequestBean; import io.ebeaninternal.server.persist.BatchControl; +import io.ebeaninternal.server.transaction.ProfileStream; import io.ebeanservice.docstore.api.DocStoreTransaction; import javax.persistence.PersistenceException; @@ -282,4 +283,19 @@ public interface SpiTransaction extends Transaction { * Return the current Tenant Id. */ Object getTenantId(); + + /** + * Return the offset time from the start of the transaction. + */ + int profileOffset(); + + /** + * Check if the event should be added to a profiling transaction. + */ + void profileEvent(SpiProfileTransactionEvent event); + + /** + * Return the stream that profiling events are written to. + */ + ProfileStream profileStream(); } diff --git a/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java b/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java new file mode 100644 index 000000000..22657938f --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/TxnProfileEventCodes.java @@ -0,0 +1,35 @@ +package io.ebeaninternal.api; + +/** + * Event codes used in transaction profiling. + */ +public interface TxnProfileEventCodes { + + byte EVT_END = 0; + byte EVT_COMMIT = 1; + byte EVT_ROLLBACK = 2; + + 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; + + byte EVT_UPDATESQL = 20; + byte EVT_CALLABLESQL = 21; + + 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; + + byte FIND_ONE_LAZY = 40; + byte FIND_MANY_LAZY = 41; + +} diff --git a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java index aca0e3758..cf476a129 100644 --- a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java +++ b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java @@ -659,7 +659,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { @Override public Transaction createTransaction() { - return transactionManager.createTransaction(true, -1); + return transactionManager.createTransaction(0,true, -1); } /** @@ -671,7 +671,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { @Override public Transaction createTransaction(TxIsolation isolation) { - return transactionManager.createTransaction(true, isolation.getLevel()); + return transactionManager.createTransaction(0,true, isolation.getLevel()); } @Override @@ -796,7 +796,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { if (isolation != null) { isoLevel = isolation.getLevel(); } - t = transactionManager.createTransaction(true, isoLevel); + t = transactionManager.createTransaction(txScope.getProfileId(), true, isoLevel); // note ScopeTrans.onFinally() restores the suspended transaction transactionScopeManager.replace(t); } @@ -842,7 +842,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { @Override public Transaction beginTransaction(TxIsolation isolation) { // start an explicit transaction - SpiTransaction t = transactionManager.createTransaction(true, isolation.getLevel()); + SpiTransaction t = transactionManager.createTransaction(0,true, isolation.getLevel()); try { transactionScopeManager.set(t); } catch (PersistenceException existingTransactionError) { @@ -2094,7 +2094,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { @Override public SpiTransaction beginServerTransaction() { - SpiTransaction t = transactionManager.createTransaction(false, -1); + SpiTransaction t = transactionManager.createTransaction(0,false, -1); transactionScopeManager.set(t); return t; } diff --git a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java index 26c1cac76..681086116 100644 --- a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java +++ b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java @@ -5,6 +5,7 @@ import io.ebean.ExpressionFactory; import io.ebean.annotation.Platform; import io.ebean.cache.ServerCacheManager; import io.ebean.config.ExternalTransactionManager; +import io.ebean.config.ProfilingConfig; import io.ebean.config.ServerConfig; import io.ebean.config.dbplatform.DatabasePlatform; import io.ebean.config.dbplatform.DbHistorySupport; @@ -19,6 +20,7 @@ import io.ebean.plugin.SpiServer; import io.ebeaninternal.api.SpiBackgroundExecutor; import io.ebeaninternal.api.SpiEbeanServer; import io.ebeaninternal.api.SpiJsonContext; +import io.ebeaninternal.api.SpiProfileHandler; import io.ebeaninternal.dbmigration.DbOffline; import io.ebeaninternal.server.autotune.AutoTuneService; import io.ebeaninternal.server.autotune.service.AutoTuneServiceFactory; @@ -49,11 +51,13 @@ import io.ebeaninternal.server.readaudit.DefaultReadAuditPrepare; import io.ebeaninternal.server.text.json.DJsonContext; import io.ebeaninternal.server.transaction.AutoCommitTransactionManager; import io.ebeaninternal.server.transaction.DataSourceSupplier; +import io.ebeaninternal.server.transaction.DefaultProfileHandler; import io.ebeaninternal.server.transaction.DefaultTransactionScopeManager; import io.ebeaninternal.server.transaction.DocStoreTransactionManager; import io.ebeaninternal.server.transaction.ExplicitTransactionManager; import io.ebeaninternal.server.transaction.ExternalTransactionScopeManager; import io.ebeaninternal.server.transaction.JtaTransactionManager; +import io.ebeaninternal.server.transaction.NoopProfileHandler; import io.ebeaninternal.server.transaction.TransactionManager; import io.ebeaninternal.server.transaction.TransactionManagerOptions; import io.ebeaninternal.server.transaction.TransactionScopeManager; @@ -352,7 +356,7 @@ public class InternalConfiguration { TransactionManagerOptions options = new TransactionManagerOptions(localL2, serverConfig, clusterManager, backgroundExecutor, - indexUpdateProcessor, beanDescriptorManager, dataSource()); + indexUpdateProcessor, beanDescriptorManager, dataSource(), profileHandler()); if (serverConfig.isExplicitTransactionBeginMode()) { return new ExplicitTransactionManager(options); @@ -366,6 +370,19 @@ public class InternalConfiguration { return new TransactionManager(options); } + private SpiProfileHandler profileHandler() { + + ProfilingConfig profilingConfig = serverConfig.getProfilingConfig(); + if (!profilingConfig.isTransactionProfiling()) { + return new NoopProfileHandler(); + } + SpiProfileHandler handler = serverConfig.service(SpiProfileHandler.class); + if (handler == null) { + handler = new DefaultProfileHandler(profilingConfig); + } + return plugin(handler); + } + /** * Return the DataSource supplier based on the tenancy mode. */ diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequest.java b/src/main/java/io/ebeaninternal/server/core/PersistRequest.java index cddf3db1d..d8ad904fb 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequest.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequest.java @@ -2,6 +2,7 @@ package io.ebeaninternal.server.core; import io.ebeaninternal.api.SpiEbeanServer; import io.ebeaninternal.api.SpiTransaction; +import io.ebeaninternal.api.TxnProfileEventCodes; import io.ebeaninternal.server.persist.BatchControl; import io.ebeaninternal.server.persist.BatchPostExecute; import io.ebeaninternal.server.persist.BatchedSqlException; @@ -10,10 +11,20 @@ import io.ebeaninternal.server.persist.PersistExecute; /** * Wraps all the objects used to persist a bean. */ -public abstract class PersistRequest extends BeanRequest implements BatchPostExecute { +public abstract class PersistRequest extends BeanRequest implements BatchPostExecute, TxnProfileEventCodes { public enum Type { - INSERT, UPDATE, DELETE, SOFT_DELETE, DELETE_PERMANENT, UPDATESQL, CALLABLESQL + INSERT(EVT_INSERT), + UPDATE(EVT_UPDATE), + DELETE(EVT_DELETE), + SOFT_DELETE(EVT_SOFT_DELETE), + DELETE_PERMANENT(EVT_DELETE_PERMANENT), + UPDATESQL(EVT_UPDATESQL), + CALLABLESQL(EVT_CALLABLESQL); + byte profileEventId; + Type(byte profileEventId) { + this.profileEventId = profileEventId; + } } boolean persistCascade; @@ -43,6 +54,10 @@ 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); + } + @Override public boolean isLogSql() { return transaction.isLogSql(); diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java index b36ecbf5a..bc7cc848e 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java @@ -12,6 +12,7 @@ import io.ebean.event.changelog.BeanChange; import io.ebeaninternal.api.ConcurrencyMode; import io.ebeaninternal.api.SpiEbeanServer; import io.ebeaninternal.api.SpiTransaction; +import io.ebeaninternal.api.SpiProfileTransactionEvent; import io.ebeaninternal.api.TransactionEvent; import io.ebeaninternal.server.cache.CacheChangeSet; import io.ebeaninternal.server.deploy.BeanDescriptor; @@ -40,7 +41,7 @@ import java.util.Set; /** * PersistRequest for insert update or delete of a bean. */ -public final class PersistRequestBean extends PersistRequest implements BeanPersistRequest, DocStoreUpdate, PreGetterCallback { +public final class PersistRequestBean extends PersistRequest implements BeanPersistRequest, DocStoreUpdate, PreGetterCallback, SpiProfileTransactionEvent { private final BeanManager beanManager; @@ -143,6 +144,8 @@ public final class PersistRequestBean extends PersistRequest implements BeanP private long now; + private int profileOffset; + /** * Flag set when request is added to JDBC batch registered as a "getter callback" to automatically flush batch. */ @@ -184,6 +187,14 @@ public final class PersistRequestBean extends PersistRequest implements BeanP initGeneratedProperties(); } + /** + * Add to profile as batched bean insert, update or delete. + */ + @Override + public void profile(int offset, int flushCount) { + profileBase(type.profileEventId, offset, beanDescriptor.getProfileId(), flushCount); + } + /** * Return the document store event that should be used for this request. *

@@ -753,13 +764,20 @@ public final class PersistRequestBean extends PersistRequest implements BeanP return control.executeOrQueue(this, true); } else { - return executeNow(); + return executeNoBatch(); } } catch (BatchedSqlException e) { throw transaction.translate(e.getMessage(), e.getCause()); } } + private int executeNoBatch() { + profileOffset = transaction.profileOffset(); + int result = executeNow(); + transaction.profileEvent(this); + return result; + } + /** * Set the generated key back to the bean. Only used for inserts with getGeneratedKeys. */ @@ -1184,4 +1202,12 @@ public final class PersistRequestBean extends PersistRequest implements BeanP public boolean isStatelessUpdate() { return statelessUpdate; } + + /** + * Add to profile as single bean insert, update or delete (not batched). + */ + @Override + public void profile() { + profileBase(type.profileEventId, profileOffset, beanDescriptor.getProfileId(), 1); + } } diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java index afcc0ebd3..651d0000c 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestCallableSql.java @@ -39,6 +39,11 @@ public final class PersistRequestCallableSql extends PersistRequest { this.callableSql = (SpiCallableSql) cs; } + @Override + public void profile(int offset, int flushCount) { + profileBase(EVT_CALLABLESQL, offset, (short)0, flushCount); + } + @Override public int executeOrQueue() { return executeStatement(); diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java index 92818330b..665de1e24 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestOrmUpdate.java @@ -32,6 +32,11 @@ public final class PersistRequestOrmUpdate extends PersistRequest { this.ormUpdate = ormUpdate; } + @Override + public void profile(int offset, int flushCount) { + profileBase(EVT_ORMUPDATE, offset, beanDescriptor.getProfileId(), flushCount); + } + public BeanDescriptor getBeanDescriptor() { return beanDescriptor; } diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java index 80488c48e..bf8f038d4 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestUpdateSql.java @@ -38,6 +38,11 @@ public final class PersistRequestUpdateSql extends PersistRequest { this.updateSql = (SpiSqlUpdate) updateSql; } + @Override + public void profile(int offset, int flushCount) { + profileBase(EVT_UPDATESQL, offset, (short)0, flushCount); + } + @Override public int executeNow() { return persistExecute.executeSqlUpdate(this); diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java index 306940797..1bd8f7392 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java @@ -114,6 +114,8 @@ public class BeanDescriptor implements MetaBeanInfo, BeanType { private final Map namedQuery; + private final short profileBeanId; + public enum EntityType { ORM, EMBEDDED, VIEW, SQL, DOC } @@ -406,7 +408,7 @@ public class BeanDescriptor implements MetaBeanInfo, BeanType { this.name = InternString.intern(deploy.getName()); this.baseTableAlias = "t0"; this.fullName = InternString.intern(deploy.getFullName()); - + this.profileBeanId = deploy.getProfileId(); this.beanType = deploy.getBeanType(); this.rootBeanType = PersistenceContextUtil.root(beanType); this.prototypeEntityBean = createPrototypeEntityBean(beanType); @@ -528,6 +530,14 @@ public class BeanDescriptor implements MetaBeanInfo, BeanType { } } + /** + * Return the id used in profiling to identify the bean type. + */ + @Override + public short getProfileId() { + return profileBeanId; + } + /** * Derive an array of property positions for properties that are initialised in the constructor. * These properties need to be unloaded when populating beans for queries. diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java index 62d8551e9..1e5a22a1e 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java @@ -79,6 +79,7 @@ import java.util.HashSet; import java.util.List; import java.util.Map; import java.util.Set; +import java.util.stream.Collectors; /** * Creates BeanDescriptors. @@ -325,6 +326,7 @@ public class BeanDescriptorManager implements BeanDescriptorMap { readEntityBeanTable(); readEntityDeploymentAssociations(); readInheritedIdGenerators(); + setProfileIds(); // creates the BeanDescriptors readEntityRelationships(); @@ -727,6 +729,23 @@ public class BeanDescriptorManager implements BeanDescriptorMap { } } + /** + * Set profileIds based on descriptor full name order. + */ + private void setProfileIds() { + + List> deployDescriptors = deployInfoMap.values().stream() + .map(DeployBeanInfo::getDescriptor) + .collect(Collectors.toList()); + + deployDescriptors.sort(Comparator.comparing(DeployBeanDescriptor::getFullName)); + + short id = 0; + for (DeployBeanDescriptor desc : deployDescriptors) { + desc.setProfileId(++id); + } + } + /** * Create the BeanTable from the deployment information gathered so far. */ @@ -1044,7 +1063,7 @@ public class BeanDescriptorManager implements BeanDescriptorMap { prop.setUnidirectional(); return; } - + if (!findMappedBy(prop)) { makeUnidirectional(info, prop); return; diff --git a/src/main/java/io/ebeaninternal/server/deploy/meta/DeployBeanDescriptor.java b/src/main/java/io/ebeaninternal/server/deploy/meta/DeployBeanDescriptor.java index 87420edf7..fa09cd587 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/meta/DeployBeanDescriptor.java +++ b/src/main/java/io/ebeaninternal/server/deploy/meta/DeployBeanDescriptor.java @@ -204,6 +204,8 @@ public class DeployBeanDescriptor { private List idProperties; + private short profileId; + /** * Construct the BeanDescriptor. */ @@ -620,6 +622,20 @@ public class DeployBeanDescriptor { setBaseTable(new TableName(viewName), "", ""); } + /** + * Set the profileId to identity this bean type. + */ + public void setProfileId(short profileId) { + this.profileId = profileId; + } + + /** + * Return the profileId to identify this bean type. + */ + public short getProfileId() { + return profileId; + } + /** * Set the base table. Only properties mapped to the base table are by default persisted. */ diff --git a/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java b/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java index b35a445f0..7e5579219 100644 --- a/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java +++ b/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java @@ -30,4 +30,8 @@ public interface BatchPostExecute { */ void postExecute(); + /** + * Add as event to the profiling. + */ + void profile(int 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 deddb087f..211c56832 100644 --- a/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java +++ b/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java @@ -1,5 +1,8 @@ package io.ebeaninternal.server.persist; +import io.ebeaninternal.api.SpiTransaction; +import io.ebeaninternal.api.SpiProfileTransactionEvent; + import java.sql.PreparedStatement; import java.sql.ResultSet; import java.sql.SQLException; @@ -12,7 +15,7 @@ import java.util.ArrayList; * This can hold CallableStatements as well. *

*/ -public class BatchedPstmt { +public class BatchedPstmt implements SpiProfileTransactionEvent { /** * The underlying statement. @@ -31,13 +34,18 @@ public class BatchedPstmt { private final String sql; + private final SpiTransaction transaction; + + private int profileStart; + /** * Create with a given statement. */ - public BatchedPstmt(PreparedStatement pstmt, boolean isGenKeys, String sql) { + public BatchedPstmt(PreparedStatement pstmt, boolean isGenKeys, String sql, SpiTransaction transaction) { this.pstmt = pstmt; this.isGenKeys = isGenKeys; this.sql = sql; + this.transaction = transaction; } /** @@ -74,12 +82,20 @@ public class BatchedPstmt { */ public void executeBatch(boolean getGeneratedKeys) throws SQLException { + this.profileStart = transaction.profileOffset(); executeAndCheckRowCounts(); if (isGenKeys && getGeneratedKeys) { getGeneratedKeys(); } postExecute(); close(); + transaction.profileEvent(this); + } + + @Override + public void profile() { + // just use the first to add the event + list.get(0).profile(profileStart, list.size()); } /** @@ -93,8 +109,8 @@ public class BatchedPstmt { } private void postExecute() { - for (BatchPostExecute aList : list) { - aList.postExecute(); + for (BatchPostExecute item : list) { + item.postExecute(); } } diff --git a/src/main/java/io/ebeaninternal/server/persist/PstmtFactory.java b/src/main/java/io/ebeaninternal/server/persist/PstmtFactory.java index 47f12e39a..7590dd6a7 100644 --- a/src/main/java/io/ebeaninternal/server/persist/PstmtFactory.java +++ b/src/main/java/io/ebeaninternal/server/persist/PstmtFactory.java @@ -54,7 +54,7 @@ public class PstmtFactory { Connection conn = t.getInternalConnection(); stmt = conn.prepareStatement(sql); - BatchedPstmt bs = new BatchedPstmt(stmt, false, sql); + BatchedPstmt bs = new BatchedPstmt(stmt, false, sql, t); batch.addStmt(bs, batchExe); return stmt; } @@ -78,7 +78,7 @@ public class PstmtFactory { Connection conn = t.getInternalConnection(); stmt = conn.prepareCall(sql); - BatchedPstmt bs = new BatchedPstmt(stmt, false, sql); + BatchedPstmt bs = new BatchedPstmt(stmt, false, sql, t); batch.addStmt(bs, batchExe); return stmt; } diff --git a/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java b/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java index 75a743c9c..22777d865 100644 --- a/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java +++ b/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java @@ -283,7 +283,7 @@ public abstract class DmlHandler implements PersistHandler, BindableRequest { stmt = getPstmt(t, sql, genKeys); - BatchedPstmt bs = new BatchedPstmt(stmt, genKeys, sql); + BatchedPstmt bs = new BatchedPstmt(stmt, genKeys, sql, t); batch.addStmt(bs, request); return stmt; } diff --git a/src/main/java/io/ebeaninternal/server/query/CQuery.java b/src/main/java/io/ebeaninternal/server/query/CQuery.java index 98ace2aa5..3aef94ed9 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQuery.java +++ b/src/main/java/io/ebeaninternal/server/query/CQuery.java @@ -13,6 +13,7 @@ import io.ebean.event.readaudit.ReadEvent; import io.ebeaninternal.api.SpiQuery; import io.ebeaninternal.api.SpiQuery.Mode; import io.ebeaninternal.api.SpiTransaction; +import io.ebeaninternal.api.SpiProfileTransactionEvent; import io.ebeaninternal.server.autotune.ProfilingListener; import io.ebeaninternal.server.core.OrmQueryRequest; import io.ebeaninternal.server.core.SpiOrmQueryRequest; @@ -50,7 +51,7 @@ import java.util.NoSuchElementException; * the key object used in reading the flat resultSet back into Objects. *

*/ -public class CQuery implements DbReadContext, CancelableQuery { +public class CQuery implements DbReadContext, CancelableQuery, SpiProfileTransactionEvent { private static final Logger logger = LoggerFactory.getLogger(CQuery.class); @@ -172,6 +173,7 @@ public class CQuery implements DbReadContext, CancelableQuery { private final Boolean readOnly; + private int profileOffset; private long startNano; private long executionTimeMicros; @@ -318,6 +320,7 @@ public class CQuery implements DbReadContext, CancelableQuery { // prepare SpiTransaction t = request.getTransaction(); + profileOffset = t.profileOffset(); Connection conn = t.getInternalConnection(); if (query.isRawSql()) { @@ -587,11 +590,19 @@ public class CQuery implements DbReadContext, CancelableQuery { profilingListener.collectQueryInfo(objectGraphNode, loadedBeanCount, executionTimeMicros); } queryPlan.executionTime(loadedBeanCount, executionTimeMicros, objectGraphNode); + getTransaction().profileEvent(this); } catch (Exception e) { logger.error("Error updating execution statistics", e); } } + @Override + public void profile() { + getTransaction() + .profileStream() + .addQueryEvent(query.profileEventId(), profileOffset, desc.getProfileId(), loadedBeanCount, query.getProfileId()); + } + QueryIterator readIterate(int bufferSize, OrmQueryRequest request) { if (bufferSize > 0) { diff --git a/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java b/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java index 522e9bc69..3f41c6830 100644 --- a/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java +++ b/src/main/java/io/ebeaninternal/server/querydefn/DefaultOrmQuery.java @@ -253,6 +253,11 @@ public class DefaultOrmQuery implements SpiQuery { private String nativeSql; + /** + * Identity the query for profiling purposes (expected to be unique for a bean type). + */ + private short profileId; + public DefaultOrmQuery(BeanDescriptor desc, EbeanServer server, ExpressionFactory expressionFactory) { this.beanDescriptor = desc; this.beanType = desc.getBeanType(); @@ -280,6 +285,26 @@ public class DefaultOrmQuery implements SpiQuery { } } + @Override + public byte profileEventId() { + switch (mode) { + case LAZYLOAD_BEAN: return FIND_ONE_LAZY; + case LAZYLOAD_MANY: return FIND_MANY_LAZY; + default: + return type.profileEventId(); + } + } + + public short getProfileId() { + return profileId; + } + + @Override + public Query setProfileId(int profileId) { + this.profileId = (short)profileId; + return this; + } + @Override public boolean isAutoTunable() { return nativeSql == null && beanDescriptor.isAutoTunable(); diff --git a/src/main/java/io/ebeaninternal/server/transaction/AutoCommitTransactionManager.java b/src/main/java/io/ebeaninternal/server/transaction/AutoCommitTransactionManager.java index ca862ebfa..6625dd997 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/AutoCommitTransactionManager.java +++ b/src/main/java/io/ebeaninternal/server/transaction/AutoCommitTransactionManager.java @@ -19,7 +19,7 @@ public class AutoCommitTransactionManager extends TransactionManager { * Create an autoCommit based Transaction. */ @Override - protected SpiTransaction createTransaction(boolean explicit, Connection c, long id) { + protected SpiTransaction createTransaction(int profileId, boolean explicit, Connection c, long id) { return new AutoCommitJdbcTransaction(prefix + id, explicit, c, this); } diff --git a/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java b/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java new file mode 100644 index 000000000..903b69e1c --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/transaction/DefaultProfileHandler.java @@ -0,0 +1,247 @@ +package io.ebeaninternal.server.transaction; + +import io.ebean.config.ProfilingConfig; +import io.ebean.plugin.BeanType; +import io.ebean.plugin.Plugin; +import io.ebean.plugin.SpiServer; +import io.ebeaninternal.api.SpiProfileHandler; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.io.File; +import java.io.FileNotFoundException; +import java.io.FileOutputStream; +import java.io.IOException; +import java.time.LocalDateTime; +import java.time.format.DateTimeFormatter; +import java.time.format.DateTimeFormatterBuilder; +import java.util.Queue; +import java.util.concurrent.ConcurrentLinkedQueue; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +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.MINUTE_OF_HOUR; +import static java.time.temporal.ChronoField.MONTH_OF_YEAR; +import static java.time.temporal.ChronoField.SECOND_OF_MINUTE; +import static java.time.temporal.ChronoField.YEAR; + +/** + * Default profile handler. + *

+ * Uses ConcurrentLinkedQueue to minimise contention on threads calling collectTransactionProfile(). + *

+ *

+ * Uses a sleep backoff on the single threaded consumer that reads the profiles and writes them to files. + *

+ */ +public class DefaultProfileHandler implements SpiProfileHandler, Plugin { + + private static final Logger log = LoggerFactory.getLogger(DefaultProfileHandler.class); + + private static final DateTimeFormatter DTF; + + static { + DTF = new DateTimeFormatterBuilder() + .parseCaseInsensitive() + .appendValue(YEAR, 4) + .appendValue(MONTH_OF_YEAR, 2) + .appendValue(DAY_OF_MONTH, 2) + .appendLiteral('-') + .appendValue(HOUR_OF_DAY, 2) + .appendValue(MINUTE_OF_HOUR, 2) + .appendValue(SECOND_OF_MINUTE, 2) + .toFormatter(); + } + + /** + * Low contention choice. + */ + private final Queue queue = new ConcurrentLinkedQueue<>(); + + private final ExecutorService executor; + + private final File dir; + + private final long minMicros; + + private final int[] includeIds; + + private final long profilesPerFile; + + private volatile boolean shutdown; + + private long profileCounter; + + /** + * Slow down polling of transaction profiling queue. + */ + private int sleepBackoff; + + private FileOutputStream out; + + public DefaultProfileHandler(ProfilingConfig config) { + this.minMicros = config.getMinimumTransactionMicros(); + this.includeIds = config.getIncludeProfileIds(); + this.profilesPerFile = config.getProfilesPerFile(); + + // dedicated single threaded executor for consuming the + // profiling and writing it to file(s) + this.executor = Executors.newSingleThreadExecutor(); + this.dir = new File(config.getDirectory()); + if (!dir.mkdirs()) { + log.error("failed to mkdirs " + dir.getAbsolutePath()); + } + incrementFile(); + } + + /** + * Low contention adding the transaction profile to the queue. + * Minimise the impact to the normal transaction processing (threads). + */ + @Override + public void collectTransactionProfile(TransactionProfile transactionProfile) { + queue.add(transactionProfile); + } + + /** + * Create and return a ProfileStream if we are profiling for the given transaction profileId. + */ + @Override + public ProfileStream createProfileStream(int profileId) { + + if (profileId < 1) { + // not this transaction + return null; + } + + if (includeIds.length == 0) { + return new ProfileStream(profileId); + } + + // 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 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); + } + } + } + + /** + * 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); + } + } + + /** + * Main loop for polling the queue and processing profiling messages. + */ + private void collect() { + while (!shutdown) { + TransactionProfile profile = queue.poll(); + if (profile == null) { + sleep(); + + } else if (include(profile)) { + write(profile); + } + } + } + + /** + * Write the profile to the current file. + */ + private void write(TransactionProfile profile) { + try { + sleepBackoff = 0; + ++profileCounter; + out.write(profile.getBytes()); + if (profileCounter % profilesPerFile == 0) { + incrementFile(); + log.debug("profiled {} transactions", profileCounter); + } + } catch (IOException e) { + log.warn("Error writing transaction profiling", e); + } + } + + /** + * Return true if the profile should be included (or false for ignored). + */ + private boolean include(TransactionProfile profile) { + return profile.getTotalMicros() >= minMicros; + } + + /** + * Sleep backing off towards 250 millis when there is no activity. + * This seems to be simple and decent for our queue consumer. + */ + private void sleep() { + try { + // backoff sleep when nothing is happening + int sleepFor = Math.min(++sleepBackoff, 250); + Thread.sleep(sleepFor); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + } + + @Override + public void configure(SpiServer server) { + + StringBuilder sb = new StringBuilder(200); + sb.append("Bean profile mapping - "); + for (BeanType type : server.getBeanTypes()) { + sb.append("profileId:").append(type.getProfileId()) + .append(" ").append(type.getName()).append(", "); + } + log.info(sb.toString()); + } + + @Override + public void online(boolean online) { + if (online) { + executor.submit(this::collect); + } + } + + @Override + public void shutdown() { + shutdown = true; + log.trace("shutting down profiling consumer"); + flushCurrentFile(); + try { + executor.shutdown(); + if (!executor.awaitTermination(4, TimeUnit.SECONDS)) { + log.info("Shut down timeout exceeded. Terminating profiling consumer thread."); + executor.shutdownNow(); + } + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + log.warn("Interrupt on shutdown", e); + } + } +} diff --git a/src/main/java/io/ebeaninternal/server/transaction/DocStoreTransactionManager.java b/src/main/java/io/ebeaninternal/server/transaction/DocStoreTransactionManager.java index 53f1f5c04..8beb2b3bb 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/DocStoreTransactionManager.java +++ b/src/main/java/io/ebeaninternal/server/transaction/DocStoreTransactionManager.java @@ -22,9 +22,9 @@ public class DocStoreTransactionManager extends TransactionManager { } @Override - public SpiTransaction createTransaction(boolean explicit, int isolationLevel) { + public SpiTransaction createTransaction(int profileId, boolean explicit, int isolationLevel) { long id = counter.incrementAndGet(); - return createTransaction(explicit, null, id); + return createTransaction(profileId, explicit, null, id); } @Override @@ -33,7 +33,7 @@ public class DocStoreTransactionManager extends TransactionManager { } @Override - protected SpiTransaction createTransaction(boolean explicit, Connection c, long id) { + protected SpiTransaction createTransaction(int profileId, boolean explicit, Connection c, long id) { return new DocStoreOnlyTransaction(prefix + id, explicit, this); } } diff --git a/src/main/java/io/ebeaninternal/server/transaction/ExplicitTransactionManager.java b/src/main/java/io/ebeaninternal/server/transaction/ExplicitTransactionManager.java index 8d082c3e3..df710279b 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/ExplicitTransactionManager.java +++ b/src/main/java/io/ebeaninternal/server/transaction/ExplicitTransactionManager.java @@ -18,7 +18,7 @@ public class ExplicitTransactionManager extends TransactionManager { * Create a ExplicitJdbcTransaction. */ @Override - protected SpiTransaction createTransaction(boolean explicit, Connection c, long id) { + protected SpiTransaction createTransaction(int profileId, boolean explicit, Connection c, long id) { return new ExplicitJdbcTransaction(prefix + id, explicit, c, this); } diff --git a/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java b/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java index c7a4b4f01..e7d77cb3c 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java +++ b/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java @@ -9,7 +9,9 @@ import io.ebean.config.dbplatform.DatabasePlatform.OnQueryOnly; import io.ebean.event.changelog.BeanChange; import io.ebean.event.changelog.ChangeSet; import io.ebeaninternal.api.SpiTransaction; +import io.ebeaninternal.api.SpiProfileTransactionEvent; import io.ebeaninternal.api.TransactionEvent; +import io.ebeaninternal.api.TxnProfileEventCodes; import io.ebeaninternal.server.core.PersistDeferredRelationship; import io.ebeaninternal.server.core.PersistRequest; import io.ebeaninternal.server.core.PersistRequestBean; @@ -34,7 +36,7 @@ import java.util.Map; /** * JDBC Connection based transaction. */ -public class JdbcTransaction implements SpiTransaction { +public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes { private static final Logger logger = LoggerFactory.getLogger(JdbcTransaction.class); @@ -169,11 +171,21 @@ public class JdbcTransaction implements SpiTransaction { protected DocStoreTransaction docStoreTxn; + private final ProfileStream profileStream; + + /** + * Create without ProfileStream option (no profiling). + */ + public JdbcTransaction(String id, boolean explicit, Connection connection, TransactionManager manager) { + this(null, id, explicit, connection, manager); + } + /** * Create a new JdbcTransaction. */ - public JdbcTransaction(String id, boolean explicit, Connection connection, TransactionManager manager) { + public JdbcTransaction(ProfileStream profileStream, String id, boolean explicit, Connection connection, TransactionManager manager) { try { + this.profileStream = profileStream; this.active = true; this.id = id; this.logPrefix = deriveLogPrefix(id); @@ -201,6 +213,23 @@ public class JdbcTransaction implements SpiTransaction { } } + @Override + public int profileOffset() { + return (profileStream == null) ? 0 : profileStream.offset(); + } + + @Override + public void profileEvent(SpiProfileTransactionEvent event) { + if (profileStream != null) { + event.profile(); + } + } + + @Override + public ProfileStream profileStream() { + return profileStream; + } + /** * Overridden in AutoCommitJdbcTransaction as that expects to run/operate with autocommit true. */ @@ -884,6 +913,7 @@ public class JdbcTransaction implements SpiTransaction { } connection = null; active = false; + profileEnd(); } /** @@ -918,14 +948,28 @@ public class JdbcTransaction implements SpiTransaction { * Perform the actual rollback on the connection. */ protected void performRollback() throws SQLException { + int offset = profileOffset(); connection.rollback(); + if (profileStream != null) { + profileStream.addEvent(EVT_ROLLBACK, offset); + } } /** * Perform the actual commit on the connection. */ protected void performCommit() throws SQLException { + int offset = profileOffset(); connection.commit(); + if (profileStream != null) { + profileStream.addEvent(EVT_COMMIT, offset); + } + } + + private void profileEnd() { + if (profileStream != null) { + profileStream.end(manager); + } } /** diff --git a/src/main/java/io/ebeaninternal/server/transaction/NoopProfileHandler.java b/src/main/java/io/ebeaninternal/server/transaction/NoopProfileHandler.java new file mode 100644 index 000000000..ab24af225 --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/transaction/NoopProfileHandler.java @@ -0,0 +1,20 @@ +package io.ebeaninternal.server.transaction; + +import io.ebeaninternal.api.SpiProfileHandler; + +/** + * A do nothing SpiProfileHandler. + */ +public class NoopProfileHandler implements SpiProfileHandler { + + @Override + public void collectTransactionProfile(TransactionProfile transactionProfile) { + // do nothing + } + + @Override + public ProfileStream createProfileStream(int profileId) { + // always return null + return null; + } +} diff --git a/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java b/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java new file mode 100644 index 000000000..691f6baa1 --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/transaction/ProfileStream.java @@ -0,0 +1,102 @@ +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. + */ +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); + } + } + + /** + * Return the time offset from the beginning 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); + } + + /** + * Add the commit/rollback 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); + } + + /** + * 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); + } + } + + /** + * End the transaction profiling. + */ + 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); + } + } + +} diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactory.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactory.java index a1593736d..cbcddc681 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactory.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactory.java @@ -34,7 +34,7 @@ abstract class TransactionFactory { /** * Return a new transaction. */ - abstract SpiTransaction createTransaction(boolean explicit, int isolationLevel); + abstract SpiTransaction createTransaction(int profileId, boolean explicit, int isolationLevel); /** * Set the Transaction Isolation level if required. diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasic.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasic.java index 004ebf33d..a10f3097c 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasic.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasic.java @@ -22,20 +22,20 @@ class TransactionFactoryBasic extends TransactionFactory { @Override public SpiTransaction createQueryTransaction(Object tenantId) { - return create(false); + return create(0,false); } @Override - public SpiTransaction createTransaction(boolean explicit, int isolationLevel) { - SpiTransaction t = create(explicit); + public SpiTransaction createTransaction(int profileId, boolean explicit, int isolationLevel) { + SpiTransaction t = create(profileId, explicit); return setIsolationLevel(t, explicit, isolationLevel); } - private SpiTransaction create(boolean explicit) { + private SpiTransaction create(int profileId, boolean explicit) { Connection c = null; try { c = dataSource.getConnection(); - return manager.createTransaction(explicit, c, counter.incrementAndGet()); + return manager.createTransaction(profileId, explicit, c, counter.incrementAndGet()); } catch (PersistenceException ex) { JdbcClose.close(c); diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenant.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenant.java index bb8259f1e..b82ddc5c8 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenant.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenant.java @@ -25,17 +25,17 @@ class TransactionFactoryTenant extends TransactionFactory { @Override public SpiTransaction createQueryTransaction(Object tenantId) { - return create(false, tenantId); + return create(0,false, tenantId); } @Override - public SpiTransaction createTransaction(boolean explicit, int isolationLevel) { + public SpiTransaction createTransaction(int profileId, boolean explicit, int isolationLevel) { - SpiTransaction t = create(explicit, null); + SpiTransaction t = create(profileId, explicit, null); return setIsolationLevel(t, explicit, isolationLevel); } - private SpiTransaction create(boolean explicit, Object tenantId) { + private SpiTransaction create(int profileId, boolean explicit, Object tenantId) { Connection c = null; try { if (tenantId == null) { @@ -43,7 +43,7 @@ class TransactionFactoryTenant extends TransactionFactory { tenantId = tenantProvider.currentId(); } c = dataSourceSupplier.getConnection(tenantId); - SpiTransaction transaction = manager.createTransaction(explicit, c, counter.incrementAndGet()); + SpiTransaction transaction = manager.createTransaction(profileId, explicit, c, counter.incrementAndGet()); transaction.setTenantId(tenantId); return transaction; diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java index 6cda1dc09..907ad1f63 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java @@ -8,6 +8,7 @@ import io.ebean.config.dbplatform.DatabasePlatform.OnQueryOnly; import io.ebean.event.changelog.ChangeLogListener; import io.ebean.event.changelog.ChangeLogPrepare; import io.ebean.event.changelog.ChangeSet; +import io.ebeaninternal.api.SpiProfileHandler; import io.ebeaninternal.api.SpiTransaction; import io.ebeaninternal.api.TransactionEvent; import io.ebeaninternal.api.TransactionEventTable; @@ -110,6 +111,8 @@ public class TransactionManager { private final DatabasePlatform databasePlatform; + private final SpiProfileHandler profileHandler; + /** * Create the TransactionManager */ @@ -131,6 +134,7 @@ public class TransactionManager { this.dataSourceSupplier = options.dataSourceSupplier; this.docStoreActive = options.config.getDocStoreConfig().isActive(); this.docStoreUpdateProcessor = options.docStoreUpdateProcessor; + this.profileHandler = options.profileHandler; this.bulkEventListenerMap = new BulkEventListenerMap(options.config.getBulkTableEventListeners()); this.prefix = ""; this.externalTransPrefix = "e"; @@ -248,8 +252,8 @@ public class TransactionManager { /** * Create a new Transaction. */ - public SpiTransaction createTransaction(boolean explicit, int isolationLevel) { - return transactionFactory.createTransaction(explicit, isolationLevel); + public SpiTransaction createTransaction(int profileId, boolean explicit, int isolationLevel) { + return transactionFactory.createTransaction(profileId, explicit, isolationLevel); } public SpiTransaction createQueryTransaction(Object tenantId) { @@ -259,8 +263,10 @@ public class TransactionManager { /** * Create a new transaction. */ - protected SpiTransaction createTransaction(boolean explicit, Connection c, long id) { - return new JdbcTransaction(prefix + id, explicit, c, this); + protected SpiTransaction createTransaction(int profileId, boolean explicit, Connection c, long id) { + + ProfileStream profileStream = profileHandler.createProfileStream(profileId); + return new JdbcTransaction(profileStream,prefix + id, explicit, c, this); } /** @@ -412,4 +418,10 @@ public class TransactionManager { } } + /** + * Process the collected transaction profiling information. + */ + public void profileCollect(TransactionProfile transactionProfile) { + profileHandler.collectTransactionProfile(transactionProfile); + } } diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionManagerOptions.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionManagerOptions.java index 7b62882c4..a17de4135 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionManagerOptions.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionManagerOptions.java @@ -2,6 +2,7 @@ package io.ebeaninternal.server.transaction; import io.ebean.BackgroundExecutor; import io.ebean.config.ServerConfig; +import io.ebeaninternal.api.SpiProfileHandler; import io.ebeaninternal.server.cluster.ClusterManager; import io.ebeaninternal.server.deploy.BeanDescriptorManager; import io.ebeanservice.docstore.api.DocStoreUpdateProcessor; @@ -19,10 +20,11 @@ public class TransactionManagerOptions { final DocStoreUpdateProcessor docStoreUpdateProcessor; final BeanDescriptorManager descMgr; final DataSourceSupplier dataSourceSupplier; + final SpiProfileHandler profileHandler; - - public TransactionManagerOptions(boolean localL2Caching, ServerConfig config, ClusterManager clusterManager, BackgroundExecutor backgroundExecutor, - DocStoreUpdateProcessor docStoreUpdateProcessor, BeanDescriptorManager descMgr, DataSourceSupplier dataSourceSupplier) { + public TransactionManagerOptions(boolean localL2Caching, ServerConfig config, ClusterManager clusterManager, + BackgroundExecutor backgroundExecutor, DocStoreUpdateProcessor docStoreUpdateProcessor, + BeanDescriptorManager descMgr, DataSourceSupplier dataSourceSupplier, SpiProfileHandler profileHandler) { this.localL2Caching = localL2Caching; this.config = config; @@ -31,6 +33,7 @@ public class TransactionManagerOptions { this.docStoreUpdateProcessor = docStoreUpdateProcessor; this.descMgr = descMgr; this.dataSourceSupplier = dataSourceSupplier; + this.profileHandler = profileHandler; } } diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java new file mode 100644 index 000000000..bedf30047 --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionProfile.java @@ -0,0 +1,52 @@ +package io.ebeaninternal.server.transaction; + +/** + * Profiling information for a single transaction that has completed. + */ +public class TransactionProfile { + + /** + * The profileId of the transaction (On @Transactional explicitly or can be automatically set by enhancement). + */ + private final int profileId; + + /** + * The total execution time of the transaction (for filtering out small/short transactions). + */ + private final long totalMicros; + + /** + * The binary encoding of the transaction profiling events. + */ + private final byte[] bytes; + + /** + * Create with profileId, total micros and encoded profile data. + */ + public TransactionProfile(int profileId, long totalMicros, byte[] bytes) { + this.profileId = profileId; + this.totalMicros = totalMicros; + this.bytes = bytes; + } + + /** + * Return the transaction profileId. + */ + public int getProfileId() { + return profileId; + } + + /** + * Return the total transaction execution time in micros. + */ + public long getTotalMicros() { + return totalMicros; + } + + /** + * Return the profiling data in encoded form. + */ + public byte[] getBytes() { + return bytes; + } +} diff --git a/src/main/resources/META-INF/ebean-version.mf b/src/main/resources/META-INF/ebean-version.mf new file mode 100644 index 000000000..c8fd396a6 --- /dev/null +++ b/src/main/resources/META-INF/ebean-version.mf @@ -0,0 +1 @@ +api-version: 11.3 diff --git a/src/test/java/io/ebeaninternal/server/transaction/DefaultProfileHandlerTest.java b/src/test/java/io/ebeaninternal/server/transaction/DefaultProfileHandlerTest.java new file mode 100644 index 000000000..9d70a1c96 --- /dev/null +++ b/src/test/java/io/ebeaninternal/server/transaction/DefaultProfileHandlerTest.java @@ -0,0 +1,34 @@ +package io.ebeaninternal.server.transaction; + +import io.ebean.config.ProfilingConfig; +import org.junit.Test; + +import static org.junit.Assert.*; + +public class DefaultProfileHandlerTest { + @Test + public void createProfileStream() throws Exception { + + DefaultProfileHandler handler = new DefaultProfileHandler(new ProfilingConfig()); + + assertNotNull(handler.createProfileStream(12)); + assertNull(handler.createProfileStream(0)); + } + + @Test + public void createProfileStream_when_specificIncludeIds() throws Exception { + + ProfilingConfig config = new ProfilingConfig(); + config.setIncludeProfileIds(new int[]{100,101}); + + DefaultProfileHandler handler = new DefaultProfileHandler(config); + + assertNotNull(handler.createProfileStream(100)); + assertNotNull(handler.createProfileStream(101)); + + assertNull(handler.createProfileStream(0)); + assertNull(handler.createProfileStream(12)); + + } + +} diff --git a/src/test/java/org/ebeantest/LoggedSqlCollector.java b/src/test/java/org/ebeantest/LoggedSqlCollector.java index a3d50127b..849c322de 100644 --- a/src/test/java/org/ebeantest/LoggedSqlCollector.java +++ b/src/test/java/org/ebeantest/LoggedSqlCollector.java @@ -11,12 +11,12 @@ import java.util.ArrayList; import java.util.List; /** - * Helper that can collect the SQL that is logged via SLF4J. + * Helper that can collectTransactionProfile the SQL that is logged via SLF4J. *

- * Used {@link #start()} and {@link #stop()} to collect the logged messages that contain the + * Used {@link #start()} and {@link #stop()} to collectTransactionProfile the logged messages that contain the * executed SQL statements. *

- * Internally this uses a Logback Appender to collect messages for org.avaje.ebean.SQL. + * Internally this uses a Logback Appender to collectTransactionProfile messages for org.avaje.ebean.SQL. */ public class LoggedSqlCollector { diff --git a/src/test/java/org/tests/persistencecontext/TestPersistenceContextScopeUsingOrders.java b/src/test/java/org/tests/persistencecontext/TestPersistenceContextScopeUsingOrders.java index f39dbff87..4c6553843 100644 --- a/src/test/java/org/tests/persistencecontext/TestPersistenceContextScopeUsingOrders.java +++ b/src/test/java/org/tests/persistencecontext/TestPersistenceContextScopeUsingOrders.java @@ -33,7 +33,7 @@ public class TestPersistenceContextScopeUsingOrders extends BaseTestCase { assertTrue(!orders.isEmpty()); - // collect the customer instances + // collectTransactionProfile the customer instances List customers = new ArrayList<>(); Set identities = new HashSet<>();