10 Key Performance Indicators

MongoDB Stockholm 2012
Christian Kvalhem, Software Engineer, 10gen

That's right: you too can learn to read the omens and ensure that your MongoDB deployment stays in tip-top shape. We'll look at memory usage, file sizes, flushing, journaling, and all the special incantations that reveal MongoDB's true inner self. By the end of the talk, you'll have ten concrete steps you can take to address performance degradation before it happens. You'll also get a few tips on application design and pointers on remote monitoring.

Transcript

1. Key Performance Indicators Christian Kvalheim 10gen Tuesday, April 24, 12
2. Agenda •The Players •Tools •Performance Indicators Tuesday, April 24, 12
3. Speed MongoDB is a high-performance database, but how do I know that I’m getting the best performance Tuesday, April 24, 12
4. Players • Memory – Memory mapped filed, OS memory handling • Locks – Global write lock, going db level in 2.2 • Disk IO – IOPS, Latency • Network – Bandwidth Tuesday, April 24, 12
5. TOOLS Tuesday, April 24, 12
6. mongostat Tuesday, April 24, 12
7. The stats • Flushes • Mapped memory • Virtual memory size (Vsize) • Resident memory • Faults • Locked percentage Tuesday, April 24, 12
8. db.serverStatus >  db.serverStatus(); {     "host"  :  “MacBook.local",                "version"  :  "2.0.1",                "process"  :  "mongod",                "uptime"  :  619052, //  Lots  more  stats... } Tuesday, April 24, 12
9. Profiler >  db.setProfilingLevel(2); {  "was"  :  0,  "slowms"  :  100,  "ok"  :  1  } Tuesday, April 24, 12
10. Profiling • 3 levels – off – slower than x ms – all • Capped collection, 1MB default • Some performance overhead but minimal Tuesday, April 24, 12
11. Profiler >  db.system.profile.find() {                "ts"  :  ISODate("2011-­‐09-­‐30T02:07:11.370Z"),                "op"  :  "query",                "ns"  :  "docs.spreadsheets",                "nscanned"  :  20001,                "nreturned"  :  1,                "responseLength"  :  241,                "millis"  :  1407,                "client"  :  "127.0.0.1",                "user"  :  "" } Tuesday, April 24, 12
12. Monitoring Service • MMS: 10gen.com/try-mms • Nagios • Munin Tuesday, April 24, 12
13. INDICATORS Tuesday, April 24, 12
14. Slow Operations Sun  May  22  19:01:47  [conn10] query  docs.spreadsheets  ntoreturn:100  reslen: 510436 nscanned:19976  {  username:    “Hackett,  Bernie”} nreturned:100      147ms Tuesday, April 24, 12
15. Replication lag • replication lag is difference in time between the primaries last operation and the last operation the secondary committed Tuesday, April 24, 12
16. PRIMARY>  rs.status() {                "set"  :  "replSet",                "date"  :  ISODate("2011-­‐09-­‐30T02:28:21Z"),                "myState"  :  1,                "members"  :  [                                {                                                "_id"  :  0,                                                "name"  :  "MacBook.local:30001",                                                "health"  :  1,                                                "state"  :  1,                                                "stateStr"  :  "PRIMARY",                                                "optime"  :  {                                                                "t"  :  1317349400000,                                                                "i"  :  1                                                },                                                "optimeDate"  :  ISODate("2011-­‐09-­‐30T02:23:20Z"),                                                "self"  :  true                                }, {                                                "_id"  :  1,                                                "name"  :  "MacBook.local:30002",                                                "health"  :  1,                                                "state"  :  2,                                                "stateStr"  :  "SECONDARY",                                                "uptime"  :  302,                                                "optime"  :  {                                                                "t"  :  1317349400000,                                                                "i"  :  1                                                },                                                "optimeDate"  :  ISODate("2011-­‐09-­‐28T10:17:47Z"),                                                "lastHeartbeat"  :  ISODate("2011-­‐09-­‐30T02:28:19Z"), Tuesday, April 24, 12
17. Virtual memory Tuesday, April 24, 12
18. Resident Memory >  db.serverStatus().mem {                "bits"  :  64,    //  Need  64,  not  32                "resident"  :  7151,  //  Physical  memory                "virtual"  :  14248,  //  Files  +  heap                "mapped"  :  6942  //  Data  files } Tuesday, April 24, 12
19. Resident Memory >  db.stats() {                "db"  :  "docs",                "collections"  :  3,                "objects"  :  805543,                "avgObjSize"  :  5107.312096312674,                "dataSize"  :  4114159508,  //  ~4GB                "storageSize"  :  4282908160,  //  ~4GB                "numExtents"  :  33,                "indexes"  :  3,                "indexSize"  :  126984192,    //  ~126MB                "fileSize"  :  8519680000,  //  ~8.5GB                "ok"  :  1 } Tuesday, April 24, 12
20. Optimal Resident Memory     indexSize  +  storageSize  <=  RAM Tuesday, April 24, 12
21. Page Faults >  db.serverStatus().extra_info {     "note"  :  "fields  vary  by  platform",   “heap_usage_bytes”  :  210656,   “page_faults”  :  2381 } Tuesday, April 24, 12
22. Page Faults • The number of times the OS needs to read and write a new page of data into memory • Very high number indicates thrashing – OS spends more time reading/writing data to disk than doing work Tuesday, April 24, 12
23. Write Lock Percentage >  db.serverStatus().globalLock {                "totalTime"  :  2809217799,                "lockTime"  :  13416655,                "ratio"  :  0.004775939766854653, } Tuesday, April 24, 12
24. Write lock percentage • the total amount of time the server spent in global write lock during the last sample period (one second) Tuesday, April 24, 12
25. Concurrency • One writer or many readers • Global RW Lock • Yields on long-running ops and if we’re likely to go to disk. Tuesday, April 24, 12
26. High Lock Percentage? You’re Probably Paging! Tuesday, April 24, 12
27. Queues • Tells you how many connections are waiting for reading or writing Tuesday, April 24, 12
28. >  db.serverStatus().globalLock {                "totalTime"  :  2809217799,                "lockTime"  :  13416655,                "ratio"  :  0.004775939766854653, "currentQueue"  :  {                                "total"  :  1,                                "readers"  :  1,                                "writers"  :  0                },                "activeClients"  :  {                                "total"  :  2,                                "readers"  :  1,                                "writers"  :  1                } Tuesday, April 24, 12
29. Current Op • db.currentOp() let’s you see the current operation executing • db.killOp(id) lets you kill a blocking long running operation Tuesday, April 24, 12
30. >  db.currentOp() {                "inprog"  :  [                                {                                                "opid"  :  6996,                                                "active"  :  true,                                                "lockType"  :  "read",                                                "waitingForLock"  :  true,                                                "secs_running"  :  1,                                                "op"  :  "query",                                                "ns"  :  "docs.spreadsheets",                                                "query"  :  {                                                            “username”  :    “Hackett,  Bernie”                                                },                                                "client"  :  "10.71.194.111:51015",                                                "desc"  :  "conn",                                                "threadId"  :  "0x152693000",                                                "numYields"  :  0                                }, Tuesday, April 24, 12
31. Background Flushing • Tells you how often the data is written to disk • A high value might indicate IO performance issue – Might happen with network attached storage • Lower the time for flushing to disk to write less data more often Tuesday, April 24, 12
32. Background Flushing >  db.serverStatus().backgroundFlushing {                "flushes"  :  5634,                "total_ms"  :  83556,                "average_ms"  :  14.830670926517572,                "last_ms"  :  4,                "last_finished"  :   ISODate("2011-­‐09-­‐30T03:30:59.052Z") } Tuesday, April 24, 12
33. Disk Considerations • Raid • SSD • SAN? Tuesday, April 24, 12
34. Connections >  db.serverStatus().connections {  "current"  :  7,  "available"  :  19993  } Tuesday, April 24, 12
35. Connections • Each connection takes up heap space • The more connections the more context switching for the CPU • Clean up your connections after use Tuesday, April 24, 12
36. Network Speed >  db.serverStatus().network {  "bytesIn"  :  877291,  "bytesOut"  :  846300,   "numRequests"  :  9186  } Tuesday, April 24, 12
37. Network Speed • Application might saturate connection leaving little replication bandwidth • Slow interconnect between app and db servers might limit your performance – Measure available bandwidth between servers, scp can be used for a sanity check of this. • If a problem bond connections, get 10Gbp cards. • Control the write speed doing getLastError every once in a while in the app Tuesday, April 24, 12
38. Fragmentation db.spreadsheets.stats() {                "ns"  :  "docs.spreadhseets",                "size"  :  8200046932,                                      //  ~8GB                "storageSize"  :  11807223808,            //  ~11GB                "paddingFactor"  :  1.4302,                "totalIndexSize"  :  345964544,            //  ~345MB                "indexSizes"  :  {                        "_id_"  :  66772992,    “username_1_filename_1”  :  146079744,    “username_1_updated_at_1”  :  133111808                },                "ok"  :  1 } Tuesday, April 24, 12
39. Fragmentation • Padding factor is the extra space MongoDB allocates for each document growth when saving documents – doc is 1000 bytes – padding factor 1.5 – total memory allocated 1500 bytes for doc Tuesday, April 24, 12
40. Fragmentation Padding factor >2 is the Horror Number Tuesday, April 24, 12
41. storageSize / size > 2 • Might not be reclaiming free space fast enough • Padding factor might not be correctly calibrated db.spreadsheets.runCommand(“compact”) Tuesday, April 24, 12
42. paddingFactor > 2 • You might have the wrong data model • You might be growing documents too much – embedded documents • Should review Schema Design Tuesday, April 24, 12
43. Summary • Ensuring dataset in memory is important – Avoid page faults • Find slow queries – Minimize time spent in write lock • Make sure you don’t flood Mongo with connections • Ensure you padding factor is < 2 – Check you schema design Tuesday, April 24, 12
44. We’re Hiring Engineers, Sales, Evangelist, Marketing, Support, Developers @mongodb_jobs http://linkd.in/joinmongo Tuesday, April 24, 12
45. We’re Always Around For Conferences, Appearances and Meetups 10gen.com/events @mongodb h2p://bit.ly/mongo8   Tuesday, April 24, 12