Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-1777

Degenerate case in wtperf run paging in

    Details

    • Type: Task
    • Status: Closed
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Labels:

      Description

      While running log-append.wtperf on Jenkins wtperf effectively hung in __wt_page_in_func. Although it was running the code from WT-1774, I do not believe the log code is involved in this issue.

      The test is running on the Jenkins AWS box, a m2.4xlarge, equivalent to my AWS HDD. I ended up killing it after gathering some information.

      A normal test run completes in about 169 seconds and the test.stat file looks like this:

      1687998 populate inserts (9659745 of 50000000) in 5 secs (35 total secs)
      1998511 populate inserts (11658256 of 50000000) in 5 secs (40 total secs)
      1932159 populate inserts (13590415 of 50000000) in 5 secs (45 total secs)
      1986784 populate inserts (15577199 of 50000000) in 5 secs (50 total secs)
      

      This test run hit some kind of problem very quickly and never recovered. Its test.stat file looks like:

      157894 populate inserts (157894 of 50000000) in 5 secs (5 total secs)
      503 populate inserts (158397 of 50000000) in 5 secs (10 total secs)
      504 populate inserts (158901 of 50000000) in 5 secs (15 total secs)
      506 populate inserts (159407 of 50000000) in 5 secs (20 total secs)
      ...
      500 populate inserts (222988 of 50000000) in 5 secs (655 total secs)
      512 populate inserts (223500 of 50000000) in 5 secs (660 total secs)
      504 populate inserts (224004 of 50000000) in 5 secs (665 total secs)
      

      After more than 10 minutes it had only done 224k of 50M operations. We are getting 100 operations per second!

      I ran pmp and it shows this every time. Our 8 populate threads are sleeping and nothing else is going on:

            8 select,__wt_sleep,__wt_page_in_func,__wt_row_search,__wt_btcur_insert,__curfile_insert,populate_thread,start_thread,clone
            2 
            1 select,__wt_sleep,__evict_server,start_thread,clone
            1 pthread_cond_wait@@GLIBC_2.3.2,__wt_cond_wait,__ckpt_server,start_thread,clone
            1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__sweep_server,start_thread,clone
            1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__log_wrlsn_server,start_thread,clone
            1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__log_server,start_thread,clone
            1 pthread_cond_timedwait@@GLIBC_2.3.2,__wt_cond_wait,__log_close_server,start_thread,clone
      

      The AWS console charts show virtually no I/O going on during this test's run time. It does show significant I/O at the times of the other runs of this test.

        Issue Links

          Activity

          Hide
          agorrod Alex Gorrod added a comment -

          Sue Loverso Have you seen this more than once? It would be nice to reproduce to see what the state of the cache is.

          Show
          agorrod Alex Gorrod added a comment - Sue Loverso Have you seen this more than once? It would be nice to reproduce to see what the state of the cache is.
          Hide
          sueloverso Sue Loverso added a comment -

          Tomorrow I'll modify wtperf so that if it finds low throughput in that range it can abort and we can look at the cache and run it in a loop.

          Show
          sueloverso Sue Loverso added a comment - Tomorrow I'll modify wtperf so that if it finds low throughput in that range it can abort and we can look at the cache and run it in a loop.
          Hide
          sueloverso Sue Loverso added a comment -

          On my AWS HDD system, with current develop, I can repro in 1-3 iterations (I added an abort if wtperf gets < 1000 ops in 3 successive reporting intervals). If I turn on statistics logging, it didn't fail (after 6 iterations). Given how quickly I can reproduce this, I'm surprised Jenkins hasn't hit it (other than the time I was watching it).

          Show
          sueloverso Sue Loverso added a comment - On my AWS HDD system, with current develop, I can repro in 1-3 iterations (I added an abort if wtperf gets < 1000 ops in 3 successive reporting intervals). If I turn on statistics logging, it didn't fail (after 6 iterations). Given how quickly I can reproduce this, I'm surprised Jenkins hasn't hit it (other than the time I was watching it).
          Hide
          sueloverso Sue Loverso added a comment -

          I believe it is the recent split changes that introduced this. If I run dc196438590, I was not able to reproduce it (in over 40 iterations). Running changeset dfec806a9b39f4ed it again failed quickly (4 iterations).

          Show
          sueloverso Sue Loverso added a comment - I believe it is the recent split changes that introduced this. If I run dc196438590, I was not able to reproduce it (in over 40 iterations). Running changeset dfec806a9b39f4ed it again failed quickly (4 iterations).
          Hide
          sueloverso Sue Loverso added a comment -

          We have a giant page. Cache size is 1Gb. The threads keep getting EBUSY from the __wt_page_release_evict call. Some info:

          The btree root:

          root = {page = 0x8ede00, home = 0x0, 
              ref_hint = 0, state = WT_REF_MEM, addr = 0x0, key = {recno = 0, ikey = 0x0}, 
              page_del = 0x0},
          

          The ref:

          (gdb) p *ref
          $4 = {page = 0x7fbf38135fa0, home = 0x8ede00, ref_hint = 12183, 
            state = WT_REF_MEM, addr = 0x0, key = {recno = 140459255984320, 
              ikey = 0x7fbf380ef0c0}, page_del = 0x0}
          

          And the page, it is 870Mb:

          (gdb) p *page
          $5 = {u = {intl = {recno = 140459255042048, parent_ref = 0x0, 
                __index = 0x7fbf38135fe8}, row = {ins = 0x7fbf38009000, upd = 0x0, 
                d = 0x7fbf38135fe8, entries = 0}, col_fix = {recno = 140459255042048, 
                bitf = 0x0, entries = 940793832}, col_var = {recno = 140459255042048, 
                d = 0x0, repeats = 0x7fbf38135fe8, nrepeats = 0, entries = 0}}, 
            type = 7 '\a', flags_atomic = 0 '\000', read_gen = 1, 
            memory_footprint = 870609380, dsk = 0x0, modify = 0x7fbf380c2940}
          

          Show
          sueloverso Sue Loverso added a comment - We have a giant page. Cache size is 1Gb. The threads keep getting EBUSY from the __wt_page_release_evict call. Some info: The btree root: root = {page = 0x8ede00, home = 0x0, ref_hint = 0, state = WT_REF_MEM, addr = 0x0, key = {recno = 0, ikey = 0x0}, page_del = 0x0}, The ref: (gdb) p *ref $4 = {page = 0x7fbf38135fa0, home = 0x8ede00, ref_hint = 12183, state = WT_REF_MEM, addr = 0x0, key = {recno = 140459255984320, ikey = 0x7fbf380ef0c0}, page_del = 0x0} And the page, it is 870Mb: (gdb) p *page $5 = {u = {intl = {recno = 140459255042048, parent_ref = 0x0, __index = 0x7fbf38135fe8}, row = {ins = 0x7fbf38009000, upd = 0x0, d = 0x7fbf38135fe8, entries = 0}, col_fix = {recno = 140459255042048, bitf = 0x0, entries = 940793832}, col_var = {recno = 140459255042048, d = 0x0, repeats = 0x7fbf38135fe8, nrepeats = 0, entries = 0}}, type = 7 '\a', flags_atomic = 0 '\000', read_gen = 1, memory_footprint = 870609380, dsk = 0x0, modify = 0x7fbf380c2940}
          Hide
          agorrod Alex Gorrod added a comment -

          Sue Loverso I caught this one earlier in a gdb session and I think the large page is a symptom. This particular wtperf configuration sets up 8 threads populating the table - sometimes we get into a situation where we are constantly attempting to force evict the page and never succeeding.

          The huge page is a leaf page - we have been aggressively attempting to force evict it since it was 5MB.

          Show
          agorrod Alex Gorrod added a comment - Sue Loverso I caught this one earlier in a gdb session and I think the large page is a symptom. This particular wtperf configuration sets up 8 threads populating the table - sometimes we get into a situation where we are constantly attempting to force evict the page and never succeeding. The huge page is a leaf page - we have been aggressively attempting to force evict it since it was 5MB.
          Hide
          michael.cahill Michael Cahill added a comment -

          This should be fixed by the merge of WT-1787. After some discussion about what the eviction server is actually doing Alex Gorrod opened WT-1788 for discussion about redesigning / simplifying eviction.

          Show
          michael.cahill Michael Cahill added a comment - This should be fixed by the merge of WT-1787 . After some discussion about what the eviction server is actually doing Alex Gorrod opened WT-1788 for discussion about redesigning / simplifying eviction.
          Hide
          ramon.fernandez Ramon Fernandez added a comment -

          Additional ticket information from GitHub

          This ticket was referenced in the following commits:
          Show
          ramon.fernandez Ramon Fernandez added a comment - Additional ticket information from GitHub This ticket was referenced in the following commits: 9c60b462a25a36915207dde240579c5aa673f2c7

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Days since reply:
                2 years, 10 weeks, 2 days ago
                Date of 1st Reply: