MongoDB3.4 版本新节点同步的一点惊喜

一个日志库数据量过大，以前3.2 版本的MongoDB oplogsize=50G  也没法初始化新节点。
在把版本升级到3.4,磁盘选择高效云盘后。再做新节点初始化数据同步。
时间已从以前的3天多，到现在的15小时左右了。
主是节省的时间是在索引建立这块。数据同步时，索引也在处理，oplog 数据也在同时同步。


以下是分析日志的一点观点，因只是基于日志，可能有不足之处。看过源码的话，可能会有更深的了解。

----------------------------------------------------------------------------------------------

#新节点同步表数据的同时，好似用了另外一个线程，把数据保存在另外一个500M内存空间中，用来建立索引，


2017-02-22T10:08:29.665+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.WebAppInterfaceCall0]      building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2017-02-22T10:09:18.997+0800 I -        [repl writer worker 7]   MongoApiLogs.WebAppInterfaceCall collection clone progress: 1125277/54284989 2% (documents copied)
2017-02-22T11:05:48.188+0800 I -        [conn143] end connection 127.0.0.1:51202 (34 connections now open)
2017-02-22T11:05:48.235+0800 I -        [repl writer worker 15]   MongoApiLogs.WebAppInterfaceCall collection clone progress: 52120797/54284989 96% (documents copied)
2017-02-22T11:07:26.721+0800 I -        [repl writer worker 15]   MongoApiLogs.WebAppInterfaceCall collection clone progress: 53709792/54284989 98% (documents copied)


2017-02-22T11:08:26.000+0800 I -        [InitialSyncInserters-MongoApiLogs.WebAppInterfaceCall0]   Index: (2/3) BTree Bottom Up Progress: 14989700/54293678 27%
2017-02-22T11:08:36.000+0800 I -        [InitialSyncInserters-MongoApiLogs.WebAppInterfaceCall0]   Index: (2/3) BTree Bottom Up Progress: 27407200/54293678 50%
2017-02-22T11:08:46.000+0800 I -        [InitialSyncInserters-MongoApiLogs.WebAppInterfaceCall0]   Index: (2/3) BTree Bottom Up Progress: 43126600/54293678 79%
2017-02-22T11:08:52.753+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.WebAppInterfaceCall0]      done building bottom layer, going to commit

#在同步数据的同时，也在同步oplog，
比如下面的 ts: { $gte: Timestamp 1487734680000|184 }
确认了一下，就是今天的时间（我从10：00 开始做新节点同步）。
有了这个处理，就不会有象在3.2之间版本的数据同步已过窗口期的问题了（同步完数据后，再同步oplog最旧时间>开始同步时间）。



Log:PRIMARY> new Date(1487734680000)
ISODate("2017-02-22T03:38:00Z")


2017-02-22T11:38:04.051+0800 I REPL     [replication-2] Scheduled new oplog query Fetcher source: 10.160.39.59:28002 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp 1487734680000|184 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000 } query metadata: { $ssm: { $secondaryOk: 1 } } active: 1 timeout: 10000ms inShutdown: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 215025 -- target:10.160.39.59:28002 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp 1487734680000|184 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000 } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms
2017-02-22T11:39:36.883+0800 I -        [repl writer worker 13]   MongoApiLogs.MHttpLogInterfaceCall collection clone progress: 33081015/76709766 43% (documents copied)
2017-02-22T11:40:15.099+0800 I REPL     [replication-3] Restarting oplog query due to error: ExceededTimeLimit: operation exceeded time limit. Last fetched optime (with hash): { ts: Timestamp 1487734810000|65, t: -1 }[-7242886806593697378]. Restarts remaining: 3
2017-02-22T11:40:15.100+0800 I REPL     [replication-3] Scheduled new oplog query Fetcher source: 10.160.39.59:28002 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp 1487734810000|65 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000 } query metadata: { $ssm: { $secondaryOk: 1 } } active: 1 timeout: 10000ms inShutdown: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 220910 -- target:10.160.39.59:28002 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp 1487734810000|65 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000 } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms




2017-02-22T14:09:22.000+0800 I -        [InitialSyncInserters-MongoApiLogs.AppInterfaceCall0]   Index: (2/3) BTree Bottom Up Progress: 46086700/50045224 92%
2017-02-22T14:09:24.443+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.AppInterfaceCall0]      done building bottom layer, going to commit
2017-02-22T14:09:27.942+0800 I REPL     [repl writer worker 14] CollectionCloner::start called, on ns:MongoApiLogs.CMSInterfaceCall
2017-02-22T14:09:27.998+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.CMSInterfaceCall0] build index on: MongoApiLogs.CMSInterfaceCall properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "MongoApiLogs.CMSInterfaceCall" }
2017-02-22T14:09:27.998+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.CMSInterfaceCall0]      building index using bulk method; build may temporarily use up to 500 megabytes of RAM

#下面日志看到表：【MongoApiLogs.OpenApiRequestLog】初始化时建立了索引，后面进行数据同步。（以前是先数据同步，完成后再一个个索引进行建立，）
2017-02-22T14:09:28.297+0800 I REPL     [repl writer worker 1] CollectionCloner::start called, on ns:MongoApiLogs.OpenApiRequestLog
2017-02-22T14:09:28.345+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.OpenApiRequestLog0] build index on: MongoApiLogs.OpenApiRequestLog properties: { v: 1, key: { InterfaceType: 1.0 }, name: "InterfaceType_1", ns: "MongoApiLogs.OpenApiRequestLog" }
2017-02-22T14:09:28.345+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.OpenApiRequestLog0]      building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-02-22T14:09:28.356+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.OpenApiRequestLog0] build index on: MongoApiLogs.OpenApiRequestLog properties: { v: 1, key: { CreateTime: -1.0 }, name: "CreateTime_-1", ns: "MongoApiLogs.OpenApiRequestLog", expireAfterSeconds: 2592000.0 }
2017-02-22T14:09:28.356+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.OpenApiRequestLog0]      building index using bulk method; build may temporarily use up to 250 megabytes of RAM
2017-02-22T14:09:28.363+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.OpenApiRequestLog0] build index on: MongoApiLogs.OpenApiRequestLog properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "MongoApiLogs.OpenApiRequestLog" }
2017-02-22T14:09:28.363+0800 I INDEX    [InitialSyncInserters-MongoApiLogs.OpenApiRequestLog0]      building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2017-02-22T14:10:06.424+0800 I REPL     [replication-4] Restarting oplog query due to error: ExceededTimeLimit: operation exceeded time limit. Last fetched optime (with hash): { ts: Timestamp 1487743800000|3, t: -1 }[684200904940466821]. Restarts remaining: 3
2017-02-22T14:10:06.424+0800 I REPL     [replication-4] Scheduled new oplog query Fetcher source: 10.160.39.59:28002 database: local query: { find: "oplog.rs", filter: { ts: { $gte: Timestamp 1487743800000|3 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000 } query metadata: { $ssm: { $secondaryOk: 1 } } active: 1 timeout: 10000ms inShutdown: 0 first: 1 firstCommandScheduler: RemoteCommandRetryScheduler request: RemoteCommand 575215 -- target:10.160.39.59:28002 db:local cmd:{ find: "oplog.rs", filter: { ts: { $gte: Timestamp 1487743800000|3 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000 } active: 1 callbackHandle.valid: 1 callbackHandle.cancelled: 0 attempt: 1 retryPolicy: RetryPolicyImpl maxAttempts: 1 maxTimeMillis: -1ms
2017-02-22T14:10:23.859+0800 I NETWORK  [thread1] connection accepted from 127.0.0.1:55862 #423 (35 connections now open)
2017-02-22T14:10:23.859+0800 I NETWORK  [conn423] received client metadata from 127.0.0.1:55862 conn423: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.1" }, os: { type: "Linux", name: "CentOS release 6.8 (Final)", architecture: "x86_64", version: "Kernel 2.6.32-642.6.2.el6.x86_64" } }
2017-02-22T14:10:23.866+0800 I -        [conn423] end connection 127.0.0.1:55862 (35 connections now open)
2017-02-22T14:10:35.932+0800 I NETWORK  [thread1] connection accepted from 127.0.0.1:55868 #424 (35 connections now open)
2017-02-22T14:10:35.932+0800 I NETWORK  [conn424] received client metadata from 127.0.0.1:55868 conn424: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.1" }, os: { type: "Linux", name: "CentOS release 6.8 (Final)", architecture: "x86_64", version: "Kernel 2.6.32-642.6.2.el6.x86_64" } }
2017-02-22T14:10:35.940+0800 I -        [conn424] end connection 127.0.0.1:55868 (35 connections now open)
2017-02-22T14:10:42.011+0800 I NETWORK  [thread1] connection accepted from 127.0.0.1:55876 #425 (35 connections now open)
2017-02-22T14:10:42.011+0800 I NETWORK  [conn425] received client metadata from 127.0.0.1:55876 conn425: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.1" }, os: { type: "Linux", name: "CentOS release 6.8 (Final)", architecture: "x86_64", version: "Kernel 2.6.32-642.6.2.el6.x86_64" } }
2017-02-22T14:10:42.018+0800 I -        [conn425] end connection 127.0.0.1:55876 (35 connections now open)
2017-02-22T14:10:47.136+0800 I NETWORK  [thread1] connection accepted from 127.0.0.1:55884 #426 (35 connections now open)
2017-02-22T14:10:47.136+0800 I NETWORK  [conn426] received client metadata from 127.0.0.1:55884 conn426: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.1" }, os: { type: "Linux", name: "CentOS release 6.8 (Final)", architecture: "x86_64", version: "Kernel 2.6.32-642.6.2.el6.x86_64" } }
2017-02-22T14:10:47.144+0800 I -        [conn426] end connection 127.0.0.1:55884 (35 connections now open)
2017-02-22T14:10:50.205+0800 I NETWORK  [thread1] connection accepted from 127.0.0.1:55886 #427 (35 connections now open)
2017-02-22T14:10:50.205+0800 I NETWORK  [conn427] received client metadata from 127.0.0.1:55886 conn427: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.1" }, os: { type: "Linux", name: "CentOS release 6.8 (Final)", architecture: "x86_64", version: "Kernel 2.6.32-642.6.2.el6.x86_64" } }
2017-02-22T14:10:50.212+0800 I -        [conn427] end connection 127.0.0.1:55886 (35 connections now open)
2017-02-22T14:10:50.273+0800 I NETWORK  [thread1] connection accepted from 127.0.0.1:55888 #428 (35 connections now open)
2017-02-22T14:10:50.273+0800 I NETWORK  [conn428] received client metadata from 127.0.0.1:55888 conn428: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.1" }, os: { type: "Linux", name: "CentOS release 6.8 (Final)", architecture: "x86_64", version: "Kernel 2.6.32-642.6.2.el6.x86_64" } }
2017-02-22T14:10:50.280+0800 I -        [conn428] end connection 127.0.0.1:55888 (35 connections now open)
2017-02-22T14:11:51.354+0800 I -        [repl writer worker 15]   MongoApiLogs.OpenApiRequestLog collection clone progress: 1837886/5923483 31% (documents copied)