为什么pymongo find_one在其他操作系统上速度较慢？

编程问答 2022-08-15

问题描述

我的mongodb服务器安装在装有fedora31的计算机上。 我的大多数客户都从fedora27运行。

我看到那些客户端获取数据的速度要慢得多。 示例代码：

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

执行速度如此巨大的差异是什么原因？

编辑 我添加了一些monitoring。更新的代码：

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,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',20,250000),'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

解决方法

使用monitoring查看驱动程序在做什么。

  1. 订阅CommandStartedEvent并确定在两种情况下，您的find的事件在流程开始后是否发布了相同的时间。这将告诉您是在服务器发现上还是在操作本身上花费了时间。您还应该收到其他关于auth＆诸如此类的命令启动事件。
  2. 如果发现开始之前的时间不同，请启用服务器和拓扑记录器，并确定两个系统之间的差异。
  3. 如果找到之前的时间相同，请查看命令成功事件并确定持续时间差异。
  4. 如果在两个系统上相同的相对时间发布了成功找到的命令，则将花费时间进行清理。
mongodbpymongopythonpython-3.x