我在一台Linux服务器(Ubantu16.04,16G内存)上测试mongodb(3.4版本)性能,循环向一个collection中import数据,数据文件大小大概44M,测试代码如下:
#!bin/bash
base_dir=/home/wja/log
:>${base_dir}/runtime.log
:>${base_dir}/dbcount.log
:>${base_dir}/memory.log
:>${base_dir}/connection.log
for((i = 0;i < 50;i++))
do
for((j = 0;j<3;j++))
do
start_time=`date +%s`
mongoimport --host localhost:27050 -d wja -c test --type csv --headerline --file /home/wja/mongotest/mongoimport_1000000.csv --numInsertionWorkers 4
end_time=`date +%s`
echo ------$[ $i * 3 + $j + 1]--------- >> ${base_dir}/connection.log
netstat -plan | grep 27050 | grep -P ^tcp | awk '{print $6}' | sort -n | uniq -c >> ${base_dir}/connection.log
echo $[ $i * 3 + $j + 1 ]th time: use $[ $end_time-$start_time ] s >> ${base_dir}/runtime.log
sleep 10
mongo localhost:27050 --quiet --eval "db=db.getSiblingDB('wja');var n = db.test.count();var cur = db.serverStatus().connections.current;var mem = db.serverStatus().mem;print(n,cur,mem.resident,mem.mapped,mem.virtual);" >> ${base_dir}/dbcount.log
done
sleep 20
done
脚本一开始运行很好,但是后续会开始出现丢失数据的现象,查看mongo的log,会有很多socket exception:
2017-04-09T16:39:20.643+0800 I NETWORK [thread1] connection accepted from 127.0.0.1:41626 #268 (8 connections now open)
2017-04-09T16:39:20.643+0800 D COMMAND [PeriodicTaskRunner] task: UnusedLockCleaner took: 0ms
2017-04-09T16:39:20.643+0800 D COMMAND [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms
2017-04-09T16:39:20.639+0800 D REPL [conn265] Waiting for write concern. OpTime: { ts: Timestamp 0|0, t: -1 }, write concern: { w: 1, wtimeout: 0 }
2017-04-09T16:39:20.643+0800 D COMMAND [conn268] run command admin.$cmd { getnonce: 1 }
2017-04-09T16:39:20.643+0800 I COMMAND [conn268] command admin.$cmd command: getnonce { getnonce: 1 } numYields:0 reslen:65 locks:{} protocol:op_query 0ms
2017-04-09T16:39:20.643+0800 D COMMAND [conn268] run command admin.$cmd { ismaster: 1 }
2017-04-09T16:39:20.643+0800 I COMMAND [conn265] command wja.test command: insert { insert: "test", documents: 1000, writeConcern: { getLastError: 1, w: 1 }, ordered: false } ninserted:1000 keysInserted:2000 numYields:0 reslen:44 locks:{ Global: { acquireCount: { r: 16, w: 16 } }, Database: { acquireCount: { w: 16 } }, Collection: { acquireCount: { w: 16 } } } protocol:op_query 28930ms
2017-04-09T16:39:20.644+0800 D COMMAND [conn267] run command admin.$cmd { getnonce: 1 }
2017-04-09T16:39:20.643+0800 D NETWORK [conn266] Socket recv() conn closed? 127.0.0.1:41610
2017-04-09T16:39:20.644+0800 I COMMAND [conn267] command admin.$cmd command: getnonce { getnonce: 1 } numYields:0 reslen:65 locks:{} protocol:op_query 0ms
2017-04-09T16:39:20.644+0800 D NETWORK [conn266] SocketException: remote: 127.0.0.1:41610 error: 9001 socket exception [CLOSED] server [127.0.0.1:41610]
2017-04-09T16:39:20.643+0800 I NETWORK [thread1] connection accepted from 127.0.0.1:41628 #269 (9 connections now open)
2017-04-09T16:39:20.644+0800 I - [conn266] end connection 127.0.0.1:41610 (9 connections now open)
2017-04-09T16:39:20.644+0800 I NETWORK [thread1] connection accepted from 127.0.0.1:41630 #270 (9 connections now open)
2017-04-09T16:39:20.644+0800 D STORAGE [conn265] WiredTigerSizeStorer::storeInto table:collection-3--156072121439285558 -> { numRecords: 40911768, dataSize: 6054941664 }
2017-04-09T16:39:20.644+0800 D COMMAND [conn267] run command admin.$cmd { ismaster: 1 }
2017-04-09T16:39:20.646+0800 D NETWORK [conn267] Starting server-side compression negotiation
2017-04-09T16:39:20.646+0800 I COMMAND [conn267] command admin.$cmd command: isMaster { ismaster: 1 } numYields:0 reslen:189 locks:{} protocol:op_query 0ms
2017-04-09T16:39:20.647+0800 D NETWORK [conn267] Socket say send() Broken pipe 127.0.0.1:41624
2017-04-09T16:39:20.647+0800 D - [conn267] User Assertion: 6:socket exception [SEND_ERROR] for 127.0.0.1:41624 src/mongo/db/service_entry_point_mongod.cpp 155
2017-04-09T16:39:20.647+0800 I - [conn267] AssertionException handling request, closing client connection: 6 socket exception [SEND_ERROR] for 127.0.0.1:41624
2017-04-09T16:39:20.647+0800 I - [conn267] end connection 127.0.0.1:41624 (9 connections now open)
2017-04-09T16:39:20.643+0800 D NETWORK [conn268] Starting server-side compression negotiation
2017-04-09T16:39:20.649+0800 I COMMAND [conn268] command admin.$cmd command: isMaster { ismaster: 1 } numYields:0 reslen:189 locks:{} protocol:op_query 5ms
2017-04-09T16:39:20.649+0800 D NETWORK [conn268] Socket say send() Broken pipe 127.0.0.1:41626
2017-04-09T16:39:20.649+0800 D - [conn268] User Assertion: 6:socket exception [SEND_ERROR] for 127.0.0.1:41626 src/mongo/db/service_entry_point_mongod.cpp 155
2017-04-09T16:39:20.649+0800 I - [conn268] AssertionException handling request, closing client connection: 6 socket exception [SEND_ERROR] for 127.0.0.1:41626
2017-04-09T16:39:20.649+0800 D COMMAND [conn269] run command admin.$cmd { getnonce: 1 }
2017-04-09T16:39:20.650+0800 I COMMAND [conn269] command admin.$cmd command: getnonce { getnonce: 1 } numYields:0 reslen:65 locks:{} protocol:op_query 0ms
2017-04-09T16:39:20.650+0800 I - [conn268] end connection 127.0.0.1:41626 (8 connections now open)
每次导入结束后,打印了一下对应端口的连接数,感觉很正常,基本都是
2 ESTABLISHED
1 LISTEN
6 TIME_WAIT
出错的时候TIME_WAIT会很小,或者会出现FIN_WAIT2和CLOSE_WAIT
我不知道是什么问题造成了连接问题,是我的测试方法不对,还是哪里配置没有注意?这个问题困扰我好久了,能有人帮我解决吗?
Try to answer:
1. Check the Socket limitations of the operating system
2. Check the maxConns setting of MongoDB
3. Let’s see how the network connection of mongoimport is implemented
This problem is related to the network connection. The above ideas are for reference.
Love MongoDB! Have fun!