[Mulgara-dev] Lost phase token

[Alex Hall]

James Leigh wrote:
> Hi Paul, Alex et al,
> 
> I am using Mulgara 2.0.6 and I keep getting the message "Lost phase
> token" in my logs, normally I can't read much from the Mulgara logs, but
> the next message caught my eye and I suspect they are related.
> 
> 17-Sep-2009 6:27:26 PM org.apache.log4j.Category info
> INFO: Lost phase token.
> STACK TRACE:
>   org.mulgara.store.xa.FreeList$Phase.<init>(FreeList.java:977)
>   org.mulgara.store.xa.ManagedBlockFile$Phase.<init>(ManagedBlockFile.java:239)
>   org.mulgara.store.statement.xa.TripleAVLFile$Phase.<init>(TripleAVLFile.java:569)
>   org.mulgara.store.statement.xa.XAStatementStoreImpl$Phase.<init>(XAStatementStoreImpl.java:1484)
>   org.mulgara.store.statement.xa.XAStatementStoreImpl.addTriple(XAStatementStoreImpl.java:439)
>   org.mulgara.resolver.store.StatementStoreResolver.modifyModel(StatementStoreResolver.java:362)
>   org.mulgara.resolver.InternalResolver.modifyModel(InternalResolver.java:164)
>   org.mulgara.resolver.ModifyModelOperation.doModify(ModifyModelOperation.java:247)
>   org.mulgara.resolver.ModifyModelOperation.execute(ModifyModelOperation.java:208)
>   org.mulgara.resolver.MulgaraInternalTransaction.execute(MulgaraInternalTransaction.java:623)
>   org.mulgara.resolver.DatabaseSession.execute(DatabaseSession.java:751)
>   org.mulgara.resolver.DatabaseSession.modify(DatabaseSession.java:728)
>   org.mulgara.resolver.DatabaseSession.insert(DatabaseSession.java:338)

Whenever a phase is created for a new transaction, we store a stack
trace so that if it later gets orphaned we can see where it was created.
 This helps us debug problems with the transaction management system.
If you're seeing this message, then it probably means that somebody
released a reference to a transaction without properly closing it.  When
using the Java API's with Mulgara, it's important to close each Session
when you're done with it, *and* you have to close each Answer when
you're done with it since each Answer holds a reference to the phase in
which it was created.  In general, all access to Answer objects should
be wrapped in a try/finally block:

Answer ans = session.query(query);
try {
  ans.beforeFirst();
  while (ans.next()) {
    // Do something with the answer...
  }
} finally {
  ans.close();
}

> I also get a lot of "Ignoring solutions" warnings, but I am not sure
> what they mean as the query results seem to be correct.
> 
> 17-Sep-2009 6:27:26 PM org.apache.log4j.Category warn
> WARNING: Ignoring solutions for [gn3350 gn33 $obj $ctx]
> 17-Sep-2009 6:27:26 PM org.apache.log4j.Category info
> INFO: Creating Answer: 4166458, xa=0
> 
> 17-Sep-2009 6:27:26 PM org.apache.log4j.Category warn
> WARNING: Ignoring solutions for non-local graph [gn3350 gn33 $obj $ctx]

These log messages are superfluous and have been downgraded to debug
level in a later release.  You'll see them a lot when resolving queries
containing variable graph URIs; in that case the constraint is sent to
each resolver factory, and most don't resolve constraints with variable
graph names and generate the above log message instead.

> This log message is what I am most concerned about.
> 
> SEVERE: Failed to rollback resource in transaction bb14:38:40:01e128e2068c482383...ca3c24:01e128e2068c48238363c...000000
> java.lang.OutOfMemoryError: Java heap space
[snip about=OutOfMemory stack trace]
> Here is why I think the the memory Error is related to the lost phase
> token. The top object allocations are all used to to print the lost
> phase taken log message. I have the completed java.hprof.txt file if
> needed.
> 
> SITES BEGIN (ordered by live bytes) Fri Sep 18 07:58:44 2009
>           percent          live          alloc'ed  stack class
>  rank   self  accum     bytes objs     bytes  objs trace name
>     1 95.07% 95.07% 747390416 47340 752370432 48279 305231 char[]	org.mulgara.util.StackTrace.getStringTrace(StackTrace.java:94)
>     2  2.25% 97.32%  17684568 47340  17820824 48280 305221 java.lang.StackTraceElement[]	org.mulgara.util.StackTrace.getStringTrace(StackTrace.java:90)
>     3  0.33% 97.65%   2616416 10608 3947543392 14995730 300008 char[]
>     4  0.19% 97.84%   1511040 23610   1521792 23778 305270 org.mulgara.store.xa.FreeList$Phase
>     5  0.19% 98.04%   1511040 23610   1521792 23778 305272 org.mulgara.store.xa.FreeList$Phase
>     6  0.14% 98.18%   1136160 47340   1158696 48279 305230 java.lang.String	org.mulgara.util.StackTrace.getStringTrace(StackTrace.java:94)
>     7  0.14% 98.32%   1136016 47334   1158744 48281 305213 java.util.LinkedList$Entry	org.mulgara.store.xa.FreeList$Phase.init(FreeList.java:1283)
>     8  0.14% 98.47%   1134576 47274   1156464 48186 305241 java.lang.Throwable	org.mulgara.store.xa.FreeList$Phase.<init>(FreeList.java:977)
> 
> I am hoping some one this list can explain to me:
> What is a lost phase token?

The on-disk data structures use phase trees to achieve transactional
isolation.  Phase tokens track when a phase is in use, and are weakly
referenced.  If a reference to a transaction is discarded without being
properly closed then you'll see this message (Disclaimer -- I'm not an
expert on Mulgara's transaction management but I think this is the case).

> Why does the log message include a stack trace?

To facilitate debugging of the transactional logic.  The stack trace is
generated when the phase is created in case we need to log it later, but
the call to generate the stack trace is wrapped in a check to
Log.isInfoEnabled().

> Why is it an INFO log message?

It's INFO level because it indicates that some client is not managing
their transactions properly.  Perhaps the stack trace should only be
generated for DEBUG-level logging, though.

> What can I do to prevent this?

To prevent the OutOfMemory, decrease the log level to WARN.  To prevent
the lost phase tokens, make sure transactions are closed when you're
done with them.  In general this means always closing Session and Answer
objects when they're no longer in use.

Regards,
Alex