Hyland Connect

dbas2000 · ‎09-04-2012

Our Alfresco output 500 MO to and from the disk where lucene-indexes are located, for each document added to the repository.

Our documents are only small pieces of PDFA files (200 ko) !

So, it takes more than 10 seconds to process a document and 2000 documents are inserted per days.

This scenario appear in our quality and production environment.
Configuration information :

JVM Parameters

  $JAVA_OPTS="-Xss512K -XX:MaxPermSize=256m -Xms2048m -Xmx2048m  
                    -Dalfresco.home=/soi/app/alfresco-ged34e
                    -Dhttp.proxyHost=xx.xx.xx.xx -Dhttp.proxyPort=xxxx  
                    -Duser.dir=${CATALINA_HOME}/user.dir  
                    -Duser.home=${CATALINA_HOME}/user.home  
                    -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=xxxx  
                    -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false  
                    -Djava.rmi.server.hostname=myserver.mydomain.ch   
                    -server -Dsun.security.ssl.allowUnsafeRenegotiation=true  
                    -Dfile.encoding=UTF-8 -Duser.country=CH -Duser.language=fr -Duser.timezone=Europe/Zurich  
                    -XX:NewRatio=1 -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode  
                    -XX:CMSInitiatingOccupancyFraction=80"  ‍‍‍‍‍‍‍‍‍‍‍‍

[size=150]Full description [/size]

Addind a new document produce 500 MO

iotop show more than 500 MO writed and readed for inserting a only 200 ko PDFA file

Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
21138 be/4 alfresco    526.40 M    584.30 M  0.00 % 10.17 % java -Dnop -Xss512K -XX:MaxPermSize=256m -Xms1024~t/tem
21186 be/4 alfresco     17.55 M    448.00 K  0.00 %  3.50 % java -Dnop -Xss512K -XX:MaxPermSize=256m -Xms1024~t/tem‍‍‍‍

At the same time, the cpu works hard

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
21068 alfresco  20   0 2119m 1.2g  14m S 92.2 63.2   6:43.85 java
21197 root      20   0  177m 9252 2528 S  0.7  0.5   0:04.51 iotop‍‍‍

Output log

below is just end of the log when adding a document. At the end of the log, there is 8 seconds elapsed between these two lines

2012-09-04 09:56:33,514 User:myuser DEBUG [lucene.fts.FullTextSearchIndexerImpl] FTS index request for workspace://SpacesStore
2012-09-04 09:56:41,987  DEBUG [lucene.fts.FullTextSearchIndexerImpl] FTS Indexing workspace://SpacesStore at Tue Sep 04 09:56:41 CEST 2012‍‍

