Work at SourceForge, help us to make it a better place! We have an immediate need for a Support Technician in our San Francisco or Denver office.

Close

Profiler results for jdbm tests

Kevin Day
2005-08-10
2013-06-03
  • Kevin Day
    Kevin Day
    2005-08-10

    I've started using a time and memory profiler to check out where the jdbm insertion time is going.

    Initial results are interesting (assuming they are meaningful - as with all new tools, I'm a bit skeptical of the accuracy of my results until I get some experience with it)...

    I'm running the PerformanceCompare test (posted in another thread in this forum), with BTree insertions, then again with recman direct insertions.

    The result show that there is a huge amount of time being spent in the FreeLogicalRowIdPage.isAllocated() method when we are doing lots of tiny insertions (i.e. writing to recman directly).

    For insertion of 10000 records, this method is called as follows:

    Recman direct:  8,176,270 calls, 17,959 ms, 29% of run time

    BTree inserts:  1,002,610 calls, 1,662 ms, 10% of run time

    I've got to run for now, but I'll post more as I dig into it.

    - K

     
    • Alex Boisvert
      Alex Boisvert
      2005-08-10

      Kevin,

      Thanks for posting your profiling results, this is interesting data.

      I do have a question for you, however.  When you run the tests, is the computer CPU-bound or I/O-bound?

      I'm asking because in most of my tests, I always end up being I/O bound and that's why I've never really made any efforts to optimize the code from a CPU efficiency standpoint.

      I'm really interested to know whether the difference in performance between the BTree (object clustering) and direct RecordManger approaches lies in more efficient use of the CPU or just more efficient use of kernel I/O primitives (effectively batching I/O calls versus doing lots of small I/O).

      Looking at FreeLogicalRowIdPage.isAllocated() , I don't see any I/O there, just computation and memory allocation.  If the test is I/O-bound (meaning that your computer has CPU to spare during execution), I would look elsewhere for the bottleneck.

      alex

       
    • Kevin Day
      Kevin Day
      2005-08-11

      My testing so far implies CPU bottleneck when doing batch inserts.  This was surprising to me (I really expected it to be IO limited...)

      It might be worth taking a crack at the NIO patch and re-running the tests, just to see if there is a discernable difference there.

      I'm commiting records every 500 inserts (there is absolutely a memory leak in jdbm with transactions turned off - I think that few users of jdbm would think that they need to call commit() with tx disabled... - I'll try to post a patch in the next week that auto-commits whenever tx are disabled)...  Obviously, the impact of this on BTree insertions would be quite a bit different than for direct recman insertions...

      At this point, I'm half wondering if there isn't something inneficient in how the next free logical / physical row is obtained...  That's just guesswork, but it would seem that if the entire logical/physical row table has to be searched for every insert in order to find the first open one, then it would be quite ineficient for batch inserts like we are doing.

      From looking at the code, there is no attempt to cache the previous search result... there may be some modest adjustments that can be made that would drastically improve batch inserts (if indeed this is where the performance problem is happening).  It would be pretty easy to just remember of the index of the last found free row of a given size.  If the next call happens before any page is freed, and it's for a size that is equal to or greater than the last size, then it is safe to just skip straight to that index...

      Another (probably more correct) option would be to change the way the free and used blocks are tracked (use a linked list for the free blocks, with each pointing to the next free block).

      All that said, I need to spend a bit more time in the analysis to make sure there is actually a bottleneck there....

      I'll have some more test results available tomorrow (runs are quite slow with the profiler in place...), and we can tell what the differences between the recman and btree insertions are.

      Cheers!

      - K

       
    • Kevin Day
      Kevin Day
      2005-08-12

      I have more extensive test results to share (I can provide the full test results via email if anyone wants them - but for now, I'll just include the topmost used methods):

      Recman direct - method times for 1000000 records with commit every 500 records
      -----------------------------------
      Name    Calls    %    Time    %    Time/Call    Total time    Inst. time
      jdbm.recman.FreeLogicalRowIdPage.isAllocated    817979074    -269.41    5774509    30.95    0.007059    13333610    31
      jdbm.recman.PhysicalRowId.getBlock    818979048    -269.74    3768096    20.19    0.004601    5697863    0
      jdbm.recman.FreeLogicalRowIdPage.isFree    409002048    -134.71    1962096    10.52    0.004797    8957351    31
      jdbm.recman.BlockIo.readLong    823065806    -271.09    1875583    10.05    0.002279    1907589    79
      jdbm.recman.FreeLogicalRowIdPage.get    821979040    -270.73    1808389    9.69    0.002200    1845084    31
      jdbm.recman.FreeLogicalRowIdPage.getFirstFree    998784    -0.33    1029183    5.52    1.030436    9986572    31
      jdbm.recman.FreeLogicalRowIdPage.getFirstAllocated    999976    -0.33    977147    5.24    0.977170    7331444    31
      jdbm.recman.RecordHeader.getAvailableSize    51998080    -17.13    233277    1.25    0.004486    349258    31
      jdbm.recman.PhysicalRowIdManager.allocNew    1002738    -0.33    210954    1.13    0.210378    687053    62
      jdbm.recman.BlockIo.readInt    51998080    -17.13    111937    0.60    0.002153    113959    79

      BTree - method times for 1000000 records with commit every 500 records
      ------------------------------
      Name    Calls    %    Time    %    Time/Call    Total time    Inst. time
      jdbm.recman.FreeLogicalRowIdPage.isAllocated    68144345    9.06    454807    14.09    0.006674    1042445    31
      jdbm.recman.FreePhysicalRowIdPage.isAllocated    52309465    6.96    321311    9.95    0.006143    737711    32
      jdbm.recman.PhysicalRowId.getBlock    68404687    9.10    299814    9.29    0.004383    446902    0
      jdbm.recman.FreePhysicalRowId.getSize    56828261    7.56    227997    7.06    0.004012    340875    0
      jdbm.recman.FreeLogicalRowIdPage.isFree    34083504    4.53    155931    4.83    0.004575    712907    31
      jdbm.recman.BlockIo.readLong    69076936    9.18    148842    4.61    0.002155    148842    94
      jdbm.recman.FreeLogicalRowIdPage.get    68477623    9.11    142690    4.42    0.002084    143035    31
      jdbm.recman.FreePhysicalRowIdPage.getFirstLargerThan    166598    0.02    126745    3.93    0.760783    871827    32
      jdbm.recman.BlockIo.readInt    57350528    7.63    114203    3.54    0.001991    114203    94
      jdbm.recman.FreePhysicalRowIdPage.get    57078149    7.59    110442    3.42    0.001935    110442    32

      (I hope that all formats itself nicely once I post it...)
      Note on the data:  Ignore the 'call percentages' column data - the totals overflowed Long.MAXVALUE, so the percentages are going to be goofy.  the 'time' and 'time percentage' columns are of must interest for the present discussion.

      My initial analysis concludes:

      When using recman directly, FreeLogicalRowIdPage.isAllocated is being called about 12 times more often than for BTree.  This method, in turn, is called directly by FreeLogicalRowIdPage.isFree - both of these show up in the top 3 methods that consume time during each run.

      isAllocated is called by only two methods:

      1. isFree - this makes a single call to isAllocated
      2. getFirstLargerThan - this makes a bunch of calls to isAllocated in a tight loop.

      My initial inclination here is that we should spend some time looking at the loop in getFirstLargerThan.

      isFree is also called by getFirstFree, which also calls isFree in a tight loop.  This one may be worth looking at as well.

      Another thing that is extremely interesting is that the BTree run wound up calling methods in FreePhysicalRowIdPage quite a bit, but the Recman run didn't call a single method in that class...  I'm not sure at all what the implications are here - maybe someone with more understanding of this class can provide some insight?

      Finally, the profiler I'm using is only giving me totals for the method calls.  It has the capability to show time totals in the call graph, which would really help to pinpoint the problem area here, but for some reason those results aren't being made available to me.

      I'll keep working on it...

      - K

       
      • Alex Boisvert
        Alex Boisvert
        2005-08-12

        Kevin,

        I haven't seen the code of your test, but my guess is that BTree ends up calling FreePhysicalRowIdPage because BPages get relocated on disk as they grow.   This probably doesn't happen with RecordManager because you don't increase the size of the records.

        Thanks for the profiler link, I'll take a look at getFirstLargerThan() and getFirstFree().

        alex

         
        • Kevin Day
          Kevin Day
          2005-08-12

          The test is the same test I posted in the other thread for comparing BTree to recman inserts, but with only one of the modes (BTree or recman) running at a time.  Keys are added monotomically, so the BPage shouldn't have to be relocated on disk at all - if it is, then maybe something funky is going on that is worth taking a look at...

          Or is the act of commiting periodically somehow causing the recman to think it has to move data around?

          - K

           
          • Alex Boisvert
            Alex Boisvert
            2005-08-12

            My explanation for this is that BPages get created, split and updated as the BTree grows.  When this happens, pages become larger as new keys added to the page (after a split).   This results in relocation at the physical level because pages are periodically committed (I assume you use your own patch) down to the physical level.

            alex

             
            • Kevin Day
              Kevin Day
              2005-08-13

              Perfect explanation - I should have realized that.  Thanks for clarifying!

              - K

               
            • Bryan Thompson
              Bryan Thompson
              2005-08-15

              Is there a level at which you can effect the "padding" of a recman allocation such that you could cause, e.g., a BPage object to be allocated with a record that was large enough for its expected final size and thereby avoid some reallocations?

              -bryan

               
              • Kevin Day
                Kevin Day
                2005-08-15

                If you absolutely knew the size of your value and key objects, then yes, this is technically possible.  Unless you are using key compression :-)

                Another way of getting at this would be for the BTree to hold on to the average size of the data (without padding) in it's existing BPages.  Any new BPage created would be padded out to consume that size...  We would definitely take a hit on disk space usage, though.

                The performance results for BTree are pretty darned good though - we could get better results by fighting this battle, but I think we'll have better overall results by focusing on new recman inserts...

                - K

                 
                • Alex Boisvert
                  Alex Boisvert
                  2005-08-15

                  Agreed.  I think we need to focus on the general case first and RecMan inserts appear to be a good optimization candidate based on the results you collected.

                  alex

                   
              • Alex Boisvert
                Alex Boisvert
                2005-08-15

                This isn't possible today but I guess we could provide "hints" for the storage layer to pre-allocate more space for cases when you know the structure size will change.

                We would need to assess the impact on the API...

                alex

                 
                • Bryan Thompson
                  Bryan Thompson
                  2005-08-16

                  Alex,

                  I think that this could be managed by just passing along a 'capacity' parameter in addition to the serialized byte[].

                  A common memory management technique isto
                  maintain linked lists of records of a common size.  The performance issue for recman insert might be improved if we accepted a 'capacity' hint and then rounded up to the nearest boundary for a record in the store, e.g., 64 byte boundary, and then stored the free records on the appropriate list.

                  At that point you no longer have to search the free list, you can just return the record that is the head (or tail) of the list.

                  -bryan

                   
    • Kevin Day
      Kevin Day
      2005-08-12

      FYI - If any of you are using Eclipse, the profiler I'm using is:

      http://eclipsecolorer.sourceforge.net/index_profiler.html

      Be sure to apply the Eclipse 3.1 binary patch (it's in the patches section), and read the "Help for new users" post that I submitted to the "Support" section.

      The tool is really, really, really nice - I've finally got the entire thing working, and it is amazing at how much insight it gives to where your performance bottlenecks are.

      Cheers!

      - K

       
    • Kevin Day
      Kevin Day
      2005-08-12

      The profiler results are pretty clear (finally got it working to my satisfaction)...  During large scale inserts directly to recman, a big chunk of CPU time is consumed by the FreeLogicalRowIdPage.getFirstFree method and methods it calls.

      The methods it calls are relatively benign, so that leaves the getFirstFree method itself as the culprit.

      Looking at it, it appears that a full linear search is being performed, looking for a free slot.  Without a deeper understanding, I'd say that this is the place where the performance hit is coming from...

      - K

       
    • Kevin Day
      Kevin Day
      2005-08-17

      I have made some tweaks to the FreeLogicalRowIdPage class, and the results are actually quite impressive.  For insertion of small values (150 bytes), performance of the record manager direct inserts is more than 300% faster.  Performance of BTree direct inserts is more than 25% faster.  For insertion of large values (1500 bytes), record manager performance is 75% faster, while BTree insertions are about the same.

      With these changes, inserts directly to the record manager are faster than inserts to the BTree (which is what we would have expected).

      I'm really not sure what kind of unit testing should be performed against these changes...  The pre-existing unit tests pass fine, but I'm not sure if we need to add any additional tests...

      Alex - can you give me some feedback on this?

      I am going to submit the patch so others can see what I've done and comment on the changes.

      One final comment:  The changes I made here should also bennefit the FreePhysicalRowIdPage class.

      - K

      Test results (I also have method profiler results if anyone wants them, but the overall performance numbers tell most of the story here):

      Adding 10,000 records, 150 bytes each.  Transactions disabled (with my autocommit patch in place).

      Before change:

      rmDirect: 18608 mills - 5374 recs/sec
      rmDirect db filesize = 16867328
      btree: 7312 mills - 13676 recs/sec
      btree db filesize = 17506304

      rmDirect: 5343 mills - 18716 recs/sec
      rmDirect db filesize = 16867328
      btree: 5812 mills - 17205 recs/sec
      btree db filesize = 17506304

      Adding 10,000 records, 1500 bytes each.  Transactions disabled (with my autocommit patch in place).  The BTree page size was set to 26 - definitely not optimized for this size of data, so BTree performance gains may not be accurate.

      Before change:

      rmDirect: 26719 mills - 3742 recs/sec
      rmDirect db filesize = 152199168
      btree: 21218 mills - 4712 recs/sec
      btree db filesize = 153518080

      After change:

      rmDirect: 15344 mills - 6517 recs/sec
      rmDirect db filesize = 152199168
      btree: 19984 mills - 5004 recs/sec
      btree db filesize = 153518080

       
      • Alex Boisvert
        Alex Boisvert
        2005-08-17

        Kevin -

        Great stuff!  The performance improvements are impressive.

        I'll take a look at your changes and provide feedback shortly.

        alex