[eclipselink-users] Disappearing Items from a Collection Part 2

[Tim McNerney <mcnerney@xxxxxxxxx>]

I've managed to get in a situation where this is happening again.
Darned refactoring. But I have some more details.

Let me throw out my domain model again, with a nod to Paul Graham:

@MappedSuperclass
BaseEntity {
  @Id
  Integer id;
}

@Entity
@Table(name = "employee")
@Inheritance(strategy = InheritanceType.SINGLE_TABLE)
@DiscriminatorColumn(name = "type", discriminatorType =
DiscriminatorType.INTEGER)
BaseEmployee extends BaseEntity {
  @OneToMany(mappedBy = "employee", fetch = FetchType.EAGER)
  Collection<Phonenumber> phonenumbers;
  @Column(name = "type")
  protected Integer type;
}

@Entity
@DiscriminatorValue("1")
Manager extends BaseEmployee {
  @OneToMany(mappedBy = "manager", fetch = FetchType.EAGER)
  private Collection<Maker> makers;
}

@Entity
@DiscriminatorValue("2")
Maker extends BaseEmployee {
  @ManyToOne(cascade = {}, fetch = FetchType.EAGER)
  @JoinColumn(name = "manager_id", referencedColumnName = "id")
  private Manager manager;
}

@Entity
@Table(name = "phonenumber")
Phonenumber extends BaseEntity {
  @Column(name = "number")
  private String number;
  @ManyToOne(cascade = {}, fetch = FetchType.EAGER)
  @JoinColumn(name = "employee_id", referencedColumnName = "id")
  private BaseEmployee employee;
}

I hope this is adequate information. I tried to distill the relevant
information. persistence.xml looks like:

 <persistence-unit name="empl" transaction-type="RESOURCE_LOCAL">
  <provider>org.eclipse.persistence.jpa.PersistenceProvider</provider>
  <class>ent.Maker</class>
  <class>ent.Manager</class>
  <class>ent.BaseEmployee</class>
  <class>ent.Phonenumber</class>
  <properties>
    <property name="eclipselink.cache.shared.default" value="false"/>
  </properties>

I've turned off caching as suggested in my previous email. I'm
retrieving the Manager in this case, and therefore the Manager's
Phonenumbers, the Makers list and the Maker's Phonenumbers.

In two separate sequential calls, I add a Phonenumber to the Maker and
then retrieve the Manager and the new Phonenumber does not appear in
the list, though I can confirm it is in the database. If I add yet
another Phonenumber to the Maker and then retrieve the Manager again,
I get the first added Phonenumber, but not the second.

I can continue this behavior and each time, the list of Phonenumbers
is always one behind. I can try to retrieve the Manager as many times
as I want, with it always missing an item. If at any point, I restart
the app, I get the entire list the next time I retrieve the Manager.

However, if I add a Phonenumber to the Manager instead of one of the
Manager's Makers, it always stays current.

If I look at the log to see what happens with the database, I see:

[EL Fine]--SELECT id FROM employee WHERE ((id = ?) AND (type = ?))
	bind => [26395, 1]
[EL Fine]--SELECT id FROM phonenumber WHERE (employee_id = ?)
	bind => [26395]
[EL Fine]--SELECT id FROM employee WHERE ((manager_id = ?) AND (type = ?))
	bind => [26395, 2]

So we are retrieving phonenumbers for the Manager, but not the Maker
in this instance. But I have made the fetching of the Makers as EAGER
as well as the Phonenumbers, so I'd expect to see:

SELECT id FROM phonenumber WHERE (employee_id = ?)
	bind => [26396]

since I have caching turned off.

* Any thoughts what might be happening?
* Any obvious mistakes I have made?
* Any additional information you need me to provide?
* Are there any troubleshooting steps I can make to figure out what
might be happening?

Thanks.

--Tim


