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

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

<b>####连接primary库</b>

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

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

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] ******

<b>####创建oplog 日志文件####</b>

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] ******

<b>####应用主库的日志，复制数据文件####</b>

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

<b>===下面是删除节点以后的日志==</b>

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 中其他节点的数据文件!(记住是数据文件，一定不要<b>mongod.lock </b>，每个mongod进程都需要自己的数据目录，如果你要运行3个mongod的实例，那么就需要3个独自的目录。mongod启动的时候会在数据目录创建一个mongod.lock文件，阻止其他进程使用此目录.)

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

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

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

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

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

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