【Mongodb】 replica set 两种添加节点方法的日志分析

    这篇文章算是 《replica set 添加和删除节点》 的点缀，本来没打算查看添加节点的第二种方法，即拷贝其他节点的数据文件到新的节点，本着“入微”的原则，对两种方法做一下对比，具体添加节点的过程和前面介绍的一样，只是在启动mongod服务之前要拷贝数据文件到本机。

下面是空库添加到一个replica set中的日志记录：

####连接primary库

Tue Nov  1 14:22:57 [initandlisten] connection accepted from 10.250.7.220:54235 #2

Tue Nov  1 14:22:57 [initandlisten] connection accepted from 10.250.7.220:54236 #3

Tue Nov  1 14:22:57 [initandlisten] connection accepted from 10.250.7.220:54237 #4

Tue Nov  1 14:22:57 [rsStart] trying to contact 10.250.7.220:27018

Tue Nov  1 14:22:57 [rsStart] trying to contact 10.250.7.220:27019

Tue Nov  1 14:22:57 [rsStart] trying to contact 10.250.7.220:27020

####从primary库复制replica set的配置信息，并保存到本地 -dbpath 指定的文件目录####

Tue Nov  1 14:22:57 [rsStart] replSet got config version 2 from a remote, saving locally

Tue Nov  1 14:22:57 [rsStart] replSet info saving a newer config version to local.system.replset

Tue Nov  1 14:22:57 [FileAllocator] allocating new datafile /opt/mongodata/r1/local.ns, filling with zeroes...

Tue Nov  1 14:22:57 [FileAllocator] creating directory /opt/mongodata/r1/_tmp

Tue Nov  1 14:22:57 [FileAllocator] done allocating datafile /opt/mongodata/r1/local.ns, size: 16MB,  took 0.118 secs

Tue Nov  1 14:22:57 [FileAllocator] allocating new datafile /opt/mongodata/r1/local.0, filling with zeroes...

Tue Nov  1 14:23:01 [FileAllocator] done allocating datafile /opt/mongodata/r1/local.0, size: 64MB,  took 3.807 secs

Tue Nov  1 14:23:01 [FileAllocator] allocating new datafile /opt/mongodata/r1/local.1, filling with zeroes...

Tue Nov  1 14:23:02 [rsStart] replSet saveConfigLocally done

Tue Nov  1 14:23:02 [FileAllocator] done allocating datafile /opt/mongodata/r1/local.1, size: 128MB,  took 1.068 secs

Tue Nov  1 14:23:02 [rsStart] replSet STARTUP2

Tue Nov  1 14:23:02 [rsMgr] replSet total number of votes is even - add arbiter or give one member an extra vote

Tue Nov  1 14:23:02 [rsSync] ******

####创建oplog 日志文件####

Tue Nov  1 14:23:02 [rsSync] creating replication oplog of size: 944MB...

Tue Nov  1 14:23:02 [FileAllocator] allocating new datafile /opt/mongodata/r1/local.2, filling with zeroes...

Tue Nov  1 14:23:04 [rsHealthPoll] replSet info member 10.250.7.220:27018 is up

Tue Nov  1 14:23:04 [rsHealthPoll] replSet member 10.250.7.220:27018 is now in state SECONDARY

Tue Nov  1 14:23:04 [rsHealthPoll] replSet info member 10.250.7.220:27019 is up

Tue Nov  1 14:23:04 [rsHealthPoll] replSet member 10.250.7.220:27019 is now in state SECONDARY

Tue Nov  1 14:23:04 [rsHealthPoll] replSet info member 10.250.7.220:27020 is up

Tue Nov  1 14:23:04 [rsHealthPoll] replSet member 10.250.7.220:27020 is now in state PRIMARY

Tue Nov  1 14:23:49 [FileAllocator] done allocating datafile /opt/mongodata/r1/local.2, size: 1024MB,  took 46.28 secs

Tue Nov  1 14:23:50 [rsSync] ******

####应用主库的日志，复制数据文件####

Tue Nov  1 14:23:50 [rsSync] replSet initial sync pending

Tue Nov  1 14:23:50 [rsSync] replSet syncing to: 10.250.7.220:27020

Tue Nov  1 14:23:50 [rsSync] build index local.me { _id: 1 }

Tue Nov  1 14:23:50 [rsSync] build index done 0 records 0.003 secs

Tue Nov  1 14:23:50 [rsSync] replSet initial sync drop all databases

Tue Nov  1 14:23:50 [rsSync] dropAllDatabasesExceptLocal 1

Tue Nov  1 14:23:50 [rsSync] replSet initial sync clone all databases

Tue Nov  1 14:23:50 [rsSync] replSet initial sync cloning db: test

Tue Nov  1 14:23:50 [FileAllocator] allocating new datafile /opt/mongodata/r1/test.ns, filling with zeroes...

Tue Nov  1 14:23:51 [FileAllocator] done allocating datafile /opt/mongodata/r1/test.ns, size: 16MB,  took 0.8 secs

Tue Nov  1 14:23:51 [FileAllocator] allocating new datafile /opt/mongodata/r1/test.0, filling with zeroes...

Tue Nov  1 14:23:55 [FileAllocator] done allocating datafile /opt/mongodata/r1/test.0, size: 64MB,  took 3.643 secs

Tue Nov  1 14:23:55 [FileAllocator] allocating new datafile /opt/mongodata/r1/test.1, filling with zeroes...

Tue Nov  1 14:23:55 [rsSync] build index test.yql { _id: 1 }

Tue Nov  1 14:23:56 [rsSync] build index done 1 records 0.006 secs

Tue Nov  1 14:23:56 [rsSync] replSet initial sync query minValid

Tue Nov  1 14:23:56 [rsSync] replSet initial oplog application from 10.250.7.220:27020 starting at Nov  1 14:14:05:1 to Nov  1 14:14:05:1

Tue Nov  1 14:23:57 [rsSync] replSet initial sync finishing up

Tue Nov  1 14:23:57 [rsSync] replSet set minValid=4eaf8e2d:1

Tue Nov  1 14:23:57 [rsSync] build index local.replset.minvalid { _id: 1 }

Tue Nov  1 14:23:57 [rsSync] build index done 0 records 0.023 secs

Tue Nov  1 14:23:57 [rsSync] replSet initial sync done

Tue Nov  1 14:23:58 [rsSync] replSet syncing to: 10.250.7.220:27020

Tue Nov  1 14:23:58 [rsSync] replSet SECONDARY

Tue Nov  1 14:24:02 [FileAllocator] done allocating datafile /opt/mongodata/r1/test.1, size: 128MB,  took 7.428 secs

Tue Nov  1 14:24:16 [clientcursormon] mem (MB) res:16 virt:2848 mapped:1312

Tue Nov  1 14:24:42 [initandlisten] connection accepted from 127.0.0.1:21141 #5

Tue Nov  1 14:29:16 [clientcursormon] mem (MB) res:16 virt:2849 mapped:1312

Tue Nov  1 14:34:16 [clientcursormon] mem (MB) res:16 virt:2913 mapped:1312

Tue Nov  1 14:39:16 [clientcursormon] mem (MB) res:16 virt:2913 mapped:1312

===下面是删除节点以后的日志==

Tue Nov  1 14:39:28 [conn2] end connection 10.250.7.220:54235

Tue Nov  1 14:39:29 [rsMgr] replset msgReceivedNewConfig version: version: 3

Tue Nov  1 14:39:29 [rsMgr] replSet info saving a newer config version to local.system.replset

Tue Nov  1 14:39:29 [rsMgr] replSet saveConfigLocally done

Tue Nov  1 14:39:29 [rsMgr] replSet error self not present in the repl set configuration:

Tue Nov  1 14:39:29 [rsMgr] { _id: "myset", version: 3, members: [ { _id: 0, host: "10.250.7.220:27018" }, { _id: 1, host: "10.250.7.220:27019" }, { _id: 2, host: "10.

250.7.220:27020" } ] }

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

这是拷贝replica set myset 中其他节点的数据文件!(记住是数据文件，一定不要mongod.lock ，每个mongod进程都需要自己的数据目录，如果你要运行3个mongod的实例，那么就需要3个独自的目录。mongod启动的时候会在数据目录创建一个mongod.lock文件，阻止其他进程使用此目录.)

####连接primary库， 这一点和上面一种方法一样。

Tue Nov  1 15:53:24 [initandlisten] connection accepted from 10.250.7.220:54761 #2

Tue Nov  1 15:53:28 [initandlisten] connection accepted from 10.250.7.220:54763 #3

Tue Nov  1 15:53:28 [initandlisten] connection accepted from 10.250.7.220:54764 #4

Tue Nov  1 15:53:34 [clientcursormon] mem (MB) res:31 virt:2606 mapped:1232

Tue Nov  1 15:53:34 [rsStart] trying to contact 10.250.7.220:27018

Tue Nov  1 15:53:34 [rsStart] trying to contact 10.250.7.220:27019

Tue Nov  1 15:53:34 [rsStart] trying to contact 10.250.7.220:27020

####拷贝配置文件，并保存。这一点和上面一种方法一样。

Tue Nov  1 15:53:34 [rsStart] replSet got config version 6 from a remote, saving locally

Tue Nov  1 15:53:34 [rsStart] replSet info saving a newer config version to local.system.replset

Tue Nov  1 15:53:34 [rsStart] replSet saveConfigLocally done

Tue Nov  1 15:53:34 [rsStart] replSet STARTUP2

Tue Nov  1 15:53:34 [rsMgr] replSet total number of votes is even - add arbiter or give one member an extra vote

Tue Nov  1 15:53:34 [rsSync] replSet SECONDARY

Tue Nov  1 15:53:34 [rsHealthPoll] replSet info member 10.250.7.220:27018 is up

Tue Nov  1 15:53:34 [rsHealthPoll] replSet member 10.250.7.220:27018 is now in state SECONDARY

Tue Nov  1 15:53:34 [rsHealthPoll] replSet info member 10.250.7.220:27019 is up

Tue Nov  1 15:53:34 [rsHealthPoll] replSet member 10.250.7.220:27019 is now in state SECONDARY

Tue Nov  1 15:53:34 [rsHealthPoll] replSet info member 10.250.7.220:27020 is up

Tue Nov  1 15:53:34 [rsHealthPoll] replSet member 10.250.7.220:27020 is now in state PRIMARY

Tue Nov  1 15:53:34 [rsMgr] replSet can't see a majority, will not try to elect self

Tue Nov  1 15:53:38 [rsSync] replSet syncing to: 10.250.7.220:27020

从上面的日志来看，整个第二种方法初始化的速度比较快。当然考虑拷贝数据文件的时间，在大量数据的时候，才能看到哪一个比较好！

Note：学习mongodb 的时候注意查看输出日志。从里面能看到很多重要的信息。如果对mongodb 进行监控的话，也要对输出日志进行分析！

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/22664653/viewspace-710057/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/22664653/viewspace-710057/