[SERVER-1815] instrument more detailed response time items in profiler Created: 20/Sep/10  Updated: 12/Jul/16  Resolved: 08/Aug/11

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

Type: New Feature Priority: Major - P3
Reporter: Kenny Gorman Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Related
related to SERVER-3546 profiler: track time in disk io Closed
Participants:

 Description   

The profiler is awesome. But we need more data about the details of where the time went so we can tune individual components and so we can construct a call graph. Splitting the "Millis" component out by type would be an excellent first step. I realize it may be hard with MM files, but perhaps just treat all calls to MM files as I/O for now. We would not be able to see physical vs logical I/O, but ok, thats a compromise. But understanding I/O vs other items would be excellent! Especially if a write was waiting to get time on the writer process. I would love something like:

read:
{ "ts" : "Mon Sep 20 2010...", "info" : "query test.foo reslen:174 nscanned:4 \nquery: {} nreturned:4 bytes:158", "millis" :

{"IO":4,"Lock":1,"Net":1,"Total":6}

, }

write:
{ "ts" : "Mon Sep 20 2010...", "info" : "insert test.foo", "millis" :

{"IO":1,"Queue":4,"Net":1,"Fsync":1,"Total":7 }

I think the various types that makes sense are:

  • Network Time
  • I/O Time (faults)
  • Queue Time (waiting for writer process for instance)
  • Connection Time
  • Lock Time
  • CPU Time
  • Fsync Time
  • GetLastError() Time

The idea of DB profiling is not new. The Oracle world as a great deal of expertise in this area, and it's one of it's great strengths. If you are not already familar here is a paper by Cary Milsap (who IMHO is the master of all things profiling in Oracle):
http://www.scribd.com/doc/16884539/Millsap-Profiling-Oracle-How-It-Works



 Comments   
Comment by auto [ 08/Aug/11 ]

Author:

{u'login': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: cleaning new profiler data SERVER-1815
Branch: master
https://github.com/mongodb/mongo/commit/3a52f00ede5a8c2507cf3f7bd345c204dc1acf61

Comment by Eliot Horowitz (Inactive) [ 08/Aug/11 ]

The profiler output has changed and there are more things now, but some are still missing

Comment by Kenny Gorman [ 25/Feb/11 ]

Can you schedule this sooner? Like 1.8? . Pretty please?

Comment by Eliot Horowitz (Inactive) [ 21/Sep/10 ]

Some of these make sense - others would be harder.
For many queries - doing the timing, etc.. is actually actually a high percentage - so need to be careful we don't hurt performance doing this.
With memory mapped files this is very expensive. You can check if a page is loaded - but it would slow things down unacceptably.
So need to think through all the details.

Comment by Kenny Gorman [ 20/Sep/10 ]

Oh, and another little data format tweak to make map reducing output easier:

{ "ts" : "Mon Sep 20 2010 11:55:52 GMT-0700 (PDT)",
"type":"query",
"db":"test",
"collection":"foo",
"nscanned":4,
"reslen":174,
"nreturned":4,
"bytes":158,
"millis":

{......}

}

Generated at Thu Feb 08 02:58:08 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.