com.objectdb.o.TEX: Type ... is not found, for a class that's already been enhanced successfully.

#1

Noticing very poor performance from ObjectDB, not exactly sure what the problem is.
Tried to implement Enhancement (because the log always says that the classes are not enhanced).
The main class starts like this, and does not reference any persistent classes directly.

static void main(String[] args) {
    Enhancer.enhance(
        "common.app.Model,common.model.*,mr.model.*",
        Model.class.getClassLoader());

Here is the output, it seems like the above code does manage to enhance.
Then another process tries to enhance again.
Then the previously enhanced classes are not found.
Would you please explain how I can use the tracing information to debug this.

-----------------------------------------------------------------------------------------------

[ObjectDB 2.8.1 Enhancer]
16 persistable types have been enhanced:
    common.app.Model
    common.model.Auction
    common.model.LogEntry
    common.model.Message
    common.model.PageView
    common.model.Person
    common.model.Site
    common.model.SystemMessage
    common.model.UserSession
    mr.model.MRAuction
    mr.model.MRBid
    mr.model.MRPriceRule
    mr.model.MRRound
    mr.model.MRSettings
    mr.model.MRTemplate
    mr.model.MRTrader
11 NON persistable types have been enhanced:
    common.model.Person$_inRole_closure1
    common.model.Site$_getActiveSessions_closure1
    common.model.Site$_getActiveSessions_closure2
    common.model.UserSession$_delete_closure1
    mr.model.MRAuction$_delete_closure2
    mr.model.MRAuction$_delete_closure3
    mr.model.MRAuction$_delete_closure4
    mr.model.MRAuction$_delete_closure5
    mr.model.MRAuction$_delete_closure6
    mr.model.MRAuction$_getSortedBidders_closure1
    mr.model.MRTrader$_delete_closure1

[2019-09-13 17:13:01 #1 enhancer.agent]
Enhancer Agent started.

[2019-09-13 17:13:01 #2 enhancer.agent] 
Starting Enhancer Agent

[2019-09-13 17:13:01 #3 enhancer.agent] 
JVM: 11.0

[2019-09-13 17:13:02 #5 store] 
Database '/home/davem/au/codebase/2019/AuctionSoftware-gh01/db/storage.odb' is opened by 54905@ryzen7

[2019-09-13 17:13:02 #6 store] 
Configuration path: /home/davem/au/codebase/2019/AuctionSoftware-gh01/src/main/resources/objectdb-au-2019-09-12.conf

[2019-09-13 17:13:02 #7 type] 
Type common.app.Model is not enhanced.

[2019-09-13 17:13:02 #8 type] 
Type common.model.Site is not enhanced.

[2019-09-13 17:13:02 #9 type] 
Type common.model.UserSession is not enhanced.

[2019-09-13 17:13:02 #10 type] 
Type common.model.Person is not enhanced.

[2019-09-13 17:13:02 #11 type] 
Type common.model.PageView is not enhanced.

[2019-09-13 17:13:02 #12 query.manager] 
<queryRequest query="SELECT a FROM Site a" args="null" transactionId="-1" />

[2019-09-13 17:13:02 #13 query.tokenizer] 
<tokenList>
  <token name="SELECT" code="132" postion="0:6" />
  <token name="a" code="1" postion="7:8" />
  <token name="FROM" code="103" postion="9:13" />
  <token name="Site" code="1" postion="14:18" />
  <token name="a" code="1" postion="19:20" />
</tokenList>

[2019-09-13 17:13:02 #14 query.tokenizer] 
<token name="QUERY" code="67" postion="0:0">
  <token name="SELECT" code="132" postion="0:6">
    <token name="a" code="1" postion="7:8" />
  </token>
  <token name="FROM" code="103" postion="9:13">
    <token name="a" code="1" postion="19:20">
      <token name="Site" code="1" postion="14:18" />
    </token>
  </token>
</token>

[2019-09-13 17:13:02 #15 query.compiler] 
<queryCompilation query="SELECT a FROM Site a">
  <symbolManager>
    <parameters />
    <variables>
      <a varId="0" type="common.model.Site" subtypes="include" typeId="3" binding="null" nav="0">
        <keys />
        <navigations />
      </a>
    </variables>
  </symbolManager>
  <queryCompData>
    <query exp="query(select(a))" var="a" directVar="a" ext="0">
      <select exp="select(a)" var="a" directVar="a" ext="0">
        <variable exp="a" type="common.model.Site" var="a" directVar="a" ext="0" varId="0" />
      </select>
    </query>
    <globals globalVariables="a" globalNavigations="0" />
  </queryCompData>
</queryCompilation>

[2019-09-13 17:13:02 #16 query.compiler] 
<query-planning>
  <sub-planning vars="a" filter="null">
    <step vars="()+a" future="true">
      <btreePlan complexity="3.6342" eval="1.48/1.18" variable="a(Site)" scope="type(Site[all])" />
    </step>
    <selected-plans>
      <btreePlan complexity="3.6342" eval="1.48/1.18" variable="a(Site)" scope="type(Site[all])" />
    </selected-plans>
  </sub-planning>
</query-planning>

[2019-09-13 17:13:02 #17 query.compiler] 
<finalPlans>
  <btreePlan 3.6342 1.48/1.18 a(Site) type(Site[all]) />
</finalPlans>

[2019-09-13 17:13:02 #18 query.manager] 
<newQueryProgram>
  <btreePlan complexity="3.6342" eval="1.48/1.18" variable="a(Site)" scope="type(Site[all])" />
</newQueryProgram>

[2019-09-13 17:13:02 #19 query.manager] 
<newQueryResponse isUnique="false" resultSize="1" fetchSize="0">
  <SimpleResultBuilder name="a" type="common.model.Site" />
</newQueryResponse>

[2019-09-13 17:13:02 #20 query.manager] 
Query "SELECT a FROM Site a" => 1 results in 29 milliseconds.

[2019-09-13 17:13:02 #21 query.manager] 
<queryRequest query="SELECT a FROM Site a" args="null" transactionId="-1" />

[2019-09-13 17:13:02 #22 query.manager] 
<validCachedQueryResponse isUnique="false" resultSize="1" fetchSize="0">
  <SimpleResultBuilder name="a" type="common.model.Site" />
</validCachedQueryResponse>

[2019-09-13 17:13:02 #23 query.manager] 
<queryRequest query="SELECT a FROM MRAuction a" args="null" transactionId="-1" />

[2019-09-13 17:13:02 #24 query.tokenizer] 
<tokenList>
  <token name="SELECT" code="132" postion="0:6" />
  <token name="a" code="1" postion="7:8" />
  <token name="FROM" code="103" postion="9:13" />
  <token name="MRAuction" code="1" postion="14:23" />
  <token name="a" code="1" postion="24:25" />
</tokenList>

[2019-09-13 17:13:02 #25 query.tokenizer] 
<token name="QUERY" code="67" postion="0:0">
  <token name="SELECT" code="132" postion="0:6">
    <token name="a" code="1" postion="7:8" />
  </token>
  <token name="FROM" code="103" postion="9:13">
    <token name="a" code="1" postion="24:25">
      <token name="MRAuction" code="1" postion="14:23" />
    </token>
  </token>
</token>

[2019-09-13 17:13:02 #26 *] 
com.objectdb.o.TEX: Type MRAuction is not found
    at com.objectdb.o.MSG.b(MSG.java:110)
    at com.objectdb.o.TRS.b(TRS.java:214)
    at com.objectdb.o.SYR.g(SYR.java:261)
    at com.objectdb.o.SYR.f(SYR.java:190)
    at com.objectdb.o.QRC.<init>(QRC.java:158)
    at com.objectdb.o.QRM.ZX(QRM.java:272)
    at com.objectdb.o.MST.ZX(MST.java:1019)
    at com.objectdb.o.WRA.ZX(WRA.java:313)
    at com.objectdb.o.WSM.ZX(WSM.java:117)
    at com.objectdb.o.QRR.k(QRR.java:260)
    at com.objectdb.o.QRR.i(QRR.java:154)
    at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:721)
    at common.app.AuQuery.all(AuQuery.groovy:17)
    at common.app.AuQuery.all(AuQuery.groovy)
    at common.app.AuQuery$all$0.call(Unknown Source)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:115)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:127)
    at mr.controllers.MRController.tick(MRController.groovy:17)
    at common.app.Heartbeat.handle(Heartbeat.groovy:43)
    at common.app.Transactor.execute(Transactor.groovy:109)
    at common.app.Transactor.access$0(Transactor.groovy)
    at common.app.Transactor$_handleRequest_closure1.doCall(Transactor.groovy:34)
    at common.app.Transactor$_handleRequest_closure1.call(Transactor.groovy)
    at common.app.Database.transact(Database.groovy:76)
    at common.app.Transactor.handleRequest(Transactor.groovy:24)
    at common.app.RedisService$2.message(RedisService.groovy:135)
    at common.app.RedisService$2.message(RedisService.groovy)
    at io.lettuce.core.pubsub.PubSubEndpoint.notifyListeners(PubSubEndpoint.java:185)
    at io.lettuce.core.pubsub.PubSubEndpoint.notifyMessage(PubSubEndpoint.java:174)
    at io.lettuce.core.pubsub.PubSubCommandHandler.doNotifyMessage(PubSubCommandHandler.java:214)
    at io.lettuce.core.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:120)
    at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:556)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1421)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:697)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:632)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:549)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:511)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)

[2019-09-13 17:13:03 #27 query.manager] 
<queryRequest query="SELECT a FROM Site a" args="null" transactionId="-1" />

[2019-09-13 17:13:03 #28 query.manager] 
<validCachedQueryResponse isUnique="false" resultSize="1" fetchSize="0">
  <SimpleResultBuilder name="a" type="common.model.Site" />
</validCachedQueryResponse>

[2019-09-13 17:13:03 #29 query.manager] 
<queryRequest query="SELECT a FROM MRAuction a" args="null" transactionId="-1" />

[2019-09-13 17:13:03 #30 query.tokenizer] 
<tokenList>
  <token name="SELECT" code="132" postion="0:6" />
  <token name="a" code="1" postion="7:8" />
  <token name="FROM" code="103" postion="9:13" />
  <token name="MRAuction" code="1" postion="14:23" />
  <token name="a" code="1" postion="24:25" />
</tokenList>

[2019-09-13 17:13:03 #31 query.tokenizer] 
<token name="QUERY" code="67" postion="0:0">
  <token name="SELECT" code="132" postion="0:6">
    <token name="a" code="1" postion="7:8" />
  </token>
  <token name="FROM" code="103" postion="9:13">
    <token name="a" code="1" postion="24:25">
      <token name="MRAuction" code="1" postion="14:23" />
    </token>
  </token>
</token>

#2

> Noticing very poor performance from ObjectDB, not exactly sure what the problem is.

Try to isolate the slow performance, e.g. is it related to a specific operation or query?

Using entity classes that are not enhanced may be related or not.

> Then another process tries to enhance again.

This is the Enhancer Agent. Try to disable it.

> Then the previously enhanced classes are not found.

Sometimes classes are loaded by the JVM before the enhancement in the main. However, in that case running your application again should use the enhanced classes. If the classes are enhanced but cannot be found it could be a class loader conflict.

ObjectDB Support

Reply