Hello,
Firstly, apologies for the duplication - I was originally posting to Hibernate Users and have just realised that was probably the wrong forum for this problem (
http://forum.hibernate.org/viewtopic.php?t=974543), so I'm re-posting here...
Hibernate version: 3.2.2
Hibernate Annotations version: 3.3.0.GA
Hibernate EntityManager version: 3.3.0.GA
Database: MySql 5.0.27
JRE: 1.5.0_07 (Java HotSpot(TM) Server VM (build 1.5.0_07-87, mixed mode))
I'm having a problem loading objects where an inheritance hierarchy is involved. I have three entity types:
PlayerAccount
WalletPlayerAccount extends PlayerAccount
InternalPlayerAccount extends WalletPlayerAccount
None of these are abstract - an entity can be one of any of these three types.
The ORM specifies a Joined inheritance strategy:
Code:
<entity class="com.blah.PlayerAccount" access="FIELD">
<inheritance strategy="JOINED" />
<attributes>
<id name="id">
<generated-value strategy="AUTO" />
</id>
<basic name="firstName" optional="false" fetch="EAGER" />
<basic name="surname" optional="false" fetch="EAGER" />
[...snip...]
</attributes>
</entity>
<entity class="com.blah.WalletPlayerAccount" access="FIELD">
<attributes>
<basic name="walletBalance" optional="false" fetch="EAGER" />
</attributes>
</entity>
<entity class="com.blah.InternalPlayerAccount" access="FIELD">
<attributes>
[...snip - more stuff that's not very interesting]
</attributes>
</entity>
I have two accounts in the database:
Account with ID 1 is an InternalPlayerAccount (i.e. there is a row in each of the tables PlayerAccount, WalletPlayerAccount and InternalPlayerAccount, all of which have id=1).
Account with ID 2 is a WalletPlayerAccount (i.e. there is a row in each of the tables PlayerAccount and WalletPlayerAccount which both have id=2, but no row exists in InternalPlayerAccount with this id).
Note that both these accounts have been created via Hibernate (i.e. via instantiation of new objects and then calling EntityManager.persist()) - they do not exist as a result of dodgy hacking direct to database, so I'm sure there isn't a data bug.
Now, if I start my application and invoke some tests that cause repeated loading of the account with ID=1 then it always comes back correctly as an InternalPlayerAccount.
If I then invoke a test that causes the loading of the account with ID=2 then it comes back correctly as a WalletPlayerAccount.
So far so good. Now, if I try to reload the account with ID=1 it comes back as a WalletPlayerAccount, not an InternalPlayerAccount. I can check the database and nothing has changed between the finds. Furthermore if I restart the application then the account is loaded as an InternalPlayerAccount again (until I load a WalletPlayerAccount that is, when the problem resurfaces again).
I can't understand what I'm doing wrong, especially as the entity with ID=1 loads properly until the object with ID=2 is first loaded. I have deliberately missed out a few things from the code above which I don't believe are relevant, but will happily be more verbose if anyone wants more info.
Many thanks
Darren
...followup post...I'm still investigating this and have some more diagnostics.
Firstly, when performing the eager find that's causing the problem, I was using a named-query that performed LEFT JOIN FETCHes for PlayerAccount's lazy relationships and then calling Hibernate.initialize() to load the subclass lazy relationships. I've replaced the named-query execution with an EntityManager.find( Class, id ) (again followed by a bunch of Hibernate.initialize() calls where necessary) to see if that was causing the problem, but it has made no difference.
So, I inspected the SQL that Hibernate generates and found there is no difference between the SQL generated on the first call (which succeeds) and the last call (which returns the wrong type). For reference, here it is:
Code:
select playeracco0_.id as id13_1_,
playeracco0_.accountSystem_id as accountS6_13_1_,
playeracco0_.failedLoginAttemptCount as failedLo2_13_1_,
playeracco0_.locked as locked13_1_,
playeracco0_.preferredOutlet_id as preferre7_13_1_,
playeracco0_.suspended as suspended13_1_,
playeracco0_.username as username13_1_,
playeracco0_1_.nonWithdrawableBalance as nonWithd2_14_1_,
playeracco0_1_.withdrawableBalance as withdraw3_14_1_,
playeracco0_2_.accountNumber as accountN2_15_1_,
playeracco0_2_.accountSystemId as accountS3_15_1_,
playeracco0_2_.address_id as address21_15_1_,
playeracco0_2_.challengeAnswer as challeng4_15_1_,
playeracco0_2_.challengeQuestion_id as challen20_15_1_,
playeracco0_2_.contactableByOthers as contacta5_15_1_,
playeracco0_2_.contactableByUs as contacta6_15_1_,
playeracco0_2_.dob as dob15_1_,
playeracco0_2_.email as email15_1_,
playeracco0_2_.encPin as encPin15_1_,
playeracco0_2_.firstName as firstName15_1_,
playeracco0_2_.lastName as lastName15_1_,
playeracco0_2_.over18 as over12_15_1_,
playeracco0_2_.paymentCard_id as payment19_15_1_,
playeracco0_2_.pinIsOneShot as pinIsOn13_15_1_,
playeracco0_2_.registrationDate as registr14_15_1_,
playeracco0_2_.significantDate as signifi15_15_1_,
playeracco0_2_.telephone as telephone15_1_,
playeracco0_2_.termsAndCondsAccepted as termsAn17_15_1_,
playeracco0_2_.title as title15_1_,
case when playeracco0_2_.id is not null then 2
when playeracco0_1_.id is not null then 1
when playeracco0_.id is not null then 0 end as clazz_1_,
accountsys1_.id as id3_0_,
accountsys1_.adapterClass as adapterC2_3_0_,
accountsys1_.encAdapterClassConfigXml as encAdapt3_3_0_,
accountsys1_.internal as internal3_0_,
accountsys1_.name as name3_0_,
accountsys1_.supportsCashDeposits as supports6_3_0_,
accountsys1_.supportsReconciliation as supports7_3_0_,
accountsys1_.tag as tag3_0_
from PlayerAccount playeracco0_
left outer join WalletPlayerAccount playeracco0_1_ on playeracco0_.id=playeracco0_1_.id
left outer join InternalPlayerAccount playeracco0_2_ on playeracco0_.id=playeracco0_2_.id
inner join AccountSystem accountsys1_ on playeracco0_.accountSystem_id=accountsys1_.id
where playeracco0_.id=?
Next, I stepped through in the debugger...
1) the first find (an InternalPlayerAccount with ID=1) succeeded as before (repeated 5 times, no problem)
2) the next find (a WalletPlayerAccount with ID=2) succeeded as before (repeated 5 times, no problem)
3) the next find (the InternalPlayerAccount with ID=1 again) failed on the first attempt. (Actually, as explained previously, it doesn't *fail* but it returns an entity of type WalletPlayerAccount instead of InternalPlayerAccount.
Whilst in the debugger and immediately prior to step (3) above, I switched to a query tool and executed the SQL above to see if bad data was being returned (specifically whether nulls are returned for the InternalPlayerAccount columns), but everything looked good and valid data was returned from all three *Account tables.
In case it helps, here is the Hibernate log output. This first extract corresponds to step (1) in the list above, i.e. a successful find:
Code:
2007-05-17 10:40:59.265 FINE org.hibernate.SQL select playeracco0_.id as id13_1_, [snip - see SQL above]
2007-05-17 10:40:59.268 FINE org.hibernate.jdbc.AbstractBatcher about to open ResultSet (open ResultSets: 0, globally: 0)
2007-05-17 10:40:59.269 FINE org.hibernate.loader.Loader result set row: 0
2007-05-17 10:40:59.271 FINE org.hibernate.loader.Loader result row: EntityKey[com.evolvegaming.lgp.AccountSystem#1], EntityKey[com.evolvegaming.lgp.PlayerAccount#1]
2007-05-17 10:40:59.278 FINE org.hibernate.jdbc.AbstractBatcher about to close ResultSet (open ResultSets: 1, globally: 1)
2007-05-17 10:40:59.278 FINE org.hibernate.jdbc.AbstractBatcher about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-05-17 10:40:59.278 FINE org.hibernate.jdbc.ConnectionManager aggressively releasing JDBC connection
2007-05-17 10:40:59.279 FINE org.hibernate.jdbc.ConnectionManager releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-05-17 10:40:59.279 FINE org.hibernate.engine.TwoPhaseLoad resolving associations for [com.evolvegaming.lgp.AccountSystem#1]
2007-05-17 10:40:59.280 FINE org.hibernate.engine.TwoPhaseLoad done materializing entity [com.evolvegaming.lgp.AccountSystem#1]
2007-05-17 10:40:59.280 FINE org.hibernate.engine.TwoPhaseLoad resolving associations for [com.evolvegaming.lgp.InternalPlayerAccount#1]
2007-05-17 10:40:59.282 FINE org.hibernate.engine.TwoPhaseLoad done materializing entity [com.evolvegaming.lgp.InternalPlayerAccount#1]
2007-05-17 10:40:59.282 FINE org.hibernate.engine.StatefulPersistenceContext initializing non-lazy collections
2007-05-17 10:40:59.282 FINE org.hibernate.loader.Loader done entity load
2007-05-17 10:40:59.283 FINE org.hibernate.jdbc.ConnectionManager aggressively releasing JDBC connection
This second extract corresponds to step (3) in the list above, i.e. a find that returns an entity of the incorrect type.
Code:
2007-05-17 10:41:00.771 FINE org.hibernate.SQL select playeracco0_.id as id13_1_, [snip - see SQL above]
2007-05-17 10:41:00.773 FINE org.hibernate.jdbc.AbstractBatcher about to open ResultSet (open ResultSets: 0, globally: 0)
2007-05-17 10:41:00.774 FINE org.hibernate.loader.Loader result set row: 0
2007-05-17 10:41:00.774 FINE org.hibernate.loader.Loader result row: EntityKey[com.evolvegaming.lgp.AccountSystem#1], EntityKey[com.evolvegaming.lgp.PlayerAccount#1]
2007-05-17 10:41:00.777 FINE org.hibernate.jdbc.AbstractBatcher about to close ResultSet (open ResultSets: 1, globally: 1)
2007-05-17 10:41:00.778 FINE org.hibernate.jdbc.AbstractBatcher about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-05-17 10:41:00.778 FINE org.hibernate.jdbc.ConnectionManager aggressively releasing JDBC connection
2007-05-17 10:41:00.778 FINE org.hibernate.jdbc.ConnectionManager releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-05-17 10:41:00.779 FINE org.hibernate.engine.TwoPhaseLoad resolving associations for [com.evolvegaming.lgp.AccountSystem#1]
2007-05-17 10:41:00.779 FINE org.hibernate.engine.TwoPhaseLoad done materializing entity [com.evolvegaming.lgp.AccountSystem#1]
2007-05-17 10:41:00.780 FINE org.hibernate.engine.TwoPhaseLoad resolving associations for [com.evolvegaming.lgp.WalletPlayerAccount#1]
2007-05-17 10:41:00.781 FINE org.hibernate.engine.TwoPhaseLoad done materializing entity [com.evolvegaming.lgp.WalletPlayerAccount#1]
2007-05-17 10:41:00.781 FINE org.hibernate.engine.StatefulPersistenceContext initializing non-lazy collections
2007-05-17 10:41:00.781 FINE org.hibernate.loader.Loader done entity load
2007-05-17 10:41:00.781 FINE org.hibernate.jdbc.ConnectionManager aggressively releasing JDBC connection
The most interesting bits to my mind are the last two org.hibernate.engine.TwoPhaseLoad entries in each extract - in the first extract it resolves/materializes InternalPlayerAccount and in the second extract WalletPlayerAccount.
I'm going to continue investigating, but if this is ringing bells for anyone, I'd really appreciate any thoughts/comments/suggestions.
Darren
...followup post... I think I'm getting somewhere... as I said previously, I'm reproducing the problem consistently by performing the following steps:
1) Finding an InternalPlayerAccount with ID=1 succeeds (repeated 5 times, no problem)
2) Finding a WalletPlayerAccount with ID=2 succeeds (repeated 5 times, no problem)
3) Finding the InternalPlayerAccount with ID=1 again returns an entity of type WalletPlayerAccount instead of InternalPlayerAccount on the first attempt.
and the actual logic looks something like this:
Code:
int outerLoopLimit = 5;
int innerLoopLimit = 5;
try {
for( int h=0; h<outerLoopLimit; h++ ) {
for( int i=0 ; i<innerLoopLimit; i++ ) {
findPlayerAccount(1); //i.e. the InternalPlayerAccount with id=1
}
for( int i=0 ; i<innerLoopLimit; i++ ) {
findPlayerAccount(2); //i.e. the WalletPlayerAccount with id=2
}
}
} catch( Throwable t ) {
t.printStackTrace();
}
When I execute this, the code gets through the first inner loop all five times without a problem. It then gets through the second inner loop OK and starts to re-iterate the outer loop. It then fails on the first execution of findPlayerAccount(1).
So, I tried playing with the values of innerLoopLimit. If I increase it, the behaviour described above is always the same - first outer iteration succeeds, then the first iteration of the first inner loop fails.
However, if I decrease the innerLoopLimit to two, I find this isn't the case - loading the account with id=1 succeeds even on the second iteration of the outer loop until the 6th time in total, at which point it fails as before. I decrease the innerLoopLimit to one and see the same - I get 5 good finds of account with id=1 (even after loading a WalletPlayerAccount), then fail on the 6th.
This seemed fishy, I looked through my persistence.xml and noticed c3p0's connection pool min_size=5
Code:
<property name="hibernate.c3p0.min_size" value="5" />
<property name="hibernate.c3p0.max_size" value="20" />
<property name="hibernate.c3p0.timeout" value="1800" />
<property name="hibernate.c3p0.max_statements" value="100" />
I tried removing the c3p0-related properties from configuration altogether and my problem dissapears!
So, does anybody think this could be a C3P0 bug, or could it still be something I'm doing wrong (in which case all suggestions appreciated!)
Darren