[EDITED: added @MappedSuperclass, @IndexedEmbedded.prefix and ids]

My initial number of Order entities is 15. When using Luke to access the Order index, I see 15 documents with no deletions.
My orders are related to Person entities as described below.
When I update one Person entity my Order index shrinks to 6 documents.
To be perfectly clear: I did not delete any Order, I just updated one Person related to a few Orders.
How can I enable logging in hibernate search to see how it updates the indexes?
I found a "logging" section in Hibernate Core but not in Hibernate Search.

Thanks for your help.

Hibernate version:

hibernate-3.2.5.GA
hibernate-entitymanager-3.3.1.GA
hibernate-search-3.0.1.GA
hibernate-annotations-3.3.0.GA
lucene-core-2.3.0

Mapping documents:

@MappedSuperclass
public class BaseOrder {
@Id
@DocumentId
@GeneratedValue
protected long id;
}

@Indexed(index = "indexes/order_component")
@Entity
public class Order extends BaseOrder {
@ManyToOne
@IndexedEmbedded(prefix = "")
private Person creator;

@ManyToOne
@IndexedEmbedded(prefix = "")
private Person seller;

@ManyToOne
@IndexedEmbedded(prefix = "")
private Person buyer;
}

@Indexed(index = "indexes/persons")
@Entity
public class Person {
@Id
@DocumentId
@GeneratedValue
private long id;

@OneToMany(mappedBy = "creator", fetch = FetchType.LAZY)
@ContainedIn
private List<Order> createdOrders = new ArrayList<Order>();

@OneToMany(mappedBy = "seller", fetch = FetchType.LAZY)
@ContainedIn
private List<Order> soldOrders = new ArrayList<Order>();

@OneToMany(mappedBy = "buyer", fetch = FetchType.LAZY)
@ContainedIn
private List<Order> boughtOrders = new ArrayList<Order>();
}

Hi,

I assume you omitted some properties and annotations in your example, right? You have a @DocumentId in Order and Person? Other than that the code looks ok at the first glace.



Regarding logging - Hibernate Search also uses commons logging. So setting the category log level hibernate.org to debug or trace will automatically enable Hibernate Search debug/trace output. I would imagine you can also define the category hibernate.org.search to narrow down the output. Unfortunately, I don't think that there is a particular log message helping you with your problem. Give it a go.

Maybe you could also post some example code.

--Hardy

Sorry about that, I updated the message to reflect the problem better, since it could be related even though I first thought it to be irrelevant.

I have my Order ID in a @MappedSupperclass, I assume @DocumentId is inherited, my initial index works fine so I assume all is well.

I also added the prefix="" to my embedded Person indexes, which we have in our code. This may be relevant as I see several "id" fields in my index order documents. But I am not sure why this would lead to index document deletions.



I will give it a try, thanks.



That is going to be hard since it's quite a huge project :(
I'm quite eager to debug this myself, but I just don't know where to start looking.
It could just as well be a lucene problem as far as I know.

I have some logging, but nothing that indicates why documents are removed from my Order index.

Basically what happens is that when I log into my application, I update a Person.lastLogingDate. I did not list it in the code above because it is not an indexed property.

Now I see from the logs that the Person index's document is rebuilt even though none of its indexed properties changed. I see that because I see its index document is removed, then added. Because that Person is indexed embedded into some Order entities (4 of them) I see hibernate search removes those 4 orders' index documents and re-adds them.

I see no indication whatsoever that the other order index documents have been removed from the hibernate logs.

I started with 15 order index documents, four were updated by hibernate search. Those four plus an unrelated order index document remain in the index (5 in total), the rest are gone.

I'm starting to get a bad feeling about those embedded indexes for performance reasons. Is it normal that index documents are rebuilt even when no indexed property has changed?

I have included the logs of org.hibernate.search as well as Lucene's IndexWriter's infoStream.

Basically I am updating one Person, which is embedded in 2 Resource, 1 Comment and 4 Order indexed entities. So what we see from the Hibernate Search log is that those are re-indexed.

What we see from Lucene's log however is not entirely clear to me, but I think my IndexWriter (thread?) is IW 45, and I see the number 15 (number of Order index documents) mentioned a lot, numDocs=4 would refer to the re-indexing of 4 order documents, and I see the number 5 a lot too, which could point to my problem of having only 5 order documents in the index afterwards.

Here is the full log, maybe I should start talking to the Lucene guys?

2008-04-09 15:07:14,016 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Resource#3
2008-04-09 15:07:14,017 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Resource#4
2008-04-09 15:07:14,017 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Resource#3: Document<...>
2008-04-09 15:07:14,018 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: current segments file is "segments_cr"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@bf9839
2008-04-09 15:07:14,018 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: load commit "segments_cr"
2008-04-09 15:07:14,018 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: init: create=false
2008-04-09 15:07:14,018 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: setInfoStream: dir=org.apache.lucene.store.FSDirectory@/home/stephane/no-backup/src/jboss-4.2.2.GA/server/default/data/foo/indexes/resource_component autoCommit=true mergePolicy=org.apache.lucene.index.LogByteSizeMergePolicy@a2c691 mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler@9a6b5a ramBufferSizeMB=16.0 maxBuffereDocs=-1 maxBuffereDeleteTerms=-1 maxFieldLength=10000 index=_4z:c15
2008-04-09 15:07:14,018 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: setMaxBufferedDocs 10
2008-04-09 15:07:14,020 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Resource#4: Document<...>
2008-04-09 15:07:14,020 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Comment#4
2008-04-09 15:07:14,021 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Comment#4: Document<stored/uncompressed,indexed<_hibernate_class:com.foo.model.Comment> stored/uncompressed,indexed<id:4> indexed,tokenized<text:Okay, thanks> stored/uncompressed,indexed<id:7> indexed,tokenized<text:BOS> stored/uncompressed,indexed<key:BOS> indexed,tokenized<text:Boston Tea Party>>
2008-04-09 15:07:14,022 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: current segments file is "segments_5a"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@1fe196a
2008-04-09 15:07:14,022 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: load commit "segments_5a"
2008-04-09 15:07:14,022 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: init: create=false
2008-04-09 15:07:14,022 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: setInfoStream: dir=org.apache.lucene.store.FSDirectory@/home/stephane/no-backup/src/jboss-4.2.2.GA/server/default/data/foo/indexes/component_comment autoCommit=true mergePolicy=org.apache.lucene.index.LogByteSizeMergePolicy@1368553 mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler@6b1f3b ramBufferSizeMB=16.0 maxBuffereDocs=-1 maxBuffereDeleteTerms=-1 maxFieldLength=10000 index=_1x:c6
2008-04-09 15:07:14,022 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: setMaxBufferedDocs 10
2008-04-09 15:07:14,022 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Order#1
2008-04-09 15:07:14,023 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Order#2
2008-04-09 15:07:14,023 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Order#4
2008-04-09 15:07:14,023 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Order#5
2008-04-09 15:07:14,024 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Order#1: Document<...>
2008-04-09 15:07:14,024 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: current segments file is "segments_ed"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@cf6a17
2008-04-09 15:07:14,025 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: load commit "segments_ed"
2008-04-09 15:07:14,025 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: init: create=false
2008-04-09 15:07:14,025 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: setInfoStream: dir=org.apache.lucene.store.FSDirectory@/home/stephane/no-backup/src/jboss-4.2.2.GA/server/default/data/foo/indexes/order_component autoCommit=true mergePolicy=org.apache.lucene.index.LogByteSizeMergePolicy@13e118c mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler@1f21aa9 ramBufferSizeMB=16.0 maxBuffereDocs=-1 maxBuffereDeleteTerms=-1 maxFieldLength=10000 index=_5q:c15
2008-04-09 15:07:14,025 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: setMaxBufferedDocs 10
2008-04-09 15:07:14,026 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Order#2: Document<...>
2008-04-09 15:07:14,049 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Order#4: Document<...>
2008-04-09 15:07:14,049 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Order#5: Document<...>
2008-04-09 15:07:14,050 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] remove from Lucene index: class com.foo.model.Person#7
2008-04-09 15:07:14,050 TRACE [org.hibernate.search.backend.impl.lucene.LuceneWorker] add to Lucene index: class com.foo.model.Person#7: Document<...>
2008-04-09 15:07:14,051 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: current segments file is "segments_6z"; deletionPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy@1b47433
2008-04-09 15:07:14,051 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: init: load commit "segments_6z"
2008-04-09 15:07:14,051 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: init: create=false
2008-04-09 15:07:14,052 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: setInfoStream: dir=org.apache.lucene.store.FSDirectory@/home/stephane/no-backup/src/jboss-4.2.2.GA/server/default/data/foo/indexes/persons autoCommit=true mergePolicy=org.apache.lucene.index.LogByteSizeMergePolicy@38c22b mergeScheduler=org.apache.lucene.index.ConcurrentMergeScheduler@53b3f0 ramBufferSizeMB=16.0 maxBuffereDocs=-1 maxBuffereDeleteTerms=-1 maxFieldLength=10000 index=_2i:c6
2008-04-09 15:07:14,052 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: setMaxBufferedDocs 10
2008-04-09 15:07:14,052 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: now flush at close
2008-04-09 15:07:14,052 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: flush: segment=_50 docStoreSegment=_50 docStoreOffset=0 flushDocs=true flushDeletes=false flushDocStores=true numDocs=2 numBufDelTerms=0
2008-04-09 15:07:14,052 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: index before flush _4z:c15
2008-04-09 15:07:14,052 INFO [STDOUT]
2008-04-09 15:07:14,052 INFO [STDOUT]
2008-04-09 15:07:14,054 INFO [STDOUT] oldRAMSize=79488 newFlushedSize=724 docs/MB=2,896.619 new/old=0.911%
2008-04-09 15:07:14,054 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_cs"
2008-04-09 15:07:14,054 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_cs" [2 segments ; isCommit = true]
2008-04-09 15:07:14,056 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_cr"
2008-04-09 15:07:14,056 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_cr"
2008-04-09 15:07:14,057 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_ct"
2008-04-09 15:07:14,057 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_ct" [2 segments ; isCommit = true]
2008-04-09 15:07:14,057 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_cs"
2008-04-09 15:07:14,057 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_cs"
2008-04-09 15:07:14,057 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.fnm"
2008-04-09 15:07:14,057 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.frq"
2008-04-09 15:07:14,057 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.prx"
2008-04-09 15:07:14,058 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.tis"
2008-04-09 15:07:14,058 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.tii"
2008-04-09 15:07:14,058 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.nrm"
2008-04-09 15:07:14,058 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.fdx"
2008-04-09 15:07:14,058 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_50.fdt"
2008-04-09 15:07:14,058 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: LMP: findMerges: 2 segments
2008-04-09 15:07:14,058 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: LMP: level -1.0 to 3.8237348: 2 segments
2008-04-09 15:07:14,058 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: CMS: now merge
2008-04-09 15:07:14,058 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: CMS: index: _4z:c15 _50:c2
2008-04-09 15:07:14,058 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: CMS: no more merges pending; now return
2008-04-09 15:07:14,058 INFO [STDOUT] IW 43 [http-127.0.0.1-8080-1]: at close: _4z:c15 _50:c2
2008-04-09 15:07:14,058 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: now flush at close
2008-04-09 15:07:14,058 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: flush: segment=_1y docStoreSegment=_1y docStoreOffset=0 flushDocs=true flushDeletes=false flushDocStores=true numDocs=1 numBufDelTerms=0
2008-04-09 15:07:14,058 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: index before flush _1x:c6
2008-04-09 15:07:14,058 INFO [STDOUT]
2008-04-09 15:07:14,058 INFO [STDOUT]
2008-04-09 15:07:14,059 INFO [STDOUT] oldRAMSize=81280 newFlushedSize=209 docs/MB=5,017.11 new/old=0.257%
2008-04-09 15:07:14,059 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_5b"
2008-04-09 15:07:14,059 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_5b" [2 segments ; isCommit = true]
2008-04-09 15:07:14,060 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_5a"
2008-04-09 15:07:14,060 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_5a"
2008-04-09 15:07:14,060 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_5c"
2008-04-09 15:07:14,060 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_5c" [2 segments ; isCommit = true]
2008-04-09 15:07:14,060 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_5b"
2008-04-09 15:07:14,060 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_5b"
2008-04-09 15:07:14,060 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.fnm"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.frq"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.prx"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.tis"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.tii"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.nrm"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.fdx"
2008-04-09 15:07:14,061 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_1y.fdt"
2008-04-09 15:07:14,061 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: LMP: findMerges: 2 segments
2008-04-09 15:07:14,061 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: LMP: level -1.0 to 3.1792645: 2 segments
2008-04-09 15:07:14,061 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: CMS: now merge
2008-04-09 15:07:14,061 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: CMS: index: _1x:c6 _1y:c1
2008-04-09 15:07:14,061 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: CMS: no more merges pending; now return
2008-04-09 15:07:14,061 INFO [STDOUT] IW 44 [http-127.0.0.1-8080-1]: at close: _1x:c6 _1y:c1
2008-04-09 15:07:14,062 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: now flush at close
2008-04-09 15:07:14,062 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: flush: segment=_2j docStoreSegment=_2j docStoreOffset=0 flushDocs=true flushDeletes=false flushDocStores=true numDocs=1 numBufDelTerms=0
2008-04-09 15:07:14,062 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: index before flush _2i:c6
2008-04-09 15:07:14,062 INFO [STDOUT]
2008-04-09 15:07:14,062 INFO [STDOUT]
2008-04-09 15:07:14,063 INFO [STDOUT] oldRAMSize=80960 newFlushedSize=281 docs/MB=3,731.587 new/old=0.347%
2008-04-09 15:07:14,063 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_70"
2008-04-09 15:07:14,063 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_70" [2 segments ; isCommit = true]
2008-04-09 15:07:14,063 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_6z"
2008-04-09 15:07:14,063 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_6z"
2008-04-09 15:07:14,064 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_71"
2008-04-09 15:07:14,064 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_71" [2 segments ; isCommit = true]
2008-04-09 15:07:14,064 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_70"
2008-04-09 15:07:14,064 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_70"
2008-04-09 15:07:14,064 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.fnm"
2008-04-09 15:07:14,064 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.frq"
2008-04-09 15:07:14,064 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.prx"
2008-04-09 15:07:14,065 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.tis"
2008-04-09 15:07:14,065 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.tii"
2008-04-09 15:07:14,065 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.nrm"
2008-04-09 15:07:14,065 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.fdx"
2008-04-09 15:07:14,065 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_2j.fdt"
2008-04-09 15:07:14,065 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: LMP: findMerges: 2 segments
2008-04-09 15:07:14,065 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: LMP: level -1.0 to 3.2203696: 2 segments
2008-04-09 15:07:14,065 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: CMS: now merge
2008-04-09 15:07:14,065 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: CMS: index: _2i:c6 _2j:c1
2008-04-09 15:07:14,065 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: CMS: no more merges pending; now return
2008-04-09 15:07:14,065 INFO [STDOUT] IW 46 [http-127.0.0.1-8080-1]: at close: _2i:c6 _2j:c1
2008-04-09 15:07:14,065 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: now flush at close
2008-04-09 15:07:14,066 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: flush: segment=_5r docStoreSegment=_5r docStoreOffset=0 flushDocs=true flushDeletes=false flushDocStores=true numDocs=4 numBufDelTerms=0
2008-04-09 15:07:14,066 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: index before flush _5q:c15
2008-04-09 15:07:14,066 INFO [STDOUT]
2008-04-09 15:07:14,066 INFO [STDOUT]
2008-04-09 15:07:14,067 INFO [STDOUT] oldRAMSize=72960 newFlushedSize=2189 docs/MB=1,916.082 new/old=3%
2008-04-09 15:07:14,067 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_ee"
2008-04-09 15:07:14,067 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_ee" [2 segments ; isCommit = true]
2008-04-09 15:07:14,067 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_ed"
2008-04-09 15:07:14,067 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_ed"
2008-04-09 15:07:14,068 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: checkpoint: wrote segments file "segments_ef"
2008-04-09 15:07:14,068 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: now checkpoint "segments_ef" [2 segments ; isCommit = true]
2008-04-09 15:07:14,068 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: deleteCommits: now remove commit "segments_ee"
2008-04-09 15:07:14,068 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "segments_ee"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.fnm"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.frq"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.prx"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.tis"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.tii"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.nrm"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.fdx"
2008-04-09 15:07:14,069 INFO [STDOUT] IFD [http-127.0.0.1-8080-1]: delete "_5r.fdt"
2008-04-09 15:07:14,069 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: LMP: findMerges: 2 segments
2008-04-09 15:07:14,069 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: LMP: level -1.0 to 3.8337843: 2 segments
2008-04-09 15:07:14,069 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: CMS: now merge
2008-04-09 15:07:14,069 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: CMS: index: _5q:c15 _5r:c4
2008-04-09 15:07:14,070 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: CMS: no more merges pending; now return
2008-04-09 15:07:14,070 INFO [STDOUT] IW 45 [http-127.0.0.1-8080-1]: at close: _5q:c15 _5r:c4

Yes this is normal, we "could" potentially be a bit smarter and avoid that but that's probably tricky. If you want to give it a try, I can point you to the right direction.
I think there is an open JIRA already.

I don't fully understand your order disapearance issue. Sometimes people get confused because they erase their DB, but they do no erase the idnex directory. this create some deviations.

Please do, I'll take a look to see if I'm qualified to fix it :)



Aha, when we redeploy our application we erase our DB, but not the indexes. The indexes are, however, recreated programatically, and optimised. The behaviour I am experiencing and describing occurs after such a redeploy.
Could this be the problem?

I'm on my way to test this by erasing the index directory when redeploying.

Thanks a lot for your help.

I am very disappointed, I thought it would be so simple :(
Deleting the indexes directory when redeploying and recreating our DB doesn't change this behaviour.
I'm still losing documents.

I don't really know how the prefix should be used, but it could be dangerous to have the same prefix for three different embedded entities.
An update will remove all compatible documents from the index, and then insert one. As far as I remember, compatible means: same index (of course), same class, ID. So you have three links which are equal.
I'm just guessing, but maybe you're deleting all three for an update, and then insert just one: reducing the total number.

Could you try using different prefixes?

regards,
Sanne

May I say you are a welcome gift :)
This is indeed the problem. Many thanks!!

