Issue #556: Negative snapshot user count

I finally hit an instance of the "Negative snapshot user count" exception

1)

[ObjectDB 2.3.2_01] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.6.0_26 (on Windows 2003 5.2).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: Negative snapshot user count
com.objectdb.o.InternalException: Negative snapshot user count
at com.objectdb.o.SNP.z(SNP.java:292)
at com.objectdb.o.SFL.Z(SFL.java:765)
at com.objectdb.o.MST.U8(MST.java:1688)
at com.objectdb.o.MST.aR(MST.java:464)
at com.objectdb.o.MST.U1(MST.java:427)
at com.objectdb.o.WRA.U1(WRA.java:248)
at com.objectdb.o.LDR.w(LDR.java:354)
at com.objectdb.o.LDR.v(LDR.java:292)
at com.objectdb.o.LDR.s(LDR.java:210)
at com.objectdb.o.OBC.aM(OBC.java:1056)
at com.objectdb.o.OBC.aK(OBC.java:969)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:551)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:474)
at rbccm.felix.objectdb.messaging.ObjectDbMessagePipe.removeData(Unknown Source)
at rbccm.felix.objectdb.messaging.ObjectDbMessagePipe.getMessage(Unknown Source)
at rbccm.felix.objectdb.messaging.ObjectDbMessagePipe.takeWithRetry(Unknown Source)
at rbccm.felix.objectdb.messaging.ObjectDbMessagePipe.take(Unknown Source)
at rbccm.felix.objectdb.messaging.ObjectDbMessagePipe.take(Unknown Source)
at rbccm.felix.framework.service.ServiceRunner.run(Unknown Source)
at java.lang.Thread.run(Thread.java:662)

2)

[ObjectDB 2.3.2_01] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.6.0_26 (on Windows 2003 5.2).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: Negative snapshot user count
com.objectdb.o.InternalException: Negative snapshot user count
at com.objectdb.o.SNP.z(SNP.java:292)
at com.objectdb.o.SFL.Z(SFL.java:765)
at com.objectdb.o.MST.U8(MST.java:1688)
at com.objectdb.o.PRG.aq(PRG.java:1131)
at com.objectdb.o.PRG.ad(PRG.java:672)
at com.objectdb.o.PRG.ac(PRG.java:536)
at com.objectdb.o.QRM.U4(QRM.java:259)
at com.objectdb.o.MST.U4(MST.java:945)
at com.objectdb.o.WRA.U4(WRA.java:290)
at com.objectdb.o.WSM.U4(WSM.java:113)
at com.objectdb.o.QRR.g(QRR.java:232)
at com.objectdb.o.QRR.b(QRR.java:151)
at com.objectdb.jpa.JpaQuery.executeUpdate(JpaQuery.java:722)
at rbccm.felix.objectdb.messaging.ObjectDbMessagePipe.changePriority(Unknown Source)
at rbccm.felix.framework.service.ServiceRunner.changePriority(Unknown Source)
at rbccm.felix.gridservice.workflow.WorkflowService.propertyChanged(Unknown Source)
at rbccm.digest.workflow.manage.WorkflowManager$1.run(Unknown Source)
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)

Please let me know if there is anything further I can do to help with the investigation.

This is still a mystery. Could you please specify the time of each exception? Are they related?

They occured within a similar timeframe as a result of different actions in the application against the same database. I've attached the full log in case it helps (sorry I should have attached it from the start).

The following is an extract from a production log which is also showing the error (nothing else of interest in the file though):

[2011-09-09 21:04:15 #24 store]
Database 'F:\calculationservice\objectdb\dbs\admin\WorkflowHistoryArchive.odb' is opened by 9744@SE101925

[2011-11-04 21:05:09 #25 *]
[ObjectDB 2.2.9_07] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.5.0_21 (on Windows 2003 5.2).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: Negative snapshot user count
com.objectdb.o.InternalException: Negative snapshot user count
at com.objectdb.o.SNP.z(SNP.java:292)
at com.objectdb.o.SFL.Z(SFL.java:765)
at com.objectdb.o.MST.UW(MST.java:1584)
at com.objectdb.o.PRG.ao(PRG.java:1100)
at com.objectdb.o.PRG.ab(PRG.java:642)
at com.objectdb.o.QRM.US(QRM.java:259)
at com.objectdb.o.MST.US(MST.java:895)
at com.objectdb.o.WRA.US(WRA.java:286)
at com.objectdb.o.WSM.US(WSM.java:113)
at com.objectdb.o.QRR.g(QRR.java:225)
at com.objectdb.o.QRR.b(QRR.java:144)
at com.objectdb.jpa.JpaQuery.executeUpdate(JpaQuery.java:684)
at rbccm.felix.gridservice.admin.dao.HistoryArchiver.moveHistory(Unknown Source)
at rbccm.felix.gridservice.admin.dao.HistoryArchiver.access$400(Unknown Source)
at rbccm.felix.gridservice.admin.dao.HistoryArchiver$1.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)

Thank you. I cannot see the problem yet, but if you get similar exceptiond again please post them since it may expose a pattern.

Ok - feel free to close this issue in the meantime then. I'll re-open if/when the problems reoccurs or I can put together a specific test for it. Thanks

The NullPointerException in issue 559 (#15) reveals that this problem can happen when using DELETE or UPDATE queries in a multithreaded application. A transaction snapshot may be released more than once and the result is wrong user count and sometimes NullPointerException when the snapshot is released while it is still in use.

I could reproduce both problems with the following test:

import javax.persistence.*;


public class T556 {
   
    private static final int COUNT = 5;
   
    private static final String DELETE_QUERY =
        "DELETE FROM MyEntity WHERE id = :id";

    public static void main(String[] args) throws Exception {

        final EntityManagerFactory emf =
            Persistence.createEntityManagerFactory(
                "objectdb:$objectdb/db/test.tmp;drop");

        EntityManager em = emf.createEntityManager();

        em.getTransaction().begin();
        for (int i = 0; i < COUNT; i++)
            em.persist(new MyEntity());
        em.persist(new MyEntity());
        em.getTransaction().commit();

        Thread[] threads = new Thread[COUNT];
        for (int i = 0; i < COUNT; i++) {
            final long id = i + 1;
            threads[i] = new Thread(new Runnable() {
                @Override
                public void run()
                {
                    EntityManager em2 = emf.createEntityManager();
                    em2.getTransaction().begin();
                    em2.createQuery(DELETE_QUERY)
                        .setParameter("id", id).executeUpdate();
                    em2.getTransaction().commit();
                    em2.close();
                }
            });
        }

        for (int i = 0; i < COUNT; i++)
            threads[i].start();
        for (int i = 0; i < COUNT; i++)
            threads[i].join();
           
        em.close();
        emf.close();
    }

    @Entity
    public static class MyEntity {
        @GeneratedValue @Id long id;
    }
}

Build 2.3.3_04 should fix this bug.