<SHAMELESS_PLUG>
My previous article about initial sync progress monitoring got some attention, and as I’m a Technical Services Engineer at MongoDB, I got to provide direct feedback during the design phase of SERVER-47863: Initial Sync Progress Metrics!.

You can be a part of this team and this awesome organization too! Head on over to MongoDB’s careers page to see what’s available, or feel free to ping me on LinkedIn if you have any questions.
</SHAMELESS_PLUG>

The goal of this post is to showcase a change that is coming in MongoDB 5.0 that will significantly improve the feedback loop regarding initial sync progress monitoring. With SERVER-47863 being completed, the results of the db.adminCommand({ replSetGetStatus: 1, initialSync: 1 }) now include additional metrics that can be used to help determine how long (approximately) an initial sync will be running for.

Though this feature is planned to be backported to all supported versions (4.4, 4.2, 4.0, 3.6), at the time of writing backports had not been completed.

If you want to test this yourself, my setup was as follows:

1) Build the server using the install-mongod SCons target. My version of the server was mongod-4.9.0-alpha-596-g4437864 as a result.
2) Start up a single node replicaset as follows:

1

mkdir data && build/install/bin/mongod --dbpath data --bind_ip_all --replSet rs0 --logpath data/mongod.log

3) Using the mongo shell, initialize the replica set:

1

mongo --eval 'rs.initiate()'

4) Seed the test.data namespace using the following mgeneratejs and mongoimport:

1

curl -s https://gist.githubusercontent.com/alexbevi/955c6675337107e16d637233f865b1e3/raw/0c48178e9c570b7594f207559744f07ecf87ac28/template.json | mgeneratejs -n 1000000 | mongoimport --collection data --numInsertionWorkers 4

5) Start another mongod and add it to the replica set

1
2

mkdir data2 && build/install/bin/mongod --port 27018 --dbpath data2 --bind_ip_all --replSet rs0 --logpath data2/mongod.log
mongo --eval 'rs.add("localhost:27018")'

The above steps will build the mongod and start up 2 nodes in a replica set with one in a STARTUP2 (initial sync) state.

By connecting to the secondary node directly and issuing a replSetGetStatus command we can now review the progress of the copy. Note that this will need to be done while the initial sync is in progress; once the node exits the STARTUP2 state and enters a SECONDARY state, the initialSyncStatus details will be unavailable.

For example:

1

db.adminCommand({ replSetGetStatus: 1, initialSync: 1 });

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39

{
  "set" : "rs0",
  ...
  "initialSyncStatus" : {
      "failedInitialSyncAttempts" : 0,
      "maxFailedInitialSyncAttempts" : 10,
      "initialSyncStart" : ISODate("2020-11-20T15:47:09.136Z"),
      "totalInitialSyncElapsedMillis" : 14925,               <-----------
      "initialSyncAttempts" : [ ],
      "approxTotalDataSize" : 311911892,                     <-----------
      "approxTotalBytesCopied" : 16811036,                   <-----------
      "remainingInitialSyncEstimatedMillis" : 0,             <-----------
      "appliedOps" : 0,
      "initialSyncOplogStart" : Timestamp(1605887228, 1),
      "totalTimeUnreachableMillis" : NumberLong(0),
      "databases" : {
          "databasesToClone" : 1,                              <-----------
          "databasesCloned" : 2,
          ...
          },
          "test" : {
              "collections" : 1,
              "clonedCollections" : 0,
              "start" : ISODate("2020-11-20T15:47:13.968Z"),
              "test.data" : {
                  "documentsToCopy" : 250000,
                  "documentsCopied" : 13481,
                  "indexes" : 1,
                  "fetchedBatches" : 2,
                  "bytesToCopy" : 311911663,                       <-----------
                  "approxBytesCopied" : 16810807,                  <-----------
                  "start" : ISODate("2020-11-20T15:47:13.968Z"),
                  "receivedBatches" : 2
              }
          }
      }
  },
  ...
}

The command output has been truncated to focus in on the new fields added to the initialSyncStatus document. The new metrics details are as follows:

Warning - Not for Production Use

MongoDB’s source code is available (through an SSPL license) and the Core Server project in MongoDB’s JIRA is publicly accessible, which is where I found this information.
Until officially announced as stable/official the methods described herein should not be considered as “production ready”. This post is for informational purposes and though at the time of writing it I am a MongoDB Inc. employee this should not be considered an official communication.

Introduction

A feature that has long been requested since Change Streams were introduced in MongoDB 3.6 is the ability to support returning the n-1 state (or pre-image) of a document when it is changed.

In SERVER-36941: Option to provide “before image” with change streams this request is captured, but at the time of writing this ticket is still in an Open state which would imply no progress has been made.

Interestingly enough, there actually has been some progress due to efforts surrounding the support of Realm Sync, namely in the following tickets:

• SERVER-45806: Record pre-images on updates and deletes when recordPreImage is enabled
• SERVER-45807: Add change stream stage to fetch pre-image for update/replace/delete events

