diff --git a/ebean-api/src/main/java/io/ebean/bean/InterceptReadWrite.java b/ebean-api/src/main/java/io/ebean/bean/InterceptReadWrite.java index dbbbc765fb..c760ca10b4 100644 --- a/ebean-api/src/main/java/io/ebean/bean/InterceptReadWrite.java +++ b/ebean-api/src/main/java/io/ebean/bean/InterceptReadWrite.java @@ -115,7 +115,7 @@ public InterceptReadWrite() { @Override public String toString() { - return "InterceptReadWrite{state=" + state + + return "InterceptReadWrite@" + hashCode() + "{state=" + state + (dirty ? " dirty;" : "") + (forceUpdate ? " forceUpdate;" : "") + (readOnly ? " readOnly;" : "") + diff --git a/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanBuffer.java b/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanBuffer.java index a04652cba5..4749cf8518 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanBuffer.java +++ b/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanBuffer.java @@ -26,4 +26,6 @@ public interface LoadBeanBuffer { boolean isCache(); void loadingStarted(); + + void loadingStopped(); } diff --git a/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanRequest.java b/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanRequest.java index 457350641d..7fa8b8a091 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanRequest.java +++ b/ebean-core/src/main/java/io/ebeaninternal/api/LoadBeanRequest.java @@ -8,6 +8,8 @@ import java.util.*; +import static java.lang.System.Logger.Level.DEBUG; + /** * Request for loading ManyToOne and OneToOne relationships. */ @@ -18,12 +20,13 @@ public final class LoadBeanRequest extends LoadRequest { private final String lazyLoadProperty; private final boolean loadCache; private final boolean alreadyLoaded; - + private String triggerEbi; /** * Construct for lazy load request. */ public LoadBeanRequest(LoadBeanBuffer loadBuffer, EntityBeanIntercept ebi, boolean loadCache) { this(loadBuffer, null, true, ebi.lazyLoadProperty(), ebi.isLoaded(), loadCache || ebi.isLoadedFromCache()); + this.triggerEbi = String.valueOf(ebi); } /** @@ -105,7 +108,8 @@ private String mode() { /** * Load the beans into the L2 cache if that is requested and check for load failures due to deletes. */ - public Result postLoad(List list) { + public Result postLoad(List list, List queryIds) { + loadBuffer.loadingStopped(); Set loadedIds = new HashSet<>(); BeanDescriptor desc = loadBuffer.descriptor(); // collect Ids and maybe load bean cache @@ -123,10 +127,17 @@ public Result postLoad(List list) { // necessary but allow processing to continue until it is accessed by client code Object id = desc.getId(ebi.owner()); if (!loadedIds.contains(id)) { - // assume this is logically deleted (hence not found) - desc.markAsDeleted(ebi.owner()); - missedIds.add(id); - missed.add(ebi); + if (queryIds.contains(id)) { + // assume this is logically deleted (hence not found) + desc.markAsDeleted(ebi.owner()); + } else { + // unexpected, added to batch during loading + missedIds.add(id); + missed.add(ebi); + } + } + if (!missed.isEmpty()) { + CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch triggered by ebi:{0} property:{1}", triggerEbi, lazyLoadProperty); } } return new Result(loadedIds, missedIds, missed); @@ -148,7 +159,7 @@ public static class Result { this.missed = missed; } - public boolean markedDeleted() { + public boolean hasMisses() { return !missedIds.isEmpty(); } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultBeanLoader.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultBeanLoader.java index 217508b99d..a7a9e51b72 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultBeanLoader.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultBeanLoader.java @@ -142,13 +142,13 @@ void loadBean(LoadBeanRequest loadRequest) { final SpiQuery query = server.createQuery(loadRequest.beanType()); loadRequest.configureQuery(query, ids); final List list = executeQuery(loadRequest, query); - final LoadBeanRequest.Result result = loadRequest.postLoad(list); - if (result.markedDeleted() && CoreLog.markedAsDeleted.isLoggable(DEBUG)) { + final LoadBeanRequest.Result result = loadRequest.postLoad(list, ids); + if (result.hasMisses() && CoreLog.markedAsDeleted.isLoggable(DEBUG)) { CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch BEFORE {0}", batchBefore); CoreLog.markedAsDeleted.log(DEBUG, "Loaded bean batch AFTER {0}", batch); - String msg = MessageFormat.format("Loaded bean marked as deleted for {0} ids:{1} missedIds:{2} loadedIds:{3} sql:{4} loadedList:{5} missed:{6}", - loadRequest.beanType(), ids, result.missedIds(), result.loadedIds(), query.getGeneratedSql(), list, result.missed()); - CoreLog.markedAsDeleted.log(DEBUG, msg, new RuntimeException("LoadBeanRequest markedAsDeleted")); + String msg = MessageFormat.format("Bean added to batch during load for {0} missedIds:{1} ids:{2} loadedIds:{3} sql:{4} missed:{5}", + loadRequest.beanType(), result.missedIds(), ids, result.loadedIds(), query.getGeneratedSql(), result.missed()); + CoreLog.markedAsDeleted.log(DEBUG, msg, new RuntimeException("LoadBeanRequest - Bean added to batch during load")); } } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/loadcontext/DLoadBeanContext.java b/ebean-core/src/main/java/io/ebeaninternal/server/loadcontext/DLoadBeanContext.java index dfc049010b..4b8e3d8dcd 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/loadcontext/DLoadBeanContext.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/loadcontext/DLoadBeanContext.java @@ -11,6 +11,7 @@ import io.ebeaninternal.server.deploy.BeanPropertyAssocMany; import io.ebeaninternal.server.querydefn.OrmQueryProperties; +import java.time.Instant; import java.util.ArrayList; import java.util.HashSet; import java.util.List; @@ -71,6 +72,9 @@ void register(EntityBeanIntercept ebi) { if (currentBuffer.isFull()) { currentBuffer = createBuffer(batchSize); } + if (currentBuffer.addWhenLoading()) { + CoreLog.markedAsDeleted.log(DEBUG, "Adding " + ebi + " to batch " + currentBuffer + " after loadingStarted(1)", new RuntimeException("Adding to batch after load(1)")); + } ebi.setBeanLoader(currentBuffer, persistenceContext()); currentBuffer.add(ebi); } @@ -117,6 +121,7 @@ static class LoadBuffer implements BeanLoader, LoadBeanBuffer { private final DLoadBeanContext context; private final int batchSize; private final Set batch; + private final Instant whenCreated = Instant.now(); private PersistenceContext persistenceContext; LoadBuffer(DLoadBeanContext context, int batchSize) { @@ -127,7 +132,8 @@ static class LoadBuffer implements BeanLoader, LoadBeanBuffer { @Override public String toString() { - return "LoadBuffer@" + hashCode(); + return "LoadBuffer@" + hashCode() + ":" + whenCreated + ":size=" + batch.size() + +":locked=" +bufferLock.isLocked()+ "/currentThread=" + bufferLock.isHeldByCurrentThread(); } @Override @@ -148,6 +154,10 @@ public boolean isFull() { return batchSize == batch.size(); } + final boolean addWhenLoading() { + return loadingStarted.get() && CoreLog.markedAsDeleted.isLoggable(DEBUG); + } + /** * Add the bean to the load buffer. */ @@ -156,11 +166,6 @@ public void add(EntityBeanIntercept ebi) { // get persistenceContext from first loaded bean into the buffer persistenceContext = ebi.persistenceContext(); } - if (loadingStarted.get()) { - if (CoreLog.markedAsDeleted.isLoggable(DEBUG)) { - CoreLog.markedAsDeleted.log(DEBUG, "Adding to batch after loadingStarted(1)", new RuntimeException("Adding to batch after load(1")); - } - } batch.add(ebi); } @@ -206,6 +211,11 @@ public void loadingStarted() { loadingStarted.set(true); } + @Override + public void loadingStopped() { + loadingStarted.set(false); + } + @Override public void loadBean(EntityBeanIntercept ebi) { // A lock is effectively held by EntityBeanIntercept.loadBean() @@ -217,7 +227,7 @@ public void loadBean(EntityBeanIntercept ebi) { // re-add to the batch and lazy load from DB skipping l2 cache if (loadingStarted.get()) { if (CoreLog.markedAsDeleted.isLoggable(DEBUG)) { - CoreLog.markedAsDeleted.log(DEBUG, "Adding to batch after loadingStarted(2)", new RuntimeException("Adding to batch after load(2")); + CoreLog.markedAsDeleted.log(DEBUG, "Adding " + ebi + "to batch " + this + "after loadingStarted(2) ", new RuntimeException("Adding to batch after load(2")); } } batch.add(ebi); @@ -230,10 +240,8 @@ public void loadBean(EntityBeanIntercept ebi) { } } - LoadBeanRequest req = new LoadBeanRequest(this, ebi, context.hitCache); - context.desc.ebeanServer().loadBean(req); + context.desc.ebeanServer().loadBean(new LoadBeanRequest(this, ebi, context.hitCache)); batch.clear(); - loadingStarted.set(false); } } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/SqlTreeLoadBean.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/SqlTreeLoadBean.java index 577e4fe6d8..bd6f62d57f 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/SqlTreeLoadBean.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/query/SqlTreeLoadBean.java @@ -247,7 +247,7 @@ private boolean isLazyLoadManyRoot() { return queryMode == Mode.LAZYLOAD_MANY && isRoot(); } - private EntityBean getContextBean() { + private EntityBean contextBean() { return contextBean; } @@ -358,7 +358,7 @@ private void initialise() throws SQLException { final EntityBean perform() throws SQLException { initialise(); if (isLazyLoadManyRoot()) { - return getContextBean(); + return contextBean(); } postLoad(); setBeanToParent();