How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

classic Classic list List threaded Threaded
15 messages Options
Reply | Threaded
Open this post in threaded view
|

How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
Please, disregard the other message. This one is more accurate. Actually
B has a belongsTo relationship to C.

I have the following situation in my application. A has many B and B
belongs to C and all associations are lazy.

When I try to get the "B" associations from an A instance method inside
a thread, it is trying to instantiate C for some unknown reason. For
trying to figure out who is creating the C instance, I've implemented
something like this:

class A {
     static hasMany = [b: B]

     def someMethod() {
          if (b.every { it.someProperty }) return false
          ...
      }
}

class B {
     static belongsTo = [c: C]

     String someProperty // nullable: true
}

class C {
     C(){
         try {1/0} catch(e) { log.error "Shouldn't be instantiated", e }
     }
}

When I take a look at target/stacktrace.log, I get something like this:

2012-02-24 18:11:40,046 [pool-8-thread-3] ERROR StackTrace  - Full Stack
Trace:
java.lang.ArithmeticException: Division by zero
         at java.math.BigDecimal.divide(BigDecimal.java:1655)
         at myapp.C.<init>(C.groovy:xxx)
         at java.lang.Class.newInstance0(Class.java:355)
         at java.lang.Class.newInstance(Class.java:308)
         at myapp.A.someMethod(A.groovy:xxx)
         at
myapp.MyBatchService$_someMethod_closure2_closure4_closure5.doCall(MyBatchService.groovy:xxx)
         at
grails.plugin.executor.PersistenceContextCallableWrapper$_call_closure1.doCall(PersistenceContextCallableWrapper.groovy:36)
         at
grails.plugin.executor.PersistenceContextWrapper.wrap(PersistenceContextWrapper.groovy:35)
         at
grails.plugin.executor.PersistenceContextCallableWrapper.call(PersistenceContextCallableWrapper.groovy:36)
         at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
         at java.util.concurrent.FutureTask.run(FutureTask.java:138)
         at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
         at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
         at java.lang.Thread.run(Thread.java:662)


But this doesn't make any sense to me. It doesn't happen always, but I
don't understand this snippet:

         at myapp.C.<init>(C.groovy:xxx)
         at java.lang.Class.newInstance0(Class.java:355)
         at java.lang.Class.newInstance(Class.java:308)
         at myapp.A.someMethod(A.groovy:xxx)

The line at someMethod is something like this:

"if (b.every { it.someProperty }) return false"

So, why instantiating C is the first thing that shows up in the
stacktrace after this line? Shouldn't other Hibernate methods be called
before trying to instantiate C?

With this stacktrace I'm unable to figure out who is trying to
instantiate C.

Please, help me.

Regards,
Rodrigo.


P.S.: I didn't reply to my old thread because usually, when I do that,
no one will read my messages as they seem to be already answered.

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
On 24/02/2012 21:15, Rodrigo Rosenfeld Rosas wrote:
> With this stacktrace I'm unable to figure out who is trying to
> instantiate C.

I'd guess it's a lazy loading thing.  If the A.b Set is a lazy
association then the process of iterating over it will cause each B in
turn to be loaded from the database, filling it its property values (and
thus possibly instantiating a C), before the { it.someProperty } closure
is called.

This will be the case even if the belongsTo is a lazy proxy, as these
are implemented as cglib subclasses of the real class so the act of
creating the proxy must call super(), i.e. the no-argument constructor
of C.  This is why it's generally a bad idea to put logic in the
constructors of classes you're using with Spring AOP, and they suggest
you put the logic in a @PostConstruct annotated method instead.

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
On 24/02/2012 21:39, Ian Roberts wrote:
> This will be the case even if the belongsTo is a lazy proxy, as these
> are implemented as cglib subclasses of the real class