Pre-Image Support

“Support” for this feature is only available in MongoDB 4.4+, so first we must ensure we are running a compatible version.

Next, as change streams are only supported in replica sets or sharded clusters our cluster cannot be a standalone instance.

Before a pre-image can be returned in a change stream support for the feature must be enabled at the collection level.

Create a New Collection with Pre-Image Support

Working in Technical Services at MongoDB I find that time and again customers need assistance understanding why the operations they’ve created indexes for may not be performing optimally. When providing supplementary documentation, the go-to article is “Optimizing MongoDB Compound Indexes” by MongoDB’s A. Jesse Jiryu Davis, however we do not have a formal public reference yet (though DOCS-11790 exists to track this effort).

I’ve presented this topic now at MongoDB.local Toronto 2019 (in “Tips and Tricks for Effective Indexing”) and at MongoDB World 2019 (in “The Sights (and Smells) of a Bad Query”). My colleague Chris Harris has also covered this topic at MongoDB World 2019 (in “Tips and Tricks++ for Querying and Indexing MongoDB”) and again at the MongoDB.local Houston 2019, for which a video is available.

Though we have Jesse’s excellent (and still applicable and valid) article from 2012, I wanted to take this opportunity to collect some thoughts on this topic based on his work and previous presentations.

The ESR “Rule”

The ordering of index keys in a compound index is critically important, and the ESR “Rule” can be used as a rule of thumb to identify the optimal order in most cases.

The reason we are putting “Rule” in quotations is because, though the guidance is applicable in most cases, there are exceptions to be aware of. These exceptions are covered in greater detail in my in “Tips and Tricks for Effective Indexing” presentation.

The “Rules”

MongoDB Stitch is a great way to build apps quickly with your data that’s already managed by MongoDB Atlas. Though these services empower you to focus on development without having to worry about infrastructure, being a managed service there are occasionally limitations imposed by the vendor.

This article summarizes why this limit exists, as well as how to adapt your MongoDB Stitch Functions to work around it.

A common question when it comes to MongoDB and the (default) storage engine (WiredTiger) is “Why is it after I removed a bunch of documents my free space didn’t increase”?

The WiredTiger storage engine maintains lists of empty records in data files as it deletes documents. This space can be reused by WiredTiger, but will not be returned to the operating system unless under very specific circumstances.

The amount of empty space available for reuse by WiredTiger is reflected in the output of db.collection.stats() under the heading wiredTiger.block-manager.file bytes available for reuse.

To allow the WiredTiger storage engine to release this empty space to the operating system, you can de-fragment your data file. This can be achieved using the compact command.

As the db.collection.stats() command must be run one collection at a time I’ve written the following script to enhance this functionality as follows:

• scan all namespaces (databases + collections)
• include index space details
• support for sharded collections
• output to CSV

Sometimes our replica set members fall off the oplog and the node needs to be resynced. When this happens, an Initial Sync is required, which does the following:

1. Clones all databases except the local database. To clone, the mongod scans every collection in each source database and inserts all data into its own copies of these collections.
2. Applies all changes to the data set. Using the oplog from the source, the mongod updates its data set to reflect the current state of the replica set.

When the initial sync finishes, the member transitions from STARTUP2 to SECONDARY.

Some common questions when performing an initial sync of a Replica Set Member are:

• How do I know if the sync is progressing?
• How long will this take to complete?

Full Time Diagnostic Data Capture (FTDC) was introduced in MongoDB 3.2 (via SERVER-19585), to incrementally collect the results of certain diagnostic commands to assist MongoDB support with troubleshooting issues.

On log rotation or startup, a mongod or mongos will collect and log:

• getCmdLineOpts: db.adminCommand({getCmdLineOpts: true})
• buildInfo: db.adminCommand({buildInfo: true})
• hostInfo: db.adminCommand({hostInfo: true})

As configured by diagnosticDataCollectionPeriodMillis and defaulting to every 1 second, FTDC will collect the output of the following commands:

• serverStatus: db.serverStatus({tcmalloc: true})
• replSetGetStatus: rs.status()
• collStats for the local.oplog.rs collection (mongod only)
• connPoolStats (mongos only)

When FTDC is enabled (per diagnosticDataCollectionEnabled), the metrics.xxxxxxx files will be stored in diagnosticDataCollectionDirectoryPath which by default is the diagnostic.data directory within the systemLog.path.

With SERVER-21818 (introduced in MongoDB 3.2.13) and SERVER-31400 (introduced in MongoDB 3.4.16) the diagnostic data capture scope was broadened to not only include internal diagnostic commands but system metrics as well. Depending on the host operating system, the diagnostic data may include one or more of the following statistics:

• CPU utilization (ex: /proc/stat)
• Memory utilization (ex: /proc/meminfo)
• Disk utilization related to performance (ex: */sys/block/\*/stat*)
• Network performance statistics (/proc/net/netstat)

