[SERVER-20786] Performance Regression in Mongo-Perf MMS/single threaded workloads from 3.0.6 (Update.MmsIncShallow1, ...) Created: 24/Sep/15  Updated: 06/Dec/22  Resolved: 05/Aug/19

Status: Closed
Project: Core Server
Component/s: Performance
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: David Daly Assignee: Backlog - Query Team (Inactive)
Resolution: Won't Fix Votes: 0
Labels: mpreg, query-44-grooming
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Assigned Teams:
Query
Operating System: ALL
Sprint: Performance B (11/02/15)
Participants:

 Description   

Performance regression across all 4 build variants for single threaded performance on Mongo-Perf.

Slightly more pronounced on 1 node repl set over stand-alone, but present in both cases.

Update.MmsIncShallow1 is the largest offender.
Regression seems to be over time. Between 3.0.6, and 3.1.0, 3.1.3, and 3.1.4.

Regression in WiredTiger Standalone (cumulative 11-13% degradation) and in MMAP (cumulative 13-17% degradation).

Can be reproduced with

var setupMMS = function( collection ) {
    collection.drop();
 
    var base = { _id: 0, a: 0, h: {}, z: 0 };
    for (var i = 0; i < 24; i++) {
        base.h[i] = {};
        for (var j = 0; j < 60; j++) {
            base.h[i][j] = { n: 0, t: 0, v: 0 };
        }
    }
    collection.insert(base);
};
 
use test0
setupMMS(db.Update_MmsIncShallow10)
benchRun({"ops":[{"op":"update","query":{"_id":0},"update":{"$inc":{"a":1}},"ns":"test0.Update_MmsIncShallow10","safe":false,"w":0,"j":false,"writeCmd":true}],"seconds":5,"host":"127.0.0.1:27017","parallel":1})



 Comments   
Comment by Craig Homa [ 05/Aug/19 ]

Closing as future perf work should be based on a broad view of system perf instead of targeting old reports of perf regressions.

Comment by Eddie Louie [ 06/Sep/17 ]

This seems like a very old ticket. Should we close this?

Comment by David Daly [ 30/Nov/15 ]

This has gotten a couple percent faster (8% regression) since this ticket was filed, but still worth investigating. Here are more recent WT results

Comment by Githook User [ 27/Oct/15 ]

Author:

{u'username': u'ksuarz', u'name': u'Kyle Suarez', u'email': u'ksuarz@gmail.com'}

Message: SERVER-20786 overrides for singleThreaded

Closes #1040

Signed-off-by: dalyd <david.daly@mongodb.com>
Branch: master
https://github.com/mongodb/mongo/commit/70a6c8b04b1b3250db7b4a982217ec9a7d4e1e15

Comment by Githook User [ 22/Oct/15 ]

Author:

{u'username': u'dalyd', u'name': u'David', u'email': u'david.daly@mongodb.com'}

Message: Merge pull request #1032 from ksuarz/master

SERVER-20786 override singleThreaded regression
Branch: master
https://github.com/mongodb/mongo/commit/30efc2300ad8740023ebb432723a1e662d16ef89

Comment by Githook User [ 22/Oct/15 ]

Author:

{u'username': u'ksuarz', u'name': u'Kyle Suarez', u'email': u'ksuarz@gmail.com'}

Message: SERVER-20786 override singleThreaded regression
Branch: master
https://github.com/mongodb/mongo/commit/46690d94e3f1350788226c2af3ecbb92020cc351

Comment by Martin Bligh [ 08/Oct/15 ]

OK, I backed out some logging changes I had in my dev view - now I get 27500 ops/s with either 3.0.6 or master.

Comment by Martin Bligh [ 08/Oct/15 ]

Oops. Previous seems to be bleed-through from something else, not sure how perf attributed it to mongod.

Old profile:

+   2.49%  mongod  mongod               [.] operator new(unsigned long)                            
+   2.14%  mongod  mongod               [.] mongo::validateBSON(char const*, unsigned long)        
+   1.73%  mongod  libpthread-2.19.so   [.] pthread_spin_trylock                                   
+   1.68%  mongod  mongod               [.] operator delete(void*)                                 
+   1.42%  mongod  [vdso]               [.] 0x0000000000000f08                                     
+   1.04%  mongod  [kernel.kallsyms]    [k] _raw_spin_lock_irqsave                                 
+   1.02%  mongod  mongod               [.] mongo::BSONElement::size() const

Sometimes (on new version) I get __log_wrlsn_server traffic, sometimes I don't

-   5.23%  mongod  [kernel.kallsyms]   [k] update_blocked_averages                                 
   - update_blocked_averages                                                                       
      - 97.55% idle_balance                                                                        
           __schedule                                                                              
         - schedule                                                                                
            + 51.64% schedule_hrtimeout_range_clock                                                
            - 48.36% futex_wait_queue_me                                                           
                 futex_wait                                                                        
                 do_futex                                                                          
                 sys_futex                                                                         
                 system_call_fastpath                                                              
               - pthread_cond_timedwait@@GLIBC_2.3.2                                               
                  + 94.81% __log_wrlsn_server                                                      
                  + 5.19% __log_server                                                             
      + 2.45% __schedule                                                                           
+   4.67%  mongod  mongod              [.] __wt_log_wrlsn                                          
+   3.83%  mongod  [kernel.kallsyms]   [k] update_cfs_rq_blocked_load                              
+   3.78%  mongod  libc-2.19.so        [.] __clock_gettime                                         
+   3.44%  mongod  [kernel.kallsyms]   [k] futex_wait_queue_me                                     
+   3.44%  mongod  [kernel.kallsyms]   [k] futex_wait_setup                                        
+   3.03%  mongod  [kernel.kallsyms]   [k] update_curr                                             
+   2.61%  mongod  [vdso]              [.] 0x0000000000000802   

Sometimes I get this too (FTDC)

 
-   4.90%  mongod  mongod              [.] mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) cons
   - mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) const                                     
   - mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) const                                     
      - 78.34% mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) const                           
         - 56.87% mongo::CmdServerStatus::run(mongo::OperationContext*, std::string const&, mongo::
              mongo::(anonymous namespace)::FTDCSimpleInternalCommandCollector::collect(mongo::Oper
              mongo::FTDCCollectorCollection::collect(mongo::Client*)                              
              mongo::FTDCController::doLoop()                                                      
              execute_native_thread_routine                                                        
         + 43.13% mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) const                        
      + 21.66% mongo::CmdServerStatus::run(mongo::OperationContext*, std::string const&, mongo::BSO

Comment by David Daly [ 06/Oct/15 ]

I did some profiling comparing between 3.1.0 and a recent master. The largest differences I was able to pull out were malloc related.

  • new
  • delete
  • tcmalloc
Generated at Thu Feb 08 03:55:16 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.