Or indeed javassist, but the same principle applies.

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
In reply to this post by Ian Roberts
Em 24-02-2012 19:39, Ian Roberts escreveu:
> On 24/02/2012 21:15, Rodrigo Rosenfeld Rosas wrote:
>> With this stacktrace I'm unable to figure out who is trying to
>> instantiate C.
> I'd guess it's a lazy loading thing.  If the A.b Set is a lazy
> association then the process of iterating over it will cause each B in
> turn to be loaded from the database, filling it its property values (and
> thus possibly instantiating a C), before the { it.someProperty } closure
> is called.

But shouldn't this behavior be consistent?

What is happening in my application is that sometimes C is instantiated
while it isn't for other A instances.

Anyway, instantiating C requires several queries to the database which
is very time consuming when I don't need them for my batch processing.

As I don't need/use any c instance (neither directly or indirectly), I'd
like to make sure it is not loaded from database.

How can I assure that?

> This will be the case even if the belongsTo is a lazy proxy, as these
> are implemented as cglib subclasses of the real class so the act of
> creating the proxy must call super(), i.e. the no-argument constructor
> of C.

>    This is why it's generally a bad idea to put logic in the
> constructors of classes you're using with Spring AOP, and they suggest
> you put the logic in a @PostConstruct annotated method instead.

I don't use constructors in my domain classes, I've just created this
one because I'd like to understand who is creating such an instance.

But the real question is why the stacktrace is incomplete?!

How can I try to avoid loading the C association if I don't know what is
triggering it?

Thanks for your insights anyway!

Cheers,
Rodrigo.

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
In reply to this post by Ian Roberts
Em 24-02-2012 19:42, Ian Roberts escreveu:
> On 24/02/2012 21:39, Ian Roberts wrote:
>> This will be the case even if the belongsTo is a lazy proxy, as these
>> are implemented as cglib subclasses of the real class
> Or indeed javassist, but the same principle applies.

Are you saying that runtime-generated classes from cglib/javassist
wouldn't show up in the Stacktrace?

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
In reply to this post by rosenfeld
On 25/02/2012 04:57, Rodrigo Rosenfeld Rosas wrote:
> I don't use constructors in my domain classes, I've just created this
> one because I'd like to understand who is creating such an instance.
>
> But the real question is why the stacktrace is incomplete?!
>
> How can I try to avoid loading the C association if I don't know what is
> triggering it?

That's my point - if the association to C is lazy then Hibernate will
not fetch it from the database immediately.  It will create a proxy
object that knows its database ID but the actual SQL queries to populate
the data of the C should only happen the first time something tries to
get one of the (non-id) property values from the C object.

*But* because the class of the proxy object is a subclass of C, the act
of creating the proxy must call the C() constructor.  This doesn't
necessarily mean it's touched the corresponding database table, you'd
need to use SQL logging to determine that.

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
In reply to this post by rosenfeld
On 25/02/2012 04:57, Rodrigo Rosenfeld Rosas wrote:
> But the real question is why the stacktrace is incomplete?!

Have a look further up your stacktrace.log...

Looking again at the original trace you posted it looks like that is a
filtered trace rather than a "full" one as it doesn't include any of the
groovy metaclass stack frames I'd expect of a full trace.

I've just been looking at the code for DefaultStackTraceFilterer (which
is responsible for logging full stack traces to stacktrace.log as it is
in the process of filtering them), and I noticed this:

    public Throwable filter(Throwable source, boolean recursive) {
        if (recursive) {
            Throwable current = source;
            while (current != null) {
                current = filter(current);
                current = current.getCause();
            }
        }
        return filter(source);
    }

The single-argument filter(Throwable) method that this calls is what
actually logs the "full" trace to stacktrace.log just before replacing
it with the filtered one.  Notice that in recursive mode the topmost
exception will be passed to filter(Throwable) *twice*, once during the
cause-chasing loop and again at the return.  The second time the "full"
trace that is logged will be the already-filtered one from the first
call, so to find the real full trace you'll have to look further back in
stacktrace.log to find the first mention.

I'll try and put together a JIRA for this.

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
In reply to this post by Ian Roberts
Em 25-02-2012 09:12, Ian Roberts escreveu:

> On 25/02/2012 04:57, Rodrigo Rosenfeld Rosas wrote:
>> I don't use constructors in my domain classes, I've just created this
>> one because I'd like to understand who is creating such an instance.
>>
>> But the real question is why the stacktrace is incomplete?!
>>
>> How can I try to avoid loading the C association if I don't know what is
>> triggering it?
> That's my point - if the association to C is lazy then Hibernate will
> not fetch it from the database immediately.  It will create a proxy
> object that knows its database ID but the actual SQL queries to populate
> the data of the C should only happen the first time something tries to
> get one of the (non-id) property values from the C object.
>
> *But* because the class of the proxy object is a subclass of C, the act
> of creating the proxy must call the C() constructor.  This doesn't
> necessarily mean it's touched the corresponding database table, you'd
> need to use SQL logging to determine that.

I think you didn't get the intention of my C constructor. I don't expect
a C instance to be created.

 From A, I need the list of B from the relationship and a property from
B, but that property is not "c", so C should never been created from my
point of view since it is a lazy association. I've created a constructor
for C to try to understand who is creating its instance.

Let me write the relevant part of the classes here again:

class A{
     static hasMany = [b: B]
     def someMethod() {
         if (b.every{it.nonCProperty}) return // You can see I don't
need C here, but it is being created on this line.
         ...
     }
}

class B {
     String nonCProperty

     static belongsTo = [c: C]
}

So, why is C being instantiated by A.someMethod()? I don't need C in
this method. Not even its id. Also, in my case, the associations from C
are also being loaded from the database according to the MySql logs. And
that is very expensive.

I want to be able to read "new A().b.nonCPropery" without triggering a
load of "b.c".

Is that possible?


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
In reply to this post by Ian Roberts
Em 25-02-2012 10:17, Ian Roberts escreveu:

> On 25/02/2012 04:57, Rodrigo Rosenfeld Rosas wrote:
>> But the real question is why the stacktrace is incomplete?!
> Have a look further up your stacktrace.log...
>
> Looking again at the original trace you posted it looks like that is a
> filtered trace rather than a "full" one as it doesn't include any of the
> groovy metaclass stack frames I'd expect of a full trace.
>
> I've just been looking at the code for DefaultStackTraceFilterer (which
> is responsible for logging full stack traces to stacktrace.log as it is
> in the process of filtering them), and I noticed this:
>
>      public Throwable filter(Throwable source, boolean recursive) {
>          if (recursive) {
>              Throwable current = source;
>              while (current != null) {
>                  current = filter(current);
>                  current = current.getCause();
>              }
>          }
>          return filter(source);
>      }
>
> The single-argument filter(Throwable) method that this calls is what
> actually logs the "full" trace to stacktrace.log just before replacing
> it with the filtered one.  Notice that in recursive mode the topmost
> exception will be passed to filter(Throwable) *twice*, once during the
> cause-chasing loop and again at the return.  The second time the "full"
> trace that is logged will be the already-filtered one from the first
> call, so to find the real full trace you'll have to look further back in
> stacktrace.log to find the first mention.
>
> I'll try and put together a JIRA for this.

You're right, thanks, I couldn't find it before because it wasn't
filtered twice but several times from my pool of threads but I took a
look way before and could find the full stacktrace, thanks!

If you're curious, here is what it looks like:

2012-02-24 18:11:40,180 [pool-8-thread-8] ERROR StackTrace  - Full Stack
Trace:
java.lang.ArithmeticException: Division by zero
     at java.math.BigDecimal.divide(BigDecimal.java:1655)
     at
org.codehaus.groovy.runtime.typehandling.BigDecimalMath.divideImpl(BigDecimalMath.java:66)
     at
org.codehaus.groovy.runtime.typehandling.IntegerMath.divideImpl(IntegerMath.java:46)
     at
org.codehaus.groovy.runtime.dgmimpl.NumberNumberDiv$NumberNumber.invoke(NumberNumberDiv.java:320)
     at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:53)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
     at myapp.C.<init>(C.groovy:xxx)
     at myapp.C_$$_javassist_45.<init>(A_$$_javassist_45.java)
     at sun.reflect.GeneratedConstructorAccessor141.newInstance(Unknown
Source)
     at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
     at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
     at java.lang.Class.newInstance0(Class.java:355)
     at java.lang.Class.newInstance(Class.java:308)
     at
org.codehaus.groovy.grails.orm.hibernate.proxy.GroovyAwareJavassistLazyInitializer.getProxy(GroovyAwareJavassistLazyInitializer.java:140)
     at
org.codehaus.groovy.grails.orm.hibernate.proxy.GroovyAwareJavassistProxyFactory.getProxy(GroovyAwareJavassistProxyFactory.java:64)
     at
org.codehaus.groovy.grails.orm.hibernate.persister.entity.GroovyAwareSingleTableEntityPersister.createProxy(GroovyAwareSingleTableEntityPersister.java:49)
     at
org.hibernate.event.def.DefaultLoadEventListener.createProxyIfNecessary(DefaultLoadEventListener.java:360)
     at
org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:281)
     at
org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152)
     at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090)
     at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038)
     at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630)
     at org.hibernate.type.EntityType.resolve(EntityType.java:438)
     at
org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:139)
     at
org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:982)
     at org.hibernate.loader.Loader.doQuery(Loader.java:857)
     at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
     at org.hibernate.loader.Loader.loadCollection(Loader.java:2166)
     at
org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:62)
     at
org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:627)
     at
org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:83)
     at
org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1863)
     at
org.hibernate.collection.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:369)
     at
org.hibernate.collection.AbstractPersistentCollection.read(AbstractPersistentCollection.java:111)
     at
org.hibernate.collection.PersistentSet.iterator(PersistentSet.java:186)
     at sun.reflect.GeneratedMethodAccessor324.invoke(Unknown Source)
     at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
     at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
     at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1047)
     at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:877)
     at
org.codehaus.groovy.runtime.InvokerHelper.invokePojoMethod(InvokerHelper.java:781)
     at
org.codehaus.groovy.runtime.InvokerHelper.invokeMethod(InvokerHelper.java:772)
     at
org.codehaus.groovy.runtime.InvokerHelper.asIterator(InvokerHelper.java:500)
     at
org.codehaus.groovy.runtime.DefaultGroovyMethods.every(DefaultGroovyMethods.java:1501)
     at org.codehaus.groovy.runtime.dgm$215.invoke(Unknown Source)
     at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:271)
     at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:53)
     at
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:42)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
     at myapp.A.myMethod(A.groovy:xxx)
     at myapp.A$myMethod$1.call(Unknown Source)
     at
myapp.MyService$_someMethod_closure2_closure4_closure5.doCall(MyService.groovy:xxx)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
     at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
     at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
     at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:877)
     at
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:66)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:141)
     at
myapp.MyService$_someMethod_closure2_closure4_closure5.doCall(MyService.groovy)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
     at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
     at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
     at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:877)
     at
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.call(PogoMetaClassSite.java:39)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:112)
     at
grails.plugin.executor.PersistenceContextCallableWrapper$_call_closure1.doCall(PersistenceContextCallableWrapper.groovy:36)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
     at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
     at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
     at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:877)
     at
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:66)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:141)
     at
grails.plugin.executor.PersistenceContextCallableWrapper$_call_closure1.doCall(PersistenceContextCallableWrapper.groovy)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
     at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
     at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
     at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:877)
     at
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.call(PogoMetaClassSite.java:39)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:112)
     at
grails.plugin.executor.PersistenceContextWrapper.wrap(PersistenceContextWrapper.groovy:35)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at
org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:267)
     at
org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:52)
     at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:141)
     at
grails.plugin.executor.PersistenceContextCallableWrapper.call(PersistenceContextCallableWrapper.groovy:36)
     at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
     at java.util.concurrent.FutureTask.run(FutureTask.java:138)
     at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
     at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
     at java.lang.Thread.run(Thread.java:662)






Have a great weekend!

Cheers,
Rodrigo.

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
In reply to this post by rosenfeld
On 25/02/2012 12:34, Rodrigo Rosenfeld Rosas wrote:
> So, why is C being instantiated by A.someMethod()? I don't need C in
> this method. Not even its id.