The metrics.xxxxxxx files in the diagnostic.data directory contain only statistics about the performance of the system and the database. They are stored in a compressed format, and are not human-readable.

Just a quick note regarding privacy, regardless of the version, the data in diagnostic.data never contains:

• Samples of queries, query predicates, or query results
• Data sampled from any end-user collection or index
• System or MongoDB user credentials or security certificates

FTDC data contains certain host machine information such as hostnames, operating system information, and the options or settings used to start the mongod or mongos. This information may be considered protected or confidential by some organizations or regulatory bodies, but is not typically considered to be Personally Identifiable Information (PII).

If you want to have a closer look at the diagnostic data collection process, you can inspect the FTDC code.

FTDC Structure

I recently found myself troubleshooting another MongoDB startup issue due to potential corruption within a WiredTiger file. As I have previously covered this topic (see “Recovering a WiredTiger collection from a corrupt MongoDB installation”), I wanted to share the diagnostic and troubleshooting journey in case it helps anyone who experiences this issue in the future.

To ensure I could troubleshoot this issue in isolation, I first collected a backup of the necessary files from the affected installation as follows:

1

tar -czvf metadata.tar.gz --exclude=WiredTigerStat* WiredTiger* _mdb_catalog.wt sizeStorer.wt

Once I had this backup I extracted it to a new location, then using m to select the versions of MongoDB to use tried to startup a standalone instance to see if I could reproduce the issue:

1
2
3
4
5
6
7

mkdir -p /tmp/repro
cd /tmp/repro
# move archive from earlier to the new directory first
tar xvf metadata.tar.gz
# This is the version of MongoDB reported to be crashing
m 3.4.18
mongod --dbpath .

Once the mongod started, we were able to see the failure and the process aborts (clipped log sample below).

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

2020-01-23T03:58:19.828-0500 I CONTROL  [initandlisten] db version v3.4.18
2020-01-23T03:58:19.828-0500 I CONTROL  [initandlisten] git version: 4410706bef6463369ea2f42399e9843903b31923
...
2020-01-23T03:58:20.187-0500 I -        [initandlisten] Invariant failure !_featureTracker src/mongo/db/storage/kv/kv_catalog.cpp 305
2020-01-23T03:58:20.187-0500 I -        [initandlisten]

***aborting after invariant() failure

2020-01-23T03:58:20.198-0500 F -        [initandlisten] Got signal: 6 (Aborted).
...
 mongod(_ZN5mongo15printStackTraceERSo+0x41) [0x55bb45c92111]
 mongod(+0x153F329) [0x55bb45c91329]
 mongod(+0x153F80D) [0x55bb45c9180d]
 libpthread.so.0(+0x12890) [0x7f5b7bee5890]
 libc.so.6(gsignal+0xC7) [0x7f5b7bb20e97]
 libc.so.6(abort+0x141) [0x7f5b7bb22801]
 mongod(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0x0) [0x55bb44f5b234]
 mongod(_ZN5mongo9KVCatalog4initEPNS_16OperationContextE+0x568) [0x55bb458db5e8]
 mongod(_ZN5mongo15KVStorageEngineC1EPNS_8KVEngineERKNS_22KVStorageEngineOptionsE+0x807) [0x55bb458e79f7]
 mongod(+0x124DFFA) [0x55bb4599fffa]
 mongod(_ZN5mongo20ServiceContextMongoD29initializeGlobalStorageEngineEv+0x697) [0x55bb45891627]
 mongod(+0x7F62AC) [0x55bb44f482ac]
 mongod(main+0x96B) [0x55bb44f66a6b]
 libc.so.6(__libc_start_main+0xE7) [0x7f5b7bb03b97]
 mongod(+0x86FFB1) [0x55bb44fc1fb1]
-----  END BACKTRACE  -----
Aborted (core dumped)

The goal of this post is to provide a first hand account of what it means to be a Technical Services Engineer at MongoDB, as well as what the journey getting to this point has looked like for me.

WHO AM I?

I have been working in Application Development and Software Engineering for nearly two decades. I started off writing desktop applications in QuickBASIC and Turbo Pascal, then eventually in VB6, VB.NET, C++ and C#. When it was time to shift focus to web development I started off with HTML/JS/CSS (as we all do :P), then in Flash/AS3, Flex, Python, Ruby/Rails and Node.js.

I have been writing software since I was a kid, starting with some automation tools for my mom’s business. I then moved on to building tools to help me cheat at various games I was playing at the time, and eventually got more into emulator programming and reverse engineering. I guess you could say I’ve always loved solving problems programmatically, and especially enjoyed identifying opportunities for automation and custom tooling.

This led me down an informal DevOps track, as I was finding there was a need for optimization in the infrastructure layers that my applications were deployed to. This led me deeper into Linux internals, system administration and network operations.

While I was gaining these new skill-sets my primary focus was always on application development and delivery. Before coming to MongoDB I was working as a Development Lead / System Architect, but I found that my focus was always being drawn back to solving performance challenges at the infrastructure level.