Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-22964

IX GlobalLock being held while wating for wt cache eviction

    Details

    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      Linux
    • Backport Completed:
    • Steps To Reproduce:
      Hide

      1. setup a two node replSet using the attached mongod.conf(only specify storage related)
      2. run test.sh
      3. It will hang after running the script for about a long time(2 days+)

      Show
      1. setup a two node replSet using the attached mongod.conf(only specify storage related) 2. run test.sh 3. It will hang after running the script for about a long time(2 days+)

      Description

      hi,
      I'm currently doing a pressure test for 3.2.3 using the attached test script. The testing environment is a two nodes replSet using WiredTiger. After running the script for long time(about 2 days). The mongod process will hang. As you can see in the attached thread stack, a lot of threads were waiting for the GlobalLock which was being held by someone(probably the thread doing profile, i.e. Thread 501). Looks like the thread locked it with MODE_IX and was doing a cappedDelete operation, making room for new profiling document. But it seems that it was waiting on WT's cache evict_waiter_cond and hangs there forever.

      1. diags1.tgz
        17.16 MB
        Ramon Fernandez
      2. global_lock_hang.ts
        1.21 MB
        CenZheng
      3. mongod.conf
        0.3 kB
        CenZheng
      4. test.sh
        0.8 kB
        CenZheng

        Issue Links

          Activity

          Hide
          ramon.fernandez Ramon Fernandez added a comment -

          CenZheng, can you please upload here the contents of the diagnostic.data directory from your dbpath and the full log file of the affected node?

          I'll try to reproduce this behavior on my end in the mean time, but since you say it takes two days it will be faster to look at the diagnostic data already captured by your system.

          Thanks,
          Ramón.

          Show
          ramon.fernandez Ramon Fernandez added a comment - CenZheng , can you please upload here the contents of the diagnostic.data directory from your dbpath and the full log file of the affected node? I'll try to reproduce this behavior on my end in the mean time, but since you say it takes two days it will be faster to look at the diagnostic data already captured by your system. Thanks, Ramón.
          Hide
          zhcn381 CenZheng added a comment -

          hi Ramon,
          I can't upload the diagnositc.data directory due to the poor network status. I'll try on next Monday if you still need it then.
          Thanks

          Show
          zhcn381 CenZheng added a comment - hi Ramon, I can't upload the diagnositc.data directory due to the poor network status. I'll try on next Monday if you still need it then. Thanks
          Hide
          ramon.fernandez Ramon Fernandez added a comment -

          CenZheng, I have been running your repro script for almost 48h but my setup hasn't hung. We do have some ideas about what the issue could be, but if it is possible for you to upload the diagnostic.data folder this information would still be useful investigating this ticket.

          Thanks,
          Ramón.

          Show
          ramon.fernandez Ramon Fernandez added a comment - CenZheng , I have been running your repro script for almost 48h but my setup hasn't hung. We do have some ideas about what the issue could be, but if it is possible for you to upload the diagnostic.data folder this information would still be useful investigating this ticket. Thanks, Ramón.
          Hide
          zhcn381 CenZheng added a comment -

          hi Ramon, I have uploaded last time's diagnostic.data file, pls check!

          Thanks

          Show
          zhcn381 CenZheng added a comment - hi Ramon, I have uploaded last time's diagnostic.data file, pls check! Thanks
          Hide
          ramon.fernandez Ramon Fernandez added a comment -

          Thanks for uploading CenZheng, I can see the diagnostics data and I'm taking a look.

          Show
          ramon.fernandez Ramon Fernandez added a comment - Thanks for uploading CenZheng , I can see the diagnostics data and I'm taking a look.
          Hide
          zhcn381 CenZheng added a comment -

          Hi, Ramon

          The situation occurred again, I have uploaded the latest diagnostics data(metrics.2016-03-09T13-01-56Z-00000.tar.gz). You can have a look.

          Thanks~

          Show
          zhcn381 CenZheng added a comment - Hi, Ramon The situation occurred again, I have uploaded the latest diagnostics data(metrics.2016-03-09T13-01-56Z-00000.tar.gz). You can have a look. Thanks~
          Hide
          ramon.fernandez Ramon Fernandez added a comment -

          Thanks for the additional information CenZheng, we believe we've identified the source of the problem and have produced a fix in WT-2451. Here's the explanation from a colleague:

          What's causing the issue is the large amount of create and drop operations: each time a create or drop is done we update the WiredTiger metadata. The metadata is currently never evicted from the cache which means that we never remove entries created for deleted items, so if there are enough create/drop operations the metadata can grow quite large. If the cache is reasonably constrained we can end up with a situation where the metadata fills the entire cache and prevents other operations from completing.

          This large amount of create and drop operations is not very common in production cases, but not unheard of either. If this will be your production use case, until this fix makes it into a stable release note that using a larger WiredTiger cache will easily help you work around the issue.

          Regards,
          Ramón.

          Show
          ramon.fernandez Ramon Fernandez added a comment - Thanks for the additional information CenZheng , we believe we've identified the source of the problem and have produced a fix in WT-2451 . Here's the explanation from a colleague: What's causing the issue is the large amount of create and drop operations: each time a create or drop is done we update the WiredTiger metadata. The metadata is currently never evicted from the cache which means that we never remove entries created for deleted items, so if there are enough create/drop operations the metadata can grow quite large. If the cache is reasonably constrained we can end up with a situation where the metadata fills the entire cache and prevents other operations from completing. This large amount of create and drop operations is not very common in production cases, but not unheard of either. If this will be your production use case, until this fix makes it into a stable release note that using a larger WiredTiger cache will easily help you work around the issue. Regards, Ramón.
          Hide
          zhcn381 CenZheng added a comment -

          Get it, Thank you Ramon~

          Show
          zhcn381 CenZheng added a comment - Get it, Thank you Ramon~

            People

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

              Dates

              • Created:
                Updated:
                Resolved: