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

Performance regression in find command (versus legacy OP_QUERY) due to additional contended calls into CursorManager

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 3.2.0-rc0
    • Component/s: Querying
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL

      Description

      Run this script:

      #!/bin/bash
       
      THREADS=$1
      CMD=$2
      if [ "$3" == "" ]; then
          BENCH_SECONDS=10
      else
          BENCH_SECONDS="$3"
      fi
       
      mongo --quiet -eval 'db.foo.insert({_id:1})'
       
      if [ $CMD == "false" ]; then
          mongo --quiet -eval '
          ops = [{op:"find", ns:"test.foo", query: {_id: 1}}]
          results = benchRun({ops:ops, parallel:'$THREADS', seconds:'$BENCH_SECONDS'})
          print(Math.round(results["totalOps/s"]))
          ' 
      else
          mongo --quiet -eval '
          ops = [{op:"command", command: {"find": "foo", "filter": {"_id" : 1}}, ns:"test"}]
          results = benchRun({ops:ops, parallel:'$THREADS', seconds:'$BENCH_SECONDS'})
          print(Math.round(results["totalOps/s"]))
          ' 
      fi
      

      You get much more lock contention with the command path vs not:

      benchRun.find 32 false 30
      233511 ops/s

      -   6.32%  mongod  [kernel.kallsyms]    [k] _raw_spin_lock                                       
         - _raw_spin_lock                                                                              
            - 48.54% futex_wake                                                                        
                 do_futex                                                                              
                 sys_futex                                                                             
                 system_call_fastpath                                                                  
               - __lll_unlock_wake                                                                     
                  + 41.15% mongo::PlanExecutor::registerExec()                                         
                  + 35.88% mongo::PlanExecutor::deregisterExec()                                       
                  + 5.40% mongo::runQuery(mongo::OperationContext*, mongo::QueryMessage&, mongo::Namesp
                  + 5.26% mongo::AutoGetCollection::AutoGetCollection(mongo::OperationContext*, mongo::
                  + 4.98% mongo::AutoGetCollectionForRead::~AutoGetCollectionForRead()                 
                  + 2.61% mongo::getExecutorFind(mongo::OperationContext*, mongo::Collection*, mongo::N
                  + 1.92% mongo::WiredTigerCursor::WiredTigerCursor(std::string const&, unsigned long, 
                  + 1.72% mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit()                     
                  + 1.09% mongo::fillOutPlannerParams(mongo::OperationContext*, mongo::Collection*, mon
            + 30.15% futex_wait_setup                                                                  
            + 18.51% try_to_wake_up      
      

      vs:
      benchRun.find 32 true 30
      119839 ops/s

       -  43.11%  mongod  [kernel.kallsyms]    [k] _raw_spin_lock
        - _raw_spin_lock                                                                              
            - 51.98% futex_wake                                                                        
                 do_futex                                                                              
                 sys_futex                                                                            
                 system_call_fastpath                                                                  
               - __lll_unlock_wake                                                                    
                  + 23.98% mongo::ClientCursor::ClientCursor(mongo::CursorManager*, mongo::PlanExecutor
                  + 20.36% mongo::ClientCursorPin::deleteUnderlying()                                  
                  + 19.67% mongo::PlanExecutor::registerExec()                                        
                  + 18.84% mongo::PlanExecutor::deregisterExec()                                      
                  + 16.71% mongo::ClientCursorPin::ClientCursorPin(mongo::CursorManager*, long long)  
            - 45.15% futex_wait_setup                                                                  
                 futex_wait                                                                            
                 do_futex                                                                              
                 sys_futex                                                                            
                 system_call_fastpath                                                                  
               - __lll_lock_wait                                                                      
                  + 22.64% mongo::ClientCursor::ClientCursor(mongo::CursorManager*, mongo::PlanExecutor
                  + 22.05% mongo::PlanExecutor::deregisterExec()                                      
                  + 19.39% mongo::PlanExecutor::registerExec()                                        
                  + 18.94% mongo::ClientCursorPin::deleteUnderlying()                                  
                  + 16.70% mongo::ClientCursorPin::ClientCursorPin(mongo::CursorManager*, long long)  
            + 2.56% try_to_wake_up  
      

      Contention appears to be CursorManager::_mutex.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              david.storch David Storch
              Reporter:
              martin.bligh Martin Bligh
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              14 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: