-
Type:
Improvement
-
Resolution: Fixed
-
Priority:
Major - P3
-
Affects Version/s: None
-
Component/s: None
-
Server Programmability
-
Minor Change
-
Repl 2025-03-31, Programmability 2025-04-14
-
200
-
None
-
3
-
None
-
None
-
None
-
None
-
None
-
None
As part of CLOUDP-300154, to improve backup restore observability, the Atlas Backups team will need performance statistics on mongodb startup/shutdown.
The current plan to retrieve these statistics is to parse the mongodb logs for log IDs:
8423403 and 8423404. To make parsing easier, we are requesting some formatting changes to these logs.
The changes we'd like are:
- change the keys to camel case
- append the keys with the unit of measurement
- make the values numerical
Mongod startup complete 8423403
Before:
{
"t": {
"$date": "2025-02-11T17:02:12.529+00:00"
},
"s": "I",
"c": "CONTROL",
"id": 8423403,
"ctx": "initandlisten",
"msg": "mongod startup complete",
"attr": {
"Summary of time elapsed": {
"Startup from clean shutdown?": true,
"Statistics": {
"Transport layer setup": "1 ms",
"Run initial syncer crash recovery": "0 ms",
"Create storage engine lock file in the data directory": "0 ms",
"Get metadata describing storage engine": "0 ms",
"Validate options in metadata against current startup options": "0 ms",
"Create storage engine": "2768 ms",
"Write current PID to file": "10 ms",
"Initialize FCV before rebuilding indexes": "15 ms",
"Drop abandoned idents and get back indexes that need to be rebuilt or builds that need to be restarted": "5 ms",
"Rebuild indexes for collections": "0 ms",
"Build user and roles graph": "0 ms",
"Verify indexes for admin.system.users collection": "0 ms",
"Verify indexes for admin.system.roles collection": "0 ms",
"Set up the background thread pool responsible for waiting for opTimes to be majority committed": "0 ms",
"Initialize information needed to make a mongod instance shard aware": "0 ms",
"Start up cluster time keys manager with a local/direct keys client": "0 ms",
"Start up the replication coordinator": "125 ms",
"Create an oplog view for tenant migrations": "0 ms",
"Start transport layer": "0 ms",
"_initAndListen total elapsed time": "3566 ms"
}
}
}
}
After
{
"t": {
"$date": "2025-02-11T17:02:12.529+00:00"
},
"s": "I",
"c": "CONTROL",
"id": 8423403,
"ctx": "initandlisten",
"msg": "mongod startup complete",
"attr": {
"Summary of time elapsed": {
"Startup from clean shutdown?": true,
"Statistics": {
"transportLayerSetupMilliseconds": 1,
"runInitialSyncerCrashRecoveryMilliseconds": 0,
"createStorageEngineLockFileInTheDataDirectoryMilliseconds": 0,
"getMetadataDescribingStorageEngineMilliseconds": 0,
"validateOptionsInMetadataAgainstCurrentStartupOptionsMilliseconds": 0,
"createStorageEngineMilliseconds": 2768,
"writeCurrentPidToFileMilliseconds": 10,
"initializeFcvBeforeRebuildingIndexesMilliseconds": 15,
"dropAbandonedIdentsAndGetBackIndexesThatNeedToBeRebuiltOrBuildsThatNeedToBeRestartedMilliseconds": 5,
"rebuildIndexesForCollectionsMilliseconds": 0,
"buildUserAndRolesGraphMilliseconds": 0,
"verifyIndexesForAdminSystemUsersCollectionMilliseconds": 0,
"verifyIndexesForAdminSystemRolesCollectionMilliseconds": 0,
"setUpTheBackgroundThreadPoolResponsibleForWaitingForOpTimesToBeMajorityCommittedMilliseconds": 0,
"initializeInformationNeededToMakeAMongodInstanceShardAwareMilliseconds": 0,
"startUpClusterTimeKeysManagerWithALocalDirectKeysClientMilliseconds": 0,
"startUpTheReplicationCoordinatorMilliseconds": 125,
"createAnOplogViewForTenantMigrationsMilliseconds": 0,
"startTransportLayerMilliseconds": 0,
"_initAndListenTotalElapsedTimeMilliseconds": 3566
}
}
}
}
Mongodb shutdown complete 8423404
Before:
{
"t": {
"$date": "2025-02-27T20:20:30.356+00:00"
},
"s": "I",
"c": "CONTROL",
"id": 8423404,
"ctx": "thread46",
"msg": "mongod shutdown complete",
"attr": {
"Summary of time elapsed": {
"Statistics": {
"Time spent in quiesce mode": "0 ms",
"Shut down FLE Crud subsystem": "0 ms",
"Shut down MirrorMaestro": "0 ms",
"Shut down WaitForMajorityService": "0 ms",
"Shut down the logical session cache": "0 ms",
"Shut down the global connection pool": "0 ms",
"Shut down the flow control ticket holder": "0 ms",
"Shut down the thread that aborts expired transactions": "0 ms",
"Kill all operations for shutdown": "0 ms",
"Shut down all tenant migration access blockers on global shutdown": "16 ms",
"Shut down all open transactions": "0 ms",
"Acquire the RSTL for shutdown": "0 ms",
"Shut down the IndexBuildsCoordinator and wait for index builds to finish": "0 ms",
"Shut down the replica set monitor": "0 ms",
"Shut down the migration util executor": "0 ms",
"Shut down the transport layer": "0 ms",
"Shut down the health log": "0 ms",
"Shut down the TTL monitor": "0 ms",
"Shut down expired pre-images and documents removers": "0 ms",
"Shut down the storage engine": "244 ms",
"Wait for the oplog cap maintainer thread to stop": "0 ms",
"Shut down full-time data capture": "10 ms",
"Shut down online certificate status protocol manager": "0 ms",
"shutdownTask total elapsed time": "276 ms"
}
}
}
}
After:
{
"t": {
"$date": "2025-02-27T20:20:30.356+00:00"
},
"s": "I",
"c": "CONTROL",
"id": 8423404,
"ctx": "thread46",
"msg": "mongod shutdown complete",
"attr": {
"Summary of time elapsed": {
"Statistics": {
"timeSpentInQuiesceModeMilliseconds": 0,
"shutDownFleCrudSubsystemMilliseconds": 0,
"shutDownMirrorMaestroMilliseconds": 0,
"shutDownWaitForMajorityServiceMilliseconds": 0,
"shutDownTheLogicalSessionCacheMilliseconds": 0,
"shutDownTheGlobalConnectionPoolMilliseconds": 0,
"shutDownTheFlowControlTicketHolderMilliseconds": 0,
"shutDownTheThreadThatAbortsExpiredTransactionsMilliseconds": 0,
"killAllOperationsForShutdownMilliseconds": 0,
"shutDownAllTenantMigrationAccessBlockersOnGlobalShutdownMilliseconds": 16,
"shutDownAllOpenTransactionsMilliseconds": 0,
"acquireTheRstlForShutdownMilliseconds": 0,
"shutDownTheIndexBuildsCoordinatorAndWaitForIndexBuildsToFinishMilliseconds": 0,
"shutDownTheReplicaSetMonitorMilliseconds": 0,
"shutDownTheMigrationUtilExecutorMilliseconds": 0,
"shutDownTheTransportLayerMilliseconds": 0,
"shutDownTheHealthLogMilliseconds": 0,
"shutDownTheTtlMonitorMilliseconds": 0,
"shutDownExpiredPreImagesAndDocumentsRemoversMilliseconds": 0,
"shutDownTheStorageEngineMilliseconds": 244,
"waitForTheOplogCapMaintainerThreadToStopMilliseconds": 0,
"shutDownFullTimeDataCaptureMilliseconds": 10,
"shutDownOnlineCertificateStatusProtocolManagerMilliseconds": 0,
"shutdownTaskTotalElapsedTimeMilliseconds": 276
}
}
}
}