【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 进行监控的话,也要对输出日志进行分析!
上一篇:MongoDB位置查询内存使用优化


下一篇:利用github pages创建简单的网站