7 Replies Latest reply: Aug 22, 2013 5:58 PM by Greybird-Oracle RSS

    Slow startup - even after agressive checkpointing - how to troubleshoot?

    kbranko

      Hi,

       

      We are evaluating Berkley DB for Java and we run into problem that recovery time is very very slow.

       

      We first tried to speed up recovery using  je.checkpointer.highPriority, je.checkpointer.wakeupInterval, etc... - no luck - startup stil is very inefficient. It takes about 4 hours to recover and start 10 databases each which has less than 10M records.

       

      So in order to understand the problem we built a small test app which will checkpoint and clean logs in the main application thread (and disable checkpoint and cleaner threads). So we set that we call bdbEnv.checkpoint(checkpointConfig) with setMinimizeRecoveryTime and setForce.

       

      Again recovery was super slow: even if we were calling bdbEnv.cleanLog and bdbEnv.checkpoint every 3000 records. Each records is less than 1KB long - uniq keys.  Note that in our test each thread has its own database handle and its own transaction for adding records.

       

      Now, the interesting thing, we noticed that during the startup (that is recovery of that environment) read rate of application was *only* 4 KB/s - and machine running the test was completely idle (quad core with quad-core).

       

      Here is our stack trace (showing that we are doing recovery):

       

              at java.io.RandomAccessFile.readBytes(Native Method)

              at java.io.RandomAccessFile.read(RandomAccessFile.java:355)

              at com.sleepycat.je.log.FileManager.readFromFileInternal(FileManager.java:1918)

              - locked <0x00000007d2da9b80> (a com.sleepycat.je.log.FileManager$DefaultRandomAccessFile)

              at com.sleepycat.je.log.FileManager.readFromFile(FileManager.java:1869)

              at com.sleepycat.je.log.FileReader$ReadWindow.fillFromFile(FileReader.java:1146)

              at com.sleepycat.je.log.FileReader$ReadWindow.slideAndFill(FileReader.java:1048)

              at com.sleepycat.je.log.FileReader.setBackwardPosition(FileReader.java:572)

              at com.sleepycat.je.log.FileReader.getLogEntryInReadBuffer(FileReader.java:429)

              at com.sleepycat.je.log.FileReader.readNextEntryAllowExceptions(FileReader.java:256)

              at com.sleepycat.je.log.FileReader.readNextEntry(FileReader.java:229)

              at com.sleepycat.je.recovery.RecoveryManager.undoLNs(RecoveryManager.java:1006)

              at com.sleepycat.je.recovery.RecoveryManager.buildTree(RecoveryManager.java:530)

              at com.sleepycat.je.recovery.RecoveryManager.recover(RecoveryManager.java:198)

              at com.sleepycat.je.dbi.EnvironmentImpl.finishInit(EnvironmentImpl.java:611)

              - locked <0x000000077e4994d8> (a com.sleepycat.je.dbi.EnvironmentImpl)

              at com.sleepycat.je.dbi.DbEnvPool.getEnvironment(DbEnvPool.java:208)

       

      The DbPrintLog output of one of our test database for which recovery takes very long time like this:

       

      <DbPrintLog>

      Log statistics:

                      type               total         provisional               total                 min                 max                 avg             entries

                                         count               count               bytes               bytes               bytes               bytes         as % of log

                     MapLN                 346                   0             683,346                 501               4,337               1,974                   0

                    NameLN                   6                   0                 184                  30                  34                  30                   0

             FileSummaryLN               3,939                   0             766,896                  24               7,084                 194                   0

                        IN                 869                   0         172,255,390                  46             353,817             198,222                 4.9

                       BIN               3,670               3,648       1,690,627,274                  42             708,998             460,661                  48

                    DbTree                  57                   0             107,333                 760               3,124               1,883                   0

                    Commit                   9                   0                 262                  29                  30                  29                   0

                 CkptStart                  52                   0               1,352                  26                  26                  26                   0

                   CkptEnd                  53                   0               4,665                  55                 105                  88                   0

                  BINDelta              33,437              32,383       1,186,036,703                  41             162,988              35,470                33.6

                     Trace                 645                   0             107,702                  46                 381                 166                   0

                FileHeader                 341                   0              12,958                  38                  38                  38                   0

                 INS_LN_TX             157,699                   0         220,123,663               1,390               1,396               1,395                 6.2

                    UPD_LN             183,600                   0         254,469,600               1,386               1,386               1,386                 7.2

                 key bytes                                                 467,579,630                                                                          (13.3)

                data bytes                                                           0                                                                             (0)

       

       

      Total bytes in portion of log read: 3,525,197,328

      Total number of entries: 384,723

       

      How to troubleshoot these kind of problem? Is there a way to speed up the recovery?

      If we want to do checkpoint and clean logs in the main application thread, how often do we need to check point? Or maybe our data is not really good for Berkeley DB?

        • 1. Re: Slow startup - even after agressive checkpointing - how to troubleshoot?
          Bogdan Coman-Oracle

          Hi,

           

          Thank you for taking the time to run all the tests.

          How to troubleshoot these kind of problem? Is there a way to speed up the recovery?

          If we want to do checkpoint and clean logs in the main application thread, how often do we need to check point? Or maybe our data is not really good for Berkeley DB?

           

          Yes, there are ways to speed-up recovery. First we need to understand the problem. Then we can discuss performance tuning and how well the data and the application fits the JE configuration you're using.

           

          Can you please post the following information:

          1. The BDB JE release you're using.

          2. The JE config (I'm looking to know all the parameters you modified from the default settings).

          3. The lower part of the DbPrintLog output, which shows the checkpoint intervals.

          4. When reproducing with the current JE configuration, do you start from scratch (new environment)?

           

          Details of your application as I understood them:

          Records < 1K each, no duplicates.

          10 databases, under 10M records each.

          Each thread has its own database handle and its own transaction for adding records.

           

          You are correct, one of the requirements for reduced recovery time is a shorter checkpoint interval. As per my understanding, you are running the checkpoints at very short intervals.

          • 2. Re: Slow startup - even after agressive checkpointing - how to troubleshoot?
            kbranko

            Hi - Thanks for prompt reply.

             

            We are testing je version 5.0.73. We use Java HotSpot(TM) 64-Bit Server VM 1.7.0_25-b15 .

             

            The config from je.properties is like this (we tried many setups but amazingly we are not getting any better results).

             

            je.env.runCheckpointer=true

            je.env.runCleaner=true

            je.cleaner.readSize=262144

            je.log.iteratorReadSize=262144

            je.nodeMaxEntries=512

            je.log.fileCacheSize=2000

            je.checkpointer.highPriority=true

            je.checkpointer.bytesInterval=1024

            je.cleaner.threads=55

            je.lock.nLockTables=10

             

            Here is snapshots of DbPrintLog (NOTE this is different test suite from my initial post - it is better representative of actual data we plan to load):

            Per checkpoint interval info:

                           lnTxn                  ln            mapLNTxn               mapLN          end to end        end to start        start to end         maxLNReplay             ckptEnd

                               0                 910                   0                  12          11,703,759       9,241,144,578                   0                 910   0x25/0x19ff4f

                               0               5,080                   0                  97          14,038,619             715,364          13,323,255               5,080   0x2a/0x579f2a

                               1               3,790                   0                 107           4,998,015           1,382,532           3,615,483               8,121   0x30/0xb4c29

                               0               5,130                   0                 145          15,960,469           1,436,701          14,523,768               7,226   0x35/0x663f3e

                               0               5,038                   0                 131          12,375,217           1,695,438          10,679,779               8,466   0x3b/0x8a7d6f

                               0               1,781                   0                 101           2,075,819       9,182,068,499                   0               4,649   0x43/0x11939a

                               2               7,950                   0                 135          17,152,063           2,729,994          14,422,069               7,952   0x4a/0x7eb559

                               0               3,202                   0                 100           5,127,681           1,195,507           3,932,174               7,933   0x59/0x345cda

                               0              10,552                   0                 135          20,431,569           4,212,674          16,218,895              12,576   0xd2/0x3af2ab

                               0              10,601                   0                 106          24,876,708           3,305,358          21,571,350              16,021   0xe9/0x855c4f

                               0               1,484                   0                  90           1,533,766             951,993             581,773               8,314   0x110/0x42d15

                               0               5,881                   0                  99          14,702,454           2,613,108          12,089,346               6,211   0x120/0x4bee0b

                               0               5,979                   0                 126          14,287,467           2,193,111          12,094,356               8,583   0x12f/0x8d59f6

                               0               1,777                   0                   3           2,795,036       9,081,880,972                   0               5,022   0x13f/0x1f6992

                               0              21,921                   0                 238          52,194,679          40,232,158          11,962,521              21,921   0x184/0x40e689

                               0               2,753                   0                 119           8,988,839           1,898,264           7,090,575              20,314   0x197/0x3178b0

                               2               8,620                   0                 124          21,213,231           2,734,555          18,478,676               9,529   0x1aa/0x43fbdf

                               3              24,724                   0                 156          61,258,550           2,465,768          58,792,782              30,124   0x1db/0x573015

                               0              20,789                   0                 157          50,072,606       8,935,430,637                   0              42,698   0x1f6/0x584bb3

                               0               6,968                   0                 133          21,504,123           1,222,236          20,281,887               6,968   0x20e/0x6f3f2e

                               2              30,225                   0                 205          74,874,310           1,859,035          73,015,275              36,094   0x230/0x2108f4

                               8             195,904                   0                 596         520,744,531         295,008,697         225,735,834             224,256   0x2b9/0x2c6547

                               2              91,290                   0                 249         287,724,927           6,782,319         280,942,608             282,012   0x2f1/0x9ae46

                              19             247,659                   0               1,200       1,039,622,602           5,990,581       1,033,632,021             332,237   0x35c/0x3ec10

                             132             720,088                   0               5,523       5,032,316,557          77,875,588       4,954,440,969             961,989   0x553/0x27451d

                              77             125,269                   0               2,199       1,908,570,981         573,364,935                   0             819,613   0x612/0x117702

            </DbPrintLog>

             

            I'm not sure what this output means. It is interesting that DbPrintLog takes only 1m20s.

             

            Regarding other setup - yes we are testing setup which will will have ~1K records and many threads adding these records to database. The idea is that we load these records into application once and then use them.

            The problem after we load these records, the application restart takes hours. Before we shutdown the application we do explicit checkpoint with setMinimizeRecoveryTime. Maybe the problem is that we are calling checkpoint and that is failing causing the system to get into full recovery?

             

            Also we do not use any transactions and we call db_sync every 100 records or so.

             

            Thanks!

            • 3. Re: Slow startup - even after agressive checkpointing - how to troubleshoot?
              Bogdan Coman-Oracle

              Hi,

               

              1) The reason for the long recovery is long checkpoints. The last valid checkpoint in the DbPrintLog output (only the last few are valid, due to log cleaning) is 5 GB.  So in spite of the fact you say you are doing frequent checkpoints, the checkpoints are taking a very, very long time.

               

              2)

              we call db_sync every 100 records or so.

               

              I don't know why you're calling sync (I assume Database.sync?) every 100 records.  That's extremely expensive and will contribute to long recoveries. Please note that once committed to your databases, your modifications will persist even in the event of an application or system failure.

              The idea is that we load these records into application once and then use them.

              If you want to do an efficient initial bulk load (populate the database in a batch mode by doing large set of writes, usually inserts but sometimes also updates and deletions), we can give you instructions for doing that -- calling Database.sync or checkpoint often is the wrong thing in this case.

               

              3) Seems like you aren't setting the cache size (unless it's in code you didn't send), so we need to know the heap size (default cache size is 60% of the heap).  It is possible the cache is much too small and that's the main cause of the long checkpoints.

               

              4)

              Also we do not use any transactions.

              In the initial report you mentioned you are using transactions:

              Note that in our test each thread has its own database handle and its own transaction for adding records.

              If you do use transaction, I would like to learn more on how you use them. Do you keep the transactions open for short or long periods of time? If they are open for long, this could cause long recovery times.  This is because recovery must replay from the "first active LSN" onward, which is the location of the first record written by any unclosed txn.

               

              Related documentation:

              Sizing the Cache - http://docs.oracle.com/cd/E17277_02/html/GettingStartedGuide/cachesize.html

              Checkpoints - http://docs.oracle.com/cd/E17277_02/html/TransactionGettingStarted/chkpoint.html

              Non-Durable Transactions - http://docs.oracle.com/cd/E17277_02/html/TransactionGettingStarted/nodurabletxn.html

               

              Thanks,

              Bogdan

              • 4. Re: Slow startup - even after agressive checkpointing - how to troubleshoot?
                kbranko

                Thank you very much for your help.

                 

                I'm sorry for confusion: we tried with transactions, without transactions, with/without sync, cache size from 1 to 32 GB. And it seems like no luck.

                However, we did noticed many messages hidden between all our logs (my mistake for not checking for BDB error in our logs):

                 

                com.sleepycat.je.utilint.DaemonThread run

                SEVERE: <DaemonThread name="Checkpointer"/> caught exception, java.lang.NullPointerException Continuing

                java.lang.NullPointerException

                        at com.sleepycat.je.dbi.DbTree$RootLevel.doWork(DbTree.java:1959)

                        at com.sleepycat.je.tree.Tree.withRootLatchedShared(Tree.java:426)

                        at com.sleepycat.je.dbi.DbTree.getHighestLevel(DbTree.java:1886)

                        at com.sleepycat.je.recovery.DirtyINMap.selectDirtyINsForCheckpoint(DirtyINMap.java:250)

                        at com.sleepycat.je.recovery.Checkpointer.doCheckpoint(Checkpointer.java:729)

                        at com.sleepycat.je.recovery.Checkpointer.onWakeup(Checkpointer.java:508)

                        at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:163)        at java.lang.Thread.run(Thread.java:724)

                 

                Basically, is seems like checkpointer is dying every little. We are doing checkpoints but they are failing

                 

                So my questions are: is the above error fatal for checkpointer? Will checkpointer thread restart after error like the above? Can this error be cause of our problem? Is there some parameter/tweak to ensure this is not happening?

                • 5. Re: Slow startup - even after agressive checkpointing - how to troubleshoot?
                  Bogdan Coman-Oracle

                  com.sleepycat.je.utilint.DaemonThread run

                  SEVERE: <DaemonThread name="Checkpointer"/> caught exception, java.lang.NullPointerException Continuing

                  java.lang.NullPointerException

                          at com.sleepycat.je.dbi.DbTree$RootLevel.doWork(DbTree.java:1959)

                          at com.sleepycat.je.tree.Tree.withRootLatchedShared(Tree.java:426)

                          at com.sleepycat.je.dbi.DbTree.getHighestLevel(DbTree.java:1886)

                          at com.sleepycat.je.recovery.DirtyINMap.selectDirtyINsForCheckpoint(DirtyINMap.java:250)

                          at com.sleepycat.je.recovery.Checkpointer.doCheckpoint(Checkpointer.java:729)

                          at com.sleepycat.je.recovery.Checkpointer.onWakeup(Checkpointer.java:508)

                          at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:163)        at java.lang.Thread.run(Thread.java:724)

                   

                   

                  Thanks for posting the error. The exception will prevent checkpoints, which will cause the long recoveries.

                  We assume this is a JE bug at this point. We'll fix it for the next patch release (Q3), under bug number [#22631].

                   

                  Please note that it would only happen when a database is created and no record is ever inserted. So a work around is to remove such databases, if they are not needed, or write a single record after creating them and delete it or abort the txn. Would you consider giving this workaround a try? This way you can help us confirm it works and that our assumption is correct.

                   

                  Thanks,

                  Bogdan

                  • 7. Re: Slow startup - even after agressive checkpointing - how to troubleshoot?
                    Greybird-Oracle