2012-09-04 09:56:02,912 User:myuser DEBUG [impl.lucene.ADMLuceneIndexerImpl] Creating indexer
2012-09-04 09:56:02,912 User:myuser DEBUG [impl.lucene.ADMLuceneIndexerImpl] Update node workspace://SpacesStore/9efb97f2-c2e3-4b96-a0af-52fbf61d5158
2012-09-04 09:56:02,921 User:myuser DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 40c30117-e988-4db0-b0a8-52eb18408da8 (the index ito which these are applied is the previous one …)
2012-09-04 09:56:02,937 User:myuser DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 707e8a54-c785-453b-8722-6acb5d5d3e46 (the index ito which these are applied is the previous one …)
2012-09-04 09:56:03,263 User:myuser DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 75f2c3d4-6885-47a9-b3cd-2285245fefc9 (the index ito which these are applied is the previous one …)
2012-09-04 09:56:04,527 User:myuser DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 4968aab5-4fff-4dda-bb8e-c079cbf8c8ac (the index ito which these are applied is the previous one …)
2012-09-04 09:56:05,416 User:myuser DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 4c33d483-5ff5-4b1f-9d5c-e74446bfe3d3 (the index ito which these are applied is the previous one …)
2012-09-04 09:56:06,323 User:myuser DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 27b977cf-4739-4e5c-84ce-27bda6d4d526 (the index ito which these are applied is the previous one …)
2012-09-04 09:56:06,334 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using EXACT_LANGUAGE_AND_ALL is [, {fr}]
2012-09-04 09:56:06,347 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using EXACT_LANGUAGE_AND_ALL is [, {fr}]
2012-09-04 09:56:06,358 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,358 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,359 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,359 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,359 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,360 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,361 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,361 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,361 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,366 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,366 User:myuser DEBUG [impl.lucene.LuceneAnalyser] Loaded org.alfresco.repo.search.impl.lucene.analysis.AlfrescoStandardAnalyser for type {http://www.alfresco.org/model/dictionary/1.0}boolean
2012-09-04 09:56:06,366 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,367 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,369 User:myuser DEBUG [impl.lucene.LuceneAnalyser] Loaded org.alfresco.repo.search.impl.lucene.analysis.DateAnalyser for type {http://www.alfresco.org/model/dictionary/1.0}datetime
2012-09-04 09:56:06,370 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,371 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,371 User:myuser DEBUG [impl.lucene.LuceneAnalyser] Loaded org.alfresco.repo.search.impl.lucene.analysis.DateAnalyser for type {http://www.alfresco.org/model/dictionary/1.0}datetime
2012-09-04 09:56:06,372 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,373 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,374 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,374 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,375 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,376 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using EXACT_LANGUAGE_AND_ALL is [, {fr}]
2012-09-04 09:56:06,377 User:myuser DEBUG [impl.lucene.LuceneAnalyser] Loaded org.alfresco.repo.search.impl.lucene.analysis.LongAnalyser for type {http://www.alfresco.org/model/dictionary/1.0}long
2012-09-04 09:56:06,377 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,378 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,381 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,381 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:06,382 User:myuser DEBUG [lucene.analysis.MLAnalayser] Loading org.apache.lucene.analysis.fr.FrenchAnalyzer for fr_CH
2012-09-04 09:56:06,382 User:myuser DEBUG [lucene.analysis.MLTokenDuplicator] Locale fr_CH using ALL_ONLY is []
2012-09-04 09:56:33,514 User:myuser DEBUG [lucene.fts.FullTextSearchIndexerImpl] FTS index request for workspace://SpacesStore
2012-09-04 09:56:41,987 DEBUG [lucene.fts.FullTextSearchIndexerImpl] FTS Indexing workspace://SpacesStore at Tue Sep 04 09:56:41 CEST 20122012-09-04 09:56:41,988 DEBUG [impl.lucene.ADMLuceneIndexerImpl] Creating indexer
2012-09-04 09:56:41,989 DEBUG [impl.lucene.FilterIndexReaderByStringId] Applying deletions FOR 5bcc8dd0-8b6c-4874-adc8-31db4c61264a (the index ito which these are applied is the previous one …)
2012-09-04 09:56:42,399 DEBUG [lucene.fts.FullTextSearchIndexerImpl] FTS index completed for workspace://SpacesStore … 0 remaining

When starting, Alfresco read 7 GO

I also noticed that when Alfresco starts, it reads 7 GO before the webapp is alive.

Mesured with iotop :

Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
21070 be/4 alfresco      7.17 G    121.76 M  0.02 % 23.50 ‍‍‍

No change when disabling cm:content indexing


   <type name="cm:content">
         <title>Content</title>
         <parent>cm:cmobject</parent>
         <archive>true</archive>
         <properties>
            <property name="cm:content">
               <type>d:content</type>
               <mandatory>false</mandatory>
               <!– Although content is marked as indexed atomically it may end up asynchronous –>
               <!– if the content conversion will take too long. Content that does not require conversion –>
               <!– to UTF8 test/plain will always be indexed atomically –>
               <index enabled="false">
                  <atomic>true</atomic>
                  <stored>false</stored>
                  <tokenised>true</tokenised>
               </index>
            </property>
         </properties>
      </type>‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

For our business solution, whe don't need fulltext search, so I do understand why Lucene output 500 MO when cm:content indexing is disabled !

Conclusion

I looking for a solution to reduce these IO writing, any help welcome !

Best regards

Pierre-André

mrogers · ‎09-04-2012

The indexes are used for more than just full text search.

And although Lucene is IO heavy it should not be a problem.

The recommendation I've always seen is to put your indexes on your fastest local disk.
And make sure its not configured with a filesystem with un-neccessasary features like slow and safe RAID settings or virus scanner. The index is derived data, it can be regenerated.

The usual problems with running alfresco in a JVM is too little RAM.

t_sato · ‎09-05-2012

Hi,

I looking for a solution to reduce these IO writing, any help welcome !

How did you know the absolute number of write I/O is your problem?

I guess your problem is indexing speed, correct? Then, sync is likely the most time consuming operations as index file gets fragmented. And it would be mostly caused by index merger, which could be improved by index writer's buffer RAM size. Could be only improved by some kind of sharding if you don't change your hardware.

But anyway, I think you need to make your problem clear and nail down further to find your real bottleneck.

dbas2000 · ‎09-10-2012

Thanks to mrogers and t_sato for your post.

After more investigations, I discovered that is the merge process that produce this traffic.

With the tool iotop, we can see that the IO traffic is produced whatever segments are merged.

The mergeFactor is fixed to 5 but every 2 documents a segment is flushed to the disk.

Below is the result from the IndexInfo.jar against the SpacesStore.

Does somebody knows how to analyse these output ?

The contentStore holds 1'600'000 documents and the first segment holds 3'029'531 documents !

java -Xmx512m -cp ./IndexInfo.jar org.alfresco.repo.search.impl.lucene.index.IndexInfo C:\\labs\\backup-lucene-indexes\\workspace\\SpacesStore  
Entry List for lucene-indexes\workspace\SpacesStore ‍‍

   Size = 9
        0        Name=0ab76c3f-be42-4486-bf5d-0716df6084f9 Type=INDEX Status=COMMITTED Docs=3029531 Deletions=0
        1        Name=12f3f5b3-047b-4179-808a-c5e55dab6ba4 Type=INDEX Status=COMMITTED Docs=1745366 Deletions=0
        2        Name=adfdcb27-3e94-4cfe-9826-072335af142b Type=INDEX Status=COMMITTED Docs=1128625 Deletions=0
        3        Name=3ad8cb8c-3515-47e2-b26b-6c342e8a5b26 Type=INDEX Status=COMMITTED Docs=725190 Deletions=0
        4        Name=c15f8d81-79ed-4a55-985a-1f7b8a1a1188 Type=INDEX Status=COMMITTED Docs=316397 Deletions=0
        5        Name=9d21316f-64b4-406c-8029-011bbc029970 Type=DELTA Status=COMMITTED Docs=40 Deletions=29
        6        Name=de201603-4374-4cf1-975c-673fe5cc2d7b Type=DELTA Status=COMMITTED Docs=80 Deletions=65
        7        Name=d85fb371-5b9f-4938-a3e2-4d7aac73c5ff Type=DELTA Status=COMMITTED Docs=128 Deletions=86
        8        Name=5b1d1df9-3e96-4334-9914-0fd2e996a775 Type=DELTA Status=COMMITTED Docs=119 Deletions=119‍‍‍‍‍‍‍‍‍‍

Thank's for any help.

Pierre-André

t_sato · ‎09-11-2012

Hi Pierre,

So now this must be the wiki you want to take a look.

It says:

It is usualy a good practice that the highest-numbered INDEX entries (which contains the least documents, number 4 in the examples above) do not contain more than a few hundred documents. If it's not the case, it could lead to massive amount of IO pressure on the index directories for merging operations.

You have the default merge factor, 5, so it applies to you as well. You have 316397 documents in the highest-numbered INDEX entry. It is far more than hundreds! So increasing the merge factor is definitely an option to improve indexing performance.

There Lucene pages are also helpful to understand how Lucene index works.
IndexWriter(2.9.3)
Improve Index Speed from Lucene wiki
Full Text Search Configuraiton from Alfresco wiki

Hope this helps.

dbas2000 · ‎09-11-2012

Hi t_sato,

So I changed the configuration with this parameters and the FULL reindexing process is currently working - Wait and see !

lucene.indexer.mergerTargetIndexCount=8
lucene.indexer.maxRamInMbForInMemoryMerge=48
lucene.indexer.writerRamBufferSizeMb=48
lucene.indexer.mergerRamBufferSizeMb=48
lucene.indexer.maxRamInMbForInMemoryIndex=48‍‍‍‍‍

I will post the result re-indexing is completed.

Pierre-André

dbas2000 · ‎09-13-2012

Hi,

Here is the indexes status after the FULL indexes rebuilding. 24 hours for 1'600'000 documents :

Size = 7
        0        Name=facae57d-2997-4964-b710-6bf7a88e1345 Type=INDEX Status=COMMITTED Docs=5527866 Deletions=0
        1        Name=32064b10-d4dd-4514-a652-5bd55921892a Type=INDEX Status=COMMITTED Docs=845705 Deletions=0
        2        Name=a68a0558-9429-4217-a44e-7f696e79a113 Type=INDEX Status=COMMITTED Docs=517370 Deletions=0
        3        Name=0482c5b5-0c3f-4c2d-ae87-ad848466faac Type=INDEX Status=COMMITTED Docs=49291 Deletions=0
        4        Name=d0b834a1-ce86-4493-bd13-a1905360c893 Type=INDEX Status=COMMITTED Docs=4751 Deletions=0
        5        Name=27e26039-1ce6-4336-bea3-dd45f9fc4533 Type=DELTA Status=COMMITTED Docs=18 Deletions=11
        6        Name=0563c9a4-daf6-4dea-91a1-96d1936cf651 Type=DELTA Status=COMMITTED Docs=50 Deletions=50‍‍‍‍‍‍‍‍

I thing it's a lot better than the previous status !

My questions are :

In order to keep the production online, does it possible to launch the reindexing process in an other server and then replace de production indexes with the rebuilded indexes ?

In the first segment there is Docs=5'527'866. Does Docs represents the number of indexed files, because the contenstore hold only 1'600'000 documents ?

Thanks

Pierre-André

t_sato · ‎09-13-2012

Looks good!

In order to keep the production online, does it possible to launch the reindexing process in an other server and then replace de production indexes with the rebuilded indexes ?

I'm afraid not unless you can have your system read-only during the rebuilding process(24 hours?).

You may need a professional Alfresco consulting service for the best possible deployment in production.

In the first segment there is Docs=5'527'866. Does Docs represents the number of indexed files, because the contenstore hold only 1'600'000 documents ?

I guess DOCS comes from numDocs of IndexReader. Then yes, it is indexed documents. I don't know details, but it means(not surprising) that 2 or 3 additional system document are stored per user document.

Hyland Connect

Alfresco write-read 500 MO when adding a 200 ko pdf document