It isn't creating an instance of the class C, it's creating an instance
of a dynamically generated proxy class that is a subclass of C, which is
how Hibernate implements a lazy association.  All Java constructors
apart from java.lang.Object you *must* directly or indirectly call their
superclass constructor, and that is what's happening in the stack trace
you posted:

    at myapp.C.<init>(C.groovy:xxx)
    at myapp.C_$$_javassist_45.<init>(A_$$_javassist_45.java)

The C constructor call that fails here is during construction *of the
proxy*, it does *not* mean that it's necessarily loading any C data from
the DB at this point.  I'm not sure how I can make this any clearer.

> Also, in my case, the associations from C
> are also being loaded from the database according to the MySql logs. And
> that is very expensive.

To debug this I'd declare an onLoad event in C and log the stack trace
there instead of in the constructor, to find the point where the DB load
happens as opposed to the point where the lazy proxy is created.

> I want to be able to read "new A().b.nonCPropery" without triggering a
> load of "b.c".
>
> Is that possible?

It certainly ought to be...

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
I've just created a JIRA with an example application:

http://jira.grails.org/browse/GRAILS-8842

Notice that a new instance of C won't be created in the first run.

I know it is actually fetching data from the database because I first noticed that looking at my MySql log.

Please, let me know if it happens the same to you.

Best,
Rodrigo.

Em 25-02-2012 11:04, Ian Roberts escreveu:
On 25/02/2012 12:34, Rodrigo Rosenfeld Rosas wrote:
So, why is C being instantiated by A.someMethod()? I don't need C in
this method. Not even its id.
It isn't creating an instance of the class C, it's creating an instance
of a dynamically generated proxy class that is a subclass of C, which is
how Hibernate implements a lazy association.  All Java constructors
apart from java.lang.Object you *must* directly or indirectly call their
superclass constructor, and that is what's happening in the stack trace
you posted:

    at myapp.C.<init>(C.groovy:xxx)
    at myapp.C_$$_javassist_45.<init>(A_$$_javassist_45.java)

The C constructor call that fails here is during construction *of the
proxy*, it does *not* mean that it's necessarily loading any C data from
the DB at this point.  I'm not sure how I can make this any clearer.

Also, in my case, the associations from C
are also being loaded from the database according to the MySql logs. And
that is very expensive.
To debug this I'd declare an onLoad event in C and log the stack trace
there instead of in the constructor, to find the point where the DB load
happens as opposed to the point where the lazy proxy is created.

I want to be able to read "new A().b.nonCPropery" without triggering a
load of "b.c".

Is that possible?
It certainly ought to be...

Ian


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
On 25/02/2012 14:14, Rodrigo Rosenfeld Rosas wrote:

> I've just created a JIRA with an example application:
>
> http://jira.grails.org/browse/GRAILS-8842
>
> Notice that a new instance of C won't be created in the first run.
>
> I know it is actually fetching data from the database because I first
> noticed that looking at my MySql log.
>
> Please, let me know if it happens the same to you.

You're still missing the point.  Yes, the C constructor gets called but
that doesn't mean it's loading from the DB.  I just modified your C
class from:

package associations

class C {
    C(){ log.error "C was instantiated" }
}

to:

package associations

class C {
    def onLoad(){ log.error "C was loaded from DB" }
}

So it would log actual DB loads rather than proxy instantiations and I
don't get any "C was loaded" log messages.  I even added another
property to C just to make sure that it wasn't the fact that C has no
properties that was causing it not to load, but I still get no "C was
loaded" messages.

The lazy association is behaving exactly as it should in this case.

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
Em 25-02-2012 12:38, Ian Roberts escreveu:

> On 25/02/2012 14:14, Rodrigo Rosenfeld Rosas wrote:
>> I've just created a JIRA with an example application:
>>
>> http://jira.grails.org/browse/GRAILS-8842
>>
>> Notice that a new instance of C won't be created in the first run.
>>
>> I know it is actually fetching data from the database because I first
>> noticed that looking at my MySql log.
>>
>> Please, let me know if it happens the same to you.
> You're still missing the point.  Yes, the C constructor gets called but
> that doesn't mean it's loading from the DB.  I just modified your C
> class from:
>
> package associations
>
> class C {
>      C(){ log.error "C was instantiated" }
> }
>
> to:
>
> package associations
>
> class C {
>      def onLoad(){ log.error "C was loaded from DB" }
> }
>
> So it would log actual DB loads rather than proxy instantiations and I
> don't get any "C was loaded" log messages.  I even added another
> property to C just to make sure that it wasn't the fact that C has no
> properties that was causing it not to load, but I still get no "C was
> loaded" messages.
>
> The lazy association is behaving exactly as it should in this case.

I have already got your point from previous messages. I'm just saying
that the first time I noticed this behavior was by looking at my MySql
log where data was being fetch from C when it shouldn't.

Then, I've showed you that C isn't instantiated (even the proxy) the
first time "runTwice()" is called. Why is it instantiated from next time
onwards? That seems inconsistent to me.

I'm going down the road right now and will only be back tomorrow
afternoon. When I'm back, I'll setup a MySql database and watch its log
in my example application.

Then I'll be able to confirm if this example is actually reproducing my
real scenario or not if there are any queries to the "c" table in the
logs after calling "runTwice()".

You didn't prove anything anyway just by looking at the onLoad() method.
Other bugs may exist that will prevent onLoad() from being called, so
the only reliable way to make sure if it is working as expected is
looking at the SQL server log.

That is what I intend to do when I'm back.

Best,
Rodrigo.


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

Ian Roberts
On 25/02/2012 15:27, Rodrigo Rosenfeld Rosas wrote:
> I have already got your point from previous messages. I'm just saying
> that the first time I noticed this behavior was by looking at my MySql
> log where data was being fetch from C when it shouldn't.
>
> Then, I've showed you that C isn't instantiated (even the proxy) the
> first time "runTwice()" is called. Why is it instantiated from next time
> onwards? That seems inconsistent to me.

OK, sorry, it was me that missed your point rather than vice versa.  I
think it's down to a race between createSampleData and callAsync in your
example MyService - because you don't have a flush anywhere in
createSampleData then (even with the connection.commit) your sample data
doesn't persist to the database until the end of the containing
transaction (i.e. the point where runTwice returns) so the first
callAsync sees and empty database.

I made myService non-transactional and wrapped a withTransaction around
the body of createSampleData and now I see the "correct" log messages
from the C constructor for both the first and second calls.

Ian

--
Ian Roberts               | Department of Computer Science
[hidden email]  | University of Sheffield, UK

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: How to get the *full* stacktrace from target/stacktrace.log? (disregard the other mesage)

rosenfeld
Em 25-02-2012 14:16, Ian Roberts escreveu:
On 25/02/2012 15:27, Rodrigo Rosenfeld Rosas wrote:
I have already got your point from previous messages. I'm just saying
that the first time I noticed this behavior was by looking at my MySql
log where data was being fetch from C when it shouldn't.

Then, I've showed you that C isn't instantiated (even the proxy) the
first time "runTwice()" is called. Why is it instantiated from next time
onwards? That seems inconsistent to me.
OK, sorry, it was me that missed your point rather than vice versa.  I
think it's down to a race between createSampleData and callAsync in your
example MyService - because you don't have a flush anywhere in
createSampleData then (even with the connection.commit) your sample data
doesn't persist to the database until the end of the containing
transaction (i.e. the point where runTwice returns) so the first
callAsync sees and empty database.

I made myService non-transactional and wrapped a withTransaction around
the body of createSampleData and now I see the "correct" log messages
from the C constructor for both the first and second calls.

Thanks for your comments, Ian. You were indeed right. Thanks to your explanations I could further understand what was causing the unneeded queries in my application.

If you're curious I've explained the reasons in my last comment in the created JIRA:

http://jira.grails.org/browse/GRAILS-8842?focusedCommentId=69666

Cheers,
Rodrigo.