8 Replies Latest reply on May 4, 2015 10:28 AM by prashant.thakur

    Problems in executing the mass indexer

    prashant.thakur

      We are facing problems in starting nodes when Indexing is enabled. The setup has 4 nodes(each 200G allocated with 16 cores and 10Gbps link) data size is approx 70G only where Index related caches are in repl_sync mode and since Index Writers are using single lock across cluster. It seems while replicating data lock acquisition is failing.

      The parameters used for indexing in configuration file are as follows

      We are using Infinispan 7.0.2.Final

         <distributed-cache name="SUBSCRIBER" mode="SYNC" owners="2" segments="60" capacity="1" l1-lifespan="0" remote-timeout="240000">

              <transaction

              transaction-manager-lookup="org.infinispan.transaction.lookup.GenericTransactionManagerLookup"

              mode="NON_XA"

              locking="OPTIMISTIC"/>

       

            <indexing index="LOCAL" auto-config="true">

                       <property name="default.indexmanager">near-real-time</property>

                       <property name="default.indexwriter.merge_factor">30</property>

                        <property name="default.indexwriter.merge_max_size">1024</property>

                        <property name="default.indexwriter.ram_buffer_size">220</property>

                        <property name="default.locking_strategy">native</property>

                        <property name="default.sharding_strategy.nbr_of_shards">6</property>

                        <property name="default.max_queue_length">1000000</property>

                        <property name="default.worker.execution">async</property>

                        <property name="default.worker.thread_pool.size">32</property>

                        <property name="default.chunk_size">128000</property>

             </indexing>

         </distributed-cache>

       

      JGroups setting is attached.

       

      We are getting the following error message while indexing.

       

      29/Apr 16:57:23,100  WARN [TCP] [Timer-2,pocg8-19-node2-26137] (TCPConnectionMap.java:624) - Discarding message because TCP send_queue is full and hasn't been releasing for 2000 ms

       

      ERROR [2015-04-29 20:42:58,906] [org.infinispan.interceptors.InvocationContextInterceptor] [ForkJoinPool.commonPool-worker-9] (InvocationContextInterceptor.java:124) - ISPN000136: Execution error

      org.infinispan.remoting.RemoteException: ISPN000217: Received exception from prashantt-ux-35660, see cause for remote stack trace

              at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:44)

              at org.infinispan.remoting.transport.AbstractTransport.parseResponseAndAddToResponseList(AbstractTransport.java:69)

              at org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:560)

              at org.infinispan.remoting.rpc.RpcManagerImpl.invokeRemotely(RpcManagerImpl.java:290)

              at org.infinispan.interceptors.distribution.TxDistributionInterceptor.prepareOnAffectedNodes(TxDistributionInterceptor.java:221)

              at org.infinispan.interceptors.distribution.TxDistributionInterceptor.visitPrepareCommand(TxDistributionInterceptor.java:205)

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)

              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

              at org.infinispan.interceptors.EntryWrappingInterceptor.visitPrepareCommand(EntryWrappingInterceptor.java:109)

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)

              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

              at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.invokeNextAndCommitIf1Pc(AbstractTxLockingInterceptor.java:78)

              at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitPrepareCommand(OptimisticLockingInterceptor.java:87)

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)

              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

              at org.infinispan.interceptors.NotificationInterceptor.visitPrepareCommand(NotificationInterceptor.java:36)

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)

              at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:98)

              at org.infinispan.interceptors.TxInterceptor.invokeNextInterceptorAndVerifyTransaction(TxInterceptor.java:131)

              at org.infinispan.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:118)

              at org.infinispan.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:124)

      .......................

      Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 10 seconds for key org.infinispan.registry.ScopedKey@a57d6b61 and requestor GlobalTransaction:<ACB-25204>:9:remote. Lock is held by GlobalTransaction:<prashantt-ux-35660>:1025:local, while request came from ACB-25204

       

       

      Complete logs are attached as tc.out which contains some modifications done to increase timeout by defining Lucene Caches explicitly but as seen from logs 10s time doesn't change.

       

      The questions we have is

      1) We are starting Index Writer from only one of the nodes specifically then why process is trying to acquire locking before complete indexing is completed ?

      2) How to change the interval from 10s. Which parameter is impacting this 10s timeout ?

      3) Will changing time out resolving the locking issue ?

      4) Is send queue defind as 640m small to get filled for our messages or is the problem again related back due to processes waiting for locks ?

        • 1. Re: Problems in executing the mass indexer
          rvansa

          First of all, before we get to your problem: do you *really* consider using 200GB heap size as a sane value? What GC are you using? Have you measured worst-case time for Full GC (in case that you use CMS GC, the Full GC with concurrent mode failure)? Have you checked that your JGroups settings can survive a GC pause that will take approximately 3 minutes (a rule of thumb is that the pause takes 1 second per 1 GB heap). Unless you managed to do so (and in that case I would be very interested how you've achieved that), you'll run into trouble, sooner or later.

           

          1) Then the write where you got the exception from is from internal Infinispan cache that keeps some metadata about the indexed objects - when you start writing concurrently on many nodes, deadlock can be observed (should have been fixed in [ISPN-4569] Inserting into cache with indexing fails for XA transactions - JBoss Issue Tracker but apparently was not completely). IIRC The workaround is to execute one write on one node, wait a while and start loading the tons of entries only after that.

          2) 3) AFAIK you cannot change this configuration, or at least it's not recommended.

          4) Don't understand the question.

          • 2. Re: Problems in executing the mass indexer
            prashant.thakur

            We are using following configuration for jvm

            -Xmx230G -Xms80G -XX:MaxPermSize=256M

            gc logs are attached for 9 collections it took approx 12 minutes and memory is stabilized at 155 GB after index writes and after manually triggering full GC the memory required is ~79GB.

             

            We intended to run 4 instances with max of 80G considering all temporary memory and failover for one node, but probably indexing as such require too much memory which we would like to understand.200G is for all other applications running in parrallel hence overall we want to limit it to 250-300GB in 4 nodes with one replication.

             

            We are storing data as byte[] and wrapped around DefaultDataContainer with our own data container to limit the memory required for data stored in Value part which limits it for 1/6th of memory required in compatibility mode.

             

            This is brief explanation of end state. Can you please suggest how we can achieve same with Indexes as most of request are coming through queries and without indexes it almost halts ?

             

            Question 4) was related to these logs as it mentions send queue is becoming full

             

            29/Apr 16:57:23,100  WARN [TCP] [Timer-2,pocg8-19-node2-26137] (TCPConnectionMap.java:624) - Discarding message because TCP send_queue is full and hasn't been releasing for 2000 ms


            The problem we observe is only when we run Index Writers in multiple nodes and it seems a cluster wide lock is acquired which throws the exception. This happens even when the data size is 100k and memory is 1 GB. As a workaround we tried to run only one instance and we are successfully able to load this data in memory.

            Full GCs are not a problem at present as max was ~2 minutes.


            808.424: [Full GC 54557630K->42200615K(149014016K), 61.3982710 secs]

            1308.521: [Full GC 73517674K->66433263K(187185152K), 77.0424660 secs]

            4330.886: [Full GC 90493321K->69294769K(186785792K), 106.4494330 secs]

            6186.447: [Full GC 106481156K->70444097K(184495616K), 102.3487290 secs]

            6288.853: [Full GC 70444385K->70444125K(184720896K), 78.1089430 secs]

            8318.683: [Full GC 112708292K->72909231K(205616640K), 79.2567090 secs]

            9877.503: [Full GC 107560518K->75617040K(204060672K), 114.5761090 secs]

            11859.376: [Full GC 131735307K->84591478K(232168960K), 68.4739470 secs]


            Can we discuss this online over IRC chat ?

            • 3. Re: Problems in executing the mass indexer
              wdfink

              Lot of problems are related to GC and after tunign GC they disapear. Unfortunatly the GC tuning is an ongoing task as each change in application, load or use-case can behave different.

              Could you show the complete GC configuration?

              Als I recommend to use -Xmx == -Xms, this prevent the GC from recalculating the used memory and adjust at runtime which is expensive.

               

              If you explain your use-case we might better understand your needs.

               

              Regarding IRC discussion I would say you migh check on IRC channel #infinispan whether you can reach someone.

              But remember most of the people are volunteers and will not have the time to chat on demand.

               

              For that you might use JDG, the supported product based on Infinispan, here you will have professional support, a SLA and other benefits.

              • 4. Re: Problems in executing the mass indexer
                prashant.thakur

                The Use case is we are trying to avoid lookups to Oracle DB with Infinispan as front end for a Real time data received from Call processing engine.

                Firstly it prevents costly oracle licenses for each core and secondly it gives much better speed. We are storing information of Subscriber and Account for Telecom Operator and this information is used for lookups when each Call Data Record comes in which is approximately 4-15 billion per day.

                 

                The number of Subscribers may vary from 50 to 100 million with each record occupying approximately 1k bytes after converting to byte array. Storing without byte array was requiring around 6k per record which was a huge over head.

                 

                The data can be looked up using approximately 10 of the fields hence using lookups through key is not possible . We thought over the idea of multiple caches for storing associations but it becomes too much of maintenance overhead. Hence we went ahead with Query feature provided by Infinispan but the problem here is we cannot store data as binary. The query engine has to look data as plain Pojo object hence we implemented a wrapeer around DefaultDataContainer which will mimic data container functionalities but for storage we can still have data stored as binary. Doing a get or Key Value Operation, Iterators by client will still result in Plain Java objects as expected.

                We have also developed a query with string interface from C++ which we would like to contribute back to Infinispan community once its stable.

                 

                In our last benchmarking results we got speed till 60k per sec for get for 4 nodes cluster which is sufficient for the time being. Query we still need to test due to above issues, locally it was giving one third of speed, hence we need some ideas on improving that speed as well.

                 

                As this is still in conceptual stage and not live yet we are experimenting with Infinispan and would go ahead with JDG license once it hits production system.

                 

                Please let me know if further details are required.

                • 5. Re: Problems in executing the mass indexer
                  sannegrinovero

                  I suspect you're hitting https://issues.jboss.org/browse/ISPN-4621 : the issue describes a replicated cache configuration, but this would apply to DIST as well as long as you're doing LOCAL indexing.

                  Please try 7.2.0.Final which includes a fix for ISPN-4627 and also other indexing improvements.

                  • 6. Re: Problems in executing the mass indexer
                    prashant.thakur

                    I see latest as 7.2.0.CR1.

                    Shall I try this version ? Or there is some plan to release 7.2.0.Final in short time.

                    • 7. Re: Problems in executing the mass indexer
                      nadirx

                      7.2.0.Final was scheduled for April 30th, but will be released today because of a last-minute hiccup.

                      • 8. Re: Problems in executing the mass indexer
                        prashant.thakur

                        Thanks Tristan,

                        Will wait for the same.