On Tue, Nov 3, 2009 at 10:13 AM, Tim McNerney <mcnerney@xxxxxxxxx> wrote:
>> Very odd.
>>
>> Setting,
>> <property name="eclipselink.cache.shared.default" value="false"/>
>>
>> Is enough to disable the cache, do not set,
>> <property name="eclipselink.cache.size.default" value="0"/>
>> <property name="eclipselink.cache.type.default" value="None"/>
>
> OK. Next time I test, I will just use that one value. I started off
> with just that, but when it didn't seem to help, I kept adding the
> other options.
>
>>
>> But, given it still occurs with the cache disabled, it does not appear to be
>> a cache issue.  It seems to be a database/transactional issue.  You could
>> confirm this by executing a native SQL query through the same EntityManager
>> before calling size, to see what result you get back.
>
> I don't think it is a database issue, for a few reasons. It is
> transient in nature, with the entry appearing and then disappearing,
> which seems very odd for a database. Also, it does not happen at all
> once I set the fetch type to EAGER. If it were a database issue, I
> would expect that it would continue happening in that case, as it is
> still the same query, only it is called through a different mechanism
> (the origin fetch rather than through triggering it by accessing the
> collection). The database is MySQL 5.1.x, I'm using XtraDB (Percona's
> enhanced InnodDB). I can use Wireshark to snoop the actual JDBC
> request/response to confirm that the entry is in the payload (or if
> you happen to know a trick to log # of results through MySQL logging,
> I'd love to hear it).
>
>>
>> What does your,  persistenceSvc.beginTx() and
>> persistenceSvc.getEntityManager() methods do?
>> If you call em.clear(); before calling the find() and size, do you get the
>> same result?
>
>    public void beginTx() {
>        try {
>            utx.begin();
>        } catch (Exception ex) {
>            throw new RuntimeException(ex);
>        }
>    }
>
>
> getEntityManger() just returns an EntityManger. PersistenceSvc is a
> ThreadLocally scoped class. It is boilerplate utility class from
> NetBeans. I will try putting in em.clear().
>
>>
>> You may want to try a different database, to confirm if it is a database
>> issue.  Are you using innodb with MySQL, can you try using it?
>
> As mentioned above, this is what I am using. I'll trying running the
> app with something else to see if the problem occurs there, also.
>
> As I mentioned in my original post, I'm willing to crank up the logs
> and try and trace down where this is happening and step through the
> Eclipselink code to see if I can track down where things are going
> awry, but it would be a huge help to get some pointers as to good
> places in the code to put some breakpoints. I tried this with 1.1.2,
> 1.1.3 and 1.2.0. I'm currently using 1.2.0.
>
> Things are complex enough in my code that I think it would be very
> difficult to put together a reproducible test case (even if I did
> simplify things enough, I don't know that it would still misbehave).
> I've got a workaround going for this (change the collection fetch
> policy to EAGER), but it is not a very satisfying solution. I'd be
> much happier knowing I understand why this problem is happening than
> just avoiding it.
>
> --Tim
>
>>
>>
>> Tim McNerney wrote:
>>>
>>> I'm running into an issue where I add an object to a collection which
>>> is a member of another collection. When retrieving the top level item
>>> on a subsequent call, the new item is sometimes in the collection and
>>> sometimes is not. I can confirm that it is getting saved to the
>>> database. Let me map out a general outline of the code in question.
>>>
>>> @Entity
>>> @Table(name = "base")
>>> @Inheritance(strategy = InheritanceType.SINGLE_TABLE)
>>> @DiscriminatorColumn(name = "type", discriminatorType =
>>> DiscriminatorType.INTEGER)
>>> public abstract class Base  {
>>>  protected Collection<Sub> sub;
>>>
>>>  @OneToMany(mappedBy = "base", cascade = CascadeType.REMOVE, fetch =
>>> FetchType.LAZY)
>>>  public Collection<Sub> getSubs() {
>>>    return this.subs;
>>>  }
>>>
>>>  public void setSubs(Collection<Sub> subs) {
>>>    this.subs = subs;
>>>  }
>>>
>>>  public void addSub(Sub sub) {
>>>    this.subs.add(sub);
>>>    sub.setPost(this);
>>>  }
>>> }
>>>
>>> @Entity
>>> @DiscriminatorValue("2")
>>> public class Top extends Base {
>>> }
>>>
>>> @Entity
>>> @Table(name = "sub")
>>> public class Sub {
>>>    private Top top;
>>>
>>>  @ManyToOne(cascade = {}, fetch = FetchType.EAGER)
>>>  @JoinColumn(name = "base_id", referencedColumnName = "id")
>>>  public Top getTop() {
>>>    return this.top;
>>>  }
>>>
>>>  public void setTop(Top top) {
>>>    this.top = top;
>>>  }
>>>
>>> public class SubDAO {
>>> public static void createSub(Integer topId, Sub sub) {
>>> try {
>>>   persistenceSvc.beginTx();
>>>   em = persistenceSvc.getEntityManager();
>>>   Base base = em.find(Base.class, id);
>>>   base.addSub(sub);
>>>   em.persist(vote);
>>>   persistenceSvc.commitTx();
>>>   em.refresh(base);
>>>   em.refresh(sub);
>>>   } finally {
>>>   persistenceSvc.close();
>>>   }
>>> }
>>>
>>> I'm obviously leaving out quite a bit, due to space, but I can expand
>>> as necessary. I only provide the general outline to help folks follow
>>> what happens.
>>>
>>> So I create the new object (Sub), add it to the Collection in the
>>> Base. Later I retrieve the Top (extends Base) and sometimes it has the
>>> new item and sometimes it does not (if I do a restart of the app
>>> server, it always has the item). The code for retrieval looks a little
>>> something like:
>>>
>>> try {
>>>   persistenceSvc.beginTx();
>>>   em = persistenceSvc.getEntityManager();
>>>   Top top = em.find(Top.class, topId);
>>>   em.refresh(question);
>>>   System.out.println("size: " + top.getSubs().size());
>>>   persistenceSvc.commitTx();
>>>   return top;
>>>  } finally {
>>>   persistenceSvc.close();
>>>  }
>>>
>>> I do the size to ensure that I instantiate the Collection. If I run
>>> this code repeatedly after having added a single Sub to a Top that
>>> already had a Sub in the collection, I'll see something like:
>>>
>>> size: 2
>>> size: 2
>>> size: 2
>>> size: 1
>>> size: 2
>>> size: 1
>>>
>>> I wanted to make sure that I wasn't seeing a caching issue, so I added
>>> the following in my persistence.xml:
>>>
>>> <property name="eclipselink.cache.shared.default" value="false"/>
>>> <property name="eclipselink.cache.size.default" value="0"/>
>>> <property name="eclipselink.cache.type.default" value="None"/>
>>>
>>> When I turn the logging up to FINE, I can see it doing the database
>>> call each time I fetch
>>>
>>> [EL Fine] .... SELECT ... FROM sub WHERE base_id = ?
>>>   [123]
>>>
>>> I can see that there are two items matching that query by doing it
>>> directly to the database. Yet I get alternate return sizes of 1 and 2.
>>> Again, if I restart the server, I'll only get 1. Only the newly added
>>> entry appears and disappears.
>>>
>>> Some details of my configuration. Tomcat 6.0.x. Eclipselink 1.1.2,
>>> 1.1.3, 1.2.0 (tried the newer versions when they came out to see if
>>> there was a bug that had been solved). MySQL 5.1. JDBC connection,
>>> both through JNDI and an explicit connection. I'm using RESOURCE_LOCAL
>>> for the transaction-type. I set the eclipselink.target-database, but
>>> that is it in terms of properties (expect as above when testing
>>> without caching).
>>>
>>> I was able to finally get correct behavior by changing the fetching to
>>> EAGER instead of LAZY. But I don't want to have to do that and I'd
>>> like to understand this unexpected behavior so I can avoid it in the
>>> future.
>>>
>>> I know there is probably not enough info for a definitive conclusion,
>>> but I'm looking for suggestions as to where to look, what might be the
>>> cause and whether or not there are known bugs which might result in
>>> this behavior. I'm happy to turn up logging to try and trace things or
>>> even set breakpoints in the code. If you need more information, let me
>>> know.
>>>
>>> I don't have a simple, reproducible test case or I'd file a bug.
>>>
>>> Any help or tips would be greatly appreciated. Thanks.
>