Now I need to find out how to include the @IndexedEmbedded entitie's "text" fields which I do want to merge with my entity's "text" field. Maybe with @DocumentId(name = "classname_id") although this would only work if I'm not embedding entities of the same class in my index...

nice :-)

again I'm not sure if I understood, but as I'm lucky today:

if you want to merge several text fields in one write something like



So you end up with a "jolly field" in your root entity, but if you remove the fields from specific properties you won't be able to discern them; I'm not sure if that is what you want.

Sanne

Note that by reusing the same field name, the data will be appended. I think that's how Lucene work.

For the enhancement, check FullTextIndexEventListener
onPostUpdate receives a PostUpdateEvent which contains the old and new state.

Somehow you could ask the documentbuilder instance if one of the changed state is affecting it.

That's not very nice compared to how we have it right now:

For every field we want to be able to do full text search on, we just put @Field(name = "text") on that property (or transient). When embedding indexed entities we automatically gain their text indexes, without having to make methods which contain all of the fields appended to strings.

On the other hand if it's the only way to make it work... ;)

Sorry about the late answer.

I looked at it because performance is terrible with our use-case without this optimisation.

It seems to me it would be easier to compare the old Document (from the index) and the new Document generated by the DocumentBuilder to decide whether the document has changed.

Comparing entities is tricky, especially since it requires them all to have valid recursive equals methods.

Comparing Document instances should be easier (I hope).

Basically in DocumentBuilder.addWorkToQueue I should create an instance of UpdateLuceneWork instead of Add+Remove, I suspect this work will be processed in LuceneWorker, where it would be easy (I hope) to compare the two Document instances.

The problem is that it does not appear easy nor correct to load the old Document from the DocumentBuilder, and in LuceneWorker it does not appear easy nor correct either to go and call back the DocumentBuilder.processContainedIn to finish the reindexing if we figured out that the two Documents were indeed different.

Do you have any advice, or shall I just start hacking it until it bends?

Comparing entities is easy as you can use the Hibernate UserType, which can compare every single state.

comparing Documents is most of the time harder as you need to explicitly store the data in the fields (more space). Also the data store is not always the data indexed.