我的mongodb服务器位于带有fedora31的机器上。我的大多数客户都是从联邦储备银行离职的。
我发现这些客户端在获取数据方面要慢得多。示例代码：
from pymongo import MongoClient
MONGO_HOST = 'XXX'
client = MongoClient(MONGO_HOST, 27017, connect=True)
collection = client.my_database.my_collection
result = collection.find_one(my_key)
从fedora31运行到fedora31:
> time python3 slow_mongo_db_debug.py
real 0m0.798s
user 0m0.257s
sys 0m0.078s
从fedora27运行到fedora31:
> time python3 slow_mongo_db_debug.py
real 0m12.633s
user 0m0.270s
sys 0m0.082s
是什么原因导致了执行速度的巨大差异？
编辑我添加了一些监控。更新代码：
from pymongo import MongoClient, monitoring
import logging
logging.basicConfig(format='%(asctime)s %(levelname)s:%(message)s', level=logging.DEBUG)
class CommandLogger(monitoring.CommandListener):
def started(self, event):
logging.info("Command {0.command_name} with request id "
"{0.request_id} started on server "
"{0.connection_id}".format(event))
def succeeded(self, event):
logging.info("Command {0.command_name} with request id "
"{0.request_id} on server {0.connection_id} "
"succeeded in {0.duration_micros} "
"microseconds".format(event))
def failed(self, event):
logging.info("Command {0.command_name} with request id "
"{0.request_id} on server {0.connection_id} "
"failed in {0.duration_micros} "
"microseconds".format(event))
class ServerLogger(monitoring.ServerListener):
def opened(self, event):
logging.info("Server {0.server_address} added to topology "
"{0.topology_id}".format(event))
def description_changed(self, event):
previous_server_type = event.previous_description.server_type
new_server_type = event.new_description.server_type
if new_server_type != previous_server_type:
# server_type_name was added in PyMongo 3.4
logging.info(
"Server {0.server_address} changed type from "
"{0.previous_description.server_type_name} to "
"{0.new_description.server_type_name}".format(event))
def closed(self, event):
logging.warning("Server {0.server_address} removed from topology "
"{0.topology_id}".format(event))
class TopologyLogger(monitoring.TopologyListener):
def opened(self, event):
logging.info("Topology with id {0.topology_id} "
"opened".format(event))
def description_changed(self, event):
logging.info("Topology description updated for "
"topology id {0.topology_id}".format(event))
previous_topology_type = event.previous_description.topology_type
new_topology_type = event.new_description.topology_type
if new_topology_type != previous_topology_type:
# topology_type_name was added in PyMongo 3.4
logging.info(
"Topology {0.topology_id} changed type from "
"{0.previous_description.topology_type_name} to "
"{0.new_description.topology_type_name}".format(event))
# The has_writable_server and has_readable_server methods
# were added in PyMongo 3.4.
if not event.new_description.has_writable_server():
logging.warning("No writable servers available.")
if not event.new_description.has_readable_server():
logging.warning("No readable servers available.")
def closed(self, event):
logging.info("Topology with id {0.topology_id} "
"closed".format(event))
MONGO_HOST = 'XXX'
logging.info('Start test')
client = MongoClient(MONGO_HOST, 27017, connect=True, event_listeners=[CommandLogger(), ServerLogger(), TopologyLogger()])
my_collection = client.my_db.my_collection
result = my_collection.find_one(my_key)
结果如下：快速：
$ time python3 slow_mongo_db_debug.py
2020-08-24 12:07:43,562 INFO:Start test
2020-08-24 12:07:43,564 INFO:Topology with id 5f43835f98b10083af58e8d7 opened
2020-08-24 12:07:43,565 INFO:Topology description updated for topology id 5f43835f98b10083af58e8d7
2020-08-24 12:07:43,565 INFO:Topology 5f43835f98b10083af58e8d7 changed type from Unknown to Single
2020-08-24 12:07:43,565 WARNING:No writable servers available.
2020-08-24 12:07:43,565 WARNING:No readable servers available.
2020-08-24 12:07:43,566 INFO:Server ('XXX', 27017) added to topology 5f43835f98b10083af58e8d7
2020-08-24 12:07:43,574 INFO:Command find with request id 1681692777 started on server ('XXX', 27017)
2020-08-24 12:07:43,684 INFO:Command find with request id 1681692777 on server ('XXX', 27017) succeeded in 109556 microseconds
real 0m0.776s
user 0m0.269s
sys 0m0.057s
慢速：
$ time python3 slow_mongo_db_debug.py
2020-08-24 12:07:59,315 INFO:Start test
2020-08-24 12:07:59,316 INFO:Topology with id 5f43836f85d65e47d21ad426 opened
2020-08-24 12:07:59,316 INFO:Topology description updated for topology id 5f43836f85d65e47d21ad426
2020-08-24 12:07:59,317 INFO:Topology 5f43836f85d65e47d21ad426 changed type from Unknown to Single
2020-08-24 12:07:59,317 WARNING:No writable servers available.
2020-08-24 12:07:59,317 WARNING:No readable servers available.
2020-08-24 12:07:59,318 INFO:Server ('XXX', 27017) added to topology 5f43836f85d65e47d21ad426
2020-08-24 12:08:13,336 INFO:Server ('XXX', 27017) changed type from Unknown to Standalone
2020-08-24 12:08:13,337 INFO:Topology description updated for topology id 5f43836f85d65e47d21ad426
2020-08-24 12:08:13,337 INFO:Topology description updated for topology id 5f43836f85d65e47d21ad426
2020-08-24 12:08:18,387 INFO:Command find with request id 1714636915 started on server ('XXX', 27017)
2020-08-24 12:08:18,478 INFO:Command find with request id 1714636915 on server ('XXX', 27017) succeeded in 90880 microseconds
real 0m19.762s
user 0m0.192s
sys 0m0.076s
编辑
增加心跳监测：
$ time python3 slow_mongo_db_debug.py
2020-08-26 12:06:14,801 INFO:Start test
2020-08-26 12:06:14,802 INFO:Topology with id 5f462606670b6643437d2022 opened
2020-08-26 12:06:14,803 INFO:Topology description updated for topology id 5f462606670b6643437d2022
2020-08-26 12:06:14,804 INFO:Topology 5f462606670b6643437d2022 changed type from Unknown to Single
2020-08-26 12:06:14,804 WARNING:No writable servers available.
2020-08-26 12:06:14,804 WARNING:No readable servers available.
2020-08-26 12:06:14,804 INFO:Server ('XXX', 27017) added to topology 5f462606670b6643437d2022
2020-08-26 12:06:14,804 INFO:Heartbeat sent to server ('XXX', 27017)
2020-08-26 12:06:19,747 INFO:Heartbeat to server ('XXX', 27017) succeeded with reply {'ismaster': True, 'maxBsonObjectSize': 16777216, 'maxMessageSizeBytes': 48000000, 'maxWriteBatchSize': 100000, 'localTime': datetime.datetime(2020, 8, 26, 9, 6, 19, 747000), 'logicalSessionTimeoutMinutes': 30, 'connectionId': 9503401, 'minWireVersion': 0, 'maxWireVersion': 8, 'readOnly': False, 'ok': 1.0}
2020-08-26 12:06:19,810 INFO:Server ('XXX', 27017) changed type from Unknown to Standalone
2020-08-26 12:06:19,810 INFO:Topology description updated for topology id 5f462606670b6643437d2022
2020-08-26 12:06:20,248 INFO:Heartbeat sent to server ('XXX', 27017)
2020-08-26 12:06:20,250 INFO:Heartbeat to server ('XXX', 27017) succeeded with reply {'ismaster': True, 'maxBsonObjectSize': 16777216, 'maxMessageSizeBytes': 48000000, 'maxWriteBatchSize': 100000, 'localTime': datetime.datetime(2020, 8, 26, 9, 6, 20, 250000), 'logicalSessionTimeoutMinutes': 30, 'connectionId': 9503401, 'minWireVersion': 0, 'maxWireVersion': 8, 'readOnly': False, 'ok': 1.0}
2020-08-26 12:06:20,812 INFO:Topology description updated for topology id 5f462606670b6643437d2022
2020-08-26 12:06:25,765 INFO:Command find with request id 1714636915 started on server ('XXX', 27017)
2020-08-26 12:06:25,766 INFO:Command find with request id 1714636915 on server ('XXX', 27017) succeeded in 1094 microseconds
real 0m11.732s
user 0m0.126s
sys 0m0.064s
使用监控来查看驱动程序在做什么。
- 订阅CommandStartedEvent，并确定
find的此事件是否在两种情况下从进程启动起的相同时间内发布。这将告诉您时间是花在服务器发现上还是花在操作本身上。您还应该接收auth&这样 - 如果查找启动前的时间不同，请启用服务器和拓扑记录器，并确定两个系统之间的差异
- 如果查找之前的时间相同，则查看命令成功事件并确定持续时间差异
- 若查找成功的命令在两个系统上的相对时间相同，那个么清理某个地方的时间就被消耗掉了