https://github.com/mongodb/mongo-php-driver/issues/1327

gh1327.php

<?php

enum TimeUnit : string
{
    case Nanos = 'ns';
    case Micros = 'μs';
    case Millis = 'ms';
}

class TimeUnitString
{
    private TimeUnit $timeUnit = TimeUnit::Millis;

    private function __construct(private int $ns) {}

    public static function fromNanos(int $ns): self
    {
        return new self($ns);
    }

    public static function fromMicros(int $micros): self
    {
        return new self($micros * 1000);
    }

    public function __toString(): string
    {
        switch ($this->timeUnit) {
            case TimeUnit::Nanos:
                return sprintf('%d%s', $this->ns, $this->timeUnit->value);

            case TimeUnit::Micros:
                return sprintf('%.3f%s', $this->ns / 1000, $this->timeUnit->value);

            case TimeUnit::Millis:
                return sprintf('%.6f%s', $this->ns / 1000000, $this->timeUnit->value);
        }
    }
}

class QueryTimeCollector implements MongoDB\Driver\Monitoring\CommandSubscriber
{
    private array $commandStartedAt = [];

    public function commandStarted(MongoDB\Driver\Monitoring\CommandStartedEvent $event)
    {
        $requestCommand = $this->getRequestCommand($event);
        $this->commandStartedAt[$requestCommand] = hrtime(true);

        printf("commandStarted(%s)\n", $requestCommand);
    }

    public function commandSucceeded(MongoDB\Driver\Monitoring\CommandSucceededEvent $event)
    {
        $requestCommand = $this->getRequestCommand($event);
        $hrtimeDuration = hrtime(true) - $this->commandStartedAt[$requestCommand];
        unset($this->commandStartedAt[$requestCommand]);

        printf(
            "commandSucceeded(%s): %s (eventDuration=%s)\n",
            $requestCommand,
            TimeUnitString::fromNanos($hrtimeDuration),
            TimeUnitString::fromMicros($event->getDurationMicros())
        );
    }

    public function commandFailed(MongoDB\Driver\Monitoring\CommandFailedEvent $event)
    {
        $requestCommand = $this->getRequestCommand($event);
        $hrtimeDuration = hrtime(true) - $this->commandStartedAt[$requestCommand];
        unset($this->commandStartedAt[$requestCommand]);

        printf(
            "commandFailed(%s): %s (eventDuration=%s)\n",
            $requestCommand,
            TimeUnitString::fromNanos($hrtimeDuration),
            TimeUnitString::fromMicros($event->getDurationMicros())
        );
    }

    private function getRequestCommand($event): string
    {
        return $event->getRequestId() . ':' . $event->getCommandName();
    }
}

class SDAMTimeCollector implements MongoDB\Driver\Monitoring\SDAMSubscriber
{
    private bool $logHeartbeat = true;
    private bool $logServer = false;
    private bool $logTopology = false;

    private array $heartbeatStartedAt = [];
    private array $serverOpenedAt = [];
    private array $topologyOpenedAt = [];

    public function serverClosed(MongoDB\Driver\Monitoring\ServerClosedEvent $event)
    {
        if ( ! $this->logServer) {
            return;
        }

        $hostPort = $this->getHostPort($event);
        $hrtimeDuration = hrtime(true) - $this->serverOpenedAt[$hostPort];
        unset($this->serverOpenedAt[$hostPort]);

        printf("serverClosed(%s): %s\n", $hostPort, TimeUnitString::fromNanos($hrtimeDuration));
    }

    public function serverOpening(MongoDB\Driver\Monitoring\ServerOpeningEvent $event)
    {
        if ( ! $this->logServer) {
            return;
        }

        $hostPort = $this->getHostPort($event);
        $this->serverOpenedAt[$hostPort] = hrtime(true);

        printf("serverOpening(%s)\n", $hostPort);
    }

    public function serverChanged(MongoDB\Driver\Monitoring\ServerChangedEvent $event)
    {
        if ( ! $this->logServer) {
            return;
        }

        printf("serverChanged(%s)\n", $this->getHostPort($event));
    }

    public function serverHeartbeatFailed(MongoDB\Driver\Monitoring\ServerHeartbeatFailedEvent $event)
    {
        if ( ! $this->logHeartbeat) {
            return;
        }

        $hostPort = $this->getHostPort($event);
        $hrtimeDuration = hrtime(true)- $this->heartbeatStartedAt[$hostPort];
        unset($this->heartbeatStartedAt[$hostPort]);

        printf(
            "serverHeartbeatFailed(%s): %s (eventDuration=%s)\n",
            $hostPort,
            TimeUnitString::fromNanos($hrtimeDuration),
            TimeUnitString::fromMicros($event->getDurationMicros())
        );
    }

    public function serverHeartbeatStarted(MongoDB\Driver\Monitoring\ServerHeartbeatStartedEvent $event)
    {
        if ( ! $this->logHeartbeat) {
            return;
        }

        $hostPort = $this->getHostPort($event);
        $this->heartbeatStartedAt[$hostPort] = hrtime(true);

        printf("serverHeartbeatStarted(%s)\n", $hostPort);
    }

    public function serverHeartbeatSucceeded(MongoDB\Driver\Monitoring\ServerHeartbeatSucceededEvent $event)
    {
        if ( ! $this->logHeartbeat) {
            return;
        }

        $hostPort = $this->getHostPort($event);
        $hrtimeDuration = hrtime(true) - $this->heartbeatStartedAt[$hostPort];
        unset($this->heartbeatStartedAt[$hostPort]);

        printf(
            "serverHeartbeatSucceeded(%s): %s (eventDuration=%s)\n",
            $hostPort,
            TimeUnitString::fromNanos($hrtimeDuration),
            TimeUnitString::fromMicros($event->getDurationMicros())
        );
    }

    public function topologyChanged(MongoDB\Driver\Monitoring\TopologyChangedEvent $event)
    {
        if ( ! $this->logTopology) {
            return;
        }

        printf("topologyChanged(%s)\n", $event->getTopologyId());
    }

    public function topologyClosed(MongoDB\Driver\Monitoring\TopologyClosedEvent $event)
    {
        if ( ! $this->logTopology) {
            return;
        }

        $tid = (string) $event->getTopologyId();
        $hrtimeDuration = hrtime(true) - $this->topologyOpenedAt[$tid];
        unset($this->topologyOpenedAt[$tid]);

        printf("topologyClosed(%s): %s\n", $tid, TimeUnitString::fromNanos($hrtimeDuration));
    }

    public function topologyOpening(MongoDB\Driver\Monitoring\TopologyOpeningEvent $event)
    {
        if ( ! $this->logTopology) {
            return;
        }

        $tid = (string) $event->getTopologyId();
        $this->topologyOpenedAt[$tid] = hrtime(true);

        printf("topologyOpening(%s)\n", $tid);
    }

    private function getHostPort($event): string
    {
        return $event->getHost() . ':' . $event->getPort();
    }
}

MongoDB\Driver\Monitoring\addSubscriber(new QueryTimeCollector());
MongoDB\Driver\Monitoring\addSubscriber(new SDAMTimeCollector());

$start = hrtime(true);
$manager = new MongoDB\Driver\Manager('mongodb+srv://USERNAME:[email protected]/?retryWrites=true&w=majority');
printf("Manager::__construct: %s\n", TimeUnitString::fromNanos(hrtime(true) - $start));

$start = hrtime(true);
$primary = $manager->selectServer();
printf("Manager::selectServer: %s\n", TimeUnitString::fromNanos(hrtime(true) - $start));

$bulk = new MongoDB\Driver\BulkWrite;
$bulk->delete(['_id' => new MongoDB\BSON\ObjectId('6295fdd2049dcd5aca422688')]);
$bulk->insert(['_id' => new MongoDB\BSON\ObjectId('6295fdd2049dcd5aca422688')]);
$start = hrtime(true);
$cursor = $manager->executeBulkWrite('MyDb.sessions', $bulk);
printf("Manager::executeBulkWrite: %s\n", TimeUnitString::fromNanos(hrtime(true) - $start));

$start = hrtime(true);
$cursor = $manager->executeQuery('MyDb.sessions', new MongoDB\Driver\Query(['_id' => new MongoDB\BSON\ObjectId('6295fdd2049dcd5aca422688')]));
printf("Manager::executeQuery: %s\n", TimeUnitString::fromNanos(hrtime(true) - $start));

$start = hrtime(true);
$doc = $cursor->toArray()[0];
printf("Cursor::toArray()[0]: %s\n", TimeUnitString::fromNanos(hrtime(true) - $start));

var_dump($doc);

gh1327.py

import time
from bson import ObjectId
from pymongo import MongoClient, InsertOne, DeleteOne

start = time.monotonic_ns()
client = MongoClient("mongodb+srv://USERNAME:[email protected]/?retryWrites=true&w=majority")
print("MongoClient: %.3fms" % ((time.monotonic_ns() - start) / 1000000));

collection = client["MyDb"]["sessions"]

start = time.monotonic_ns()
collection.bulk_write([DeleteOne({"_id" : ObjectId("6295fdd2049dcd5aca422688")}), InsertOne({"_id" : ObjectId("6295fdd2049dcd5aca422688")})])
print("bulk_write: %.3fms" % ((time.monotonic_ns() - start) / 1000000));

start = time.monotonic_ns()
doc = collection.find_one({"_id" : ObjectId("6295fdd2049dcd5aca422688")})
print("find_one: %.3fms" % ((time.monotonic_ns() - start) / 1000000));

print(doc)

output.txt

$ python3 gh1327.py
MongoClient: 47.017ms
bulk_write: 251.621ms
find_one: 20.887ms
{'_id': ObjectId('6295fdd2049dcd5aca422688')}

# Note: running the PHP script immediately after Python may report a shorter
# time for Manager construction if libmongoc uses a cached DNS result.

$ php gh1327.php 
Manager::__construct: 45.391130ms
serverHeartbeatStarted(cluster0-shard-00-00.4b82o.mongodb.net:27017)
serverHeartbeatStarted(cluster0-shard-00-01.4b82o.mongodb.net:27017)
serverHeartbeatStarted(cluster0-shard-00-02.4b82o.mongodb.net:27017)
serverHeartbeatSucceeded(cluster0-shard-00-00.4b82o.mongodb.net:27017): 271.919108ms (eventDuration=13.842000ms)
serverHeartbeatSucceeded(cluster0-shard-00-02.4b82o.mongodb.net:27017): 204.903404ms (eventDuration=12.296000ms)
serverHeartbeatSucceeded(cluster0-shard-00-01.4b82o.mongodb.net:27017): 246.729284ms (eventDuration=16.243000ms)
commandStarted(3:delete)
commandSucceeded(3:delete): 14.711443ms (eventDuration=14.724000ms)
commandStarted(5:insert)
commandSucceeded(5:insert): 24.562444ms (eventDuration=24.512000ms)
Manager::executeBulkWrite: 379.732041ms
commandStarted(7:find)
commandSucceeded(7:find): 19.403067ms (eventDuration=19.368000ms)
Manager::executeQuery: 20.029461ms
Cursor::toArray()[0]: 0.076156ms
object(stdClass)#11 (1) {
  ["_id"]=>
  object(MongoDB\BSON\ObjectId)#12 (1) {
    ["oid"]=>
    string(24) "6295fdd2049dcd5aca422688"
  }
}