Testing the PHP driver with Atlas failovers

README.md

Testing the PHP driver with Atlas failovers

Ping

The following was added to the URI for an Atlas 3.6 cluster and assigned to a $uri variable in the PHP script:

?serverSelectionTryOnce=false&serverSelectionTimeoutMS=15000

The script was then executed:

php atlas-ping.php

While the script was executing, a failover test was initiated from the Atlas cluster overview page.

Abridged output follows:

Success since 15:10:46.413856
  Number of commands: 5000
  Command durations: min=0.006383, max=0.028371, avg=0.007208 (seconds)
  Total duration: 36.067752 (seconds)
Success since 15:11:22.482895
  Number of commands: 3813
  Command durations: min=0.006388, max=0.028537, avg=0.006798 (seconds)
  Total duration: 25.943891 (seconds)
Failure since 15:11:48.428574
  Number of commands: 1
  Command durations: min=0.000799, max=0.000799, avg=0.000799 (seconds)
  Total duration: 0.000799 (seconds)
Success since 15:12:00.379337
  Number of commands: 5000
  Command durations: min=0.006559, max=11.950593, avg=0.009302 (seconds)
  Total duration: 46.536481 (seconds)
Success since 15:12:34.966290
^C

With this test, we see 8813 successful ping commands, followed by one failure. This failure occurs after the PHP library selects what it believes is a primary server for the ping operation, writes the command to the socket, and encounters an error because the connection has closed. The subsequent ping operation is delayed as it spends 11.95 seconds in the server selection loop attempting to find a new primary server. Thereafter, we see ping commands execute as quickly as before the failover.

This is roughly the same behavior we might expect for a write operation without retryable writes enabled.

Upsert with Retryable Writes

The following was added to the URI for an Atlas 3.6 cluster and assigned to a $uri variable in the PHP script:

?serverSelectionTryOnce=false&serverSelectionTimeoutMS=15000&retryWrites=true

The script was then executed:

php atlas-upsert.php

While the script was executing, a failover test was initiated from the Atlas cluster overview page.

Abridged output follows:

Success since 15:20:09.754595
  Number of commands: 5000
  Command durations: min=0.006609, max=0.214565, avg=0.007060 (seconds)
  Total duration: 35.330071 (seconds)
Success since 15:20:45.085878
  Number of commands: 5000
  Command durations: min=0.006436, max=11.581084, avg=0.009280 (seconds)
  Total duration: 46.427248 (seconds)
Success since 15:21:31.514379
  Number of commands: 5000
  Command durations: min=0.006445, max=0.020294, avg=0.006885 (seconds)
  Total duration: 34.452975 (seconds)
Success since 15:22:05.968087
^C

The failover kicked in during the second block of commands. The maximum command duration for that block is 11.58 seconds and is what we would expect for the retried write operation. The operation initially fails against a recently stepped down primary, the driver enters a server selection loop for up to 15 seconds, and finally retries the operation on the newly discovered primary. That sequence of events takes 11.58 seconds.

atlas-ping.php

<?php

require_once 'vendor/autoload.php';

// $uri = 'mongodb+srv://username:password@example.mongodb.net/test';
$client = new MongoDB\Client($uri);

$lastOk = null;
$firstStart = null;
$lastEnd = null;
$durations = [];

while (true) {
    $start = microtime(true);
    try {
        $client->test->command(['ping' => 1]);
        $ok = true;
    } catch (MongoDB\Driver\Exception\Exception $e) {
        //printf("%s(%d): %s\n", get_class($e), $e->getCode(), $e->getMessage());
        $ok = false;
    }
    $end = microtime(true);
    $duration = $end - $start;

    $stateChanged = ($ok !== $lastOk);

    if (!$stateChanged) {
        $durations[] = $duration;
        if ($firstStart === null) {
            $firstStart = $start;
        }
        $lastEnd = $end;
    }

    if ($stateChanged || count($durations) >= 5000) {
        if ($lastOk !== null) {
            printf("  Number of commands: %d\n", count($durations));
            printf("  Command durations: min=%.6f, max=%.6f, avg=%.6f (seconds)\n", min($durations), max($durations), array_sum($durations) / count($durations));
            printf("  Total duration: %.6f (seconds)\n", ($lastEnd - $firstStart));
        }

        printf("%s since %s\n", ($ok ? 'Success' : 'Failure'), (new DateTime)->format('H:i:s.u'));

        $lastOk = $ok;
        $firstStart = null;
        $durations = [];

        if ($stateChanged) {
            $durations[] = $duration;
            if ($firstStart === null) {
                $firstStart = $start;
            }
            $lastEnd = $end;
        }
    }
}

atlas-upsert.php

<?php

require_once 'vendor/autoload.php';

// $uri = 'mongodb+srv://username:password@example.mongodb.net/test';
$client = new MongoDB\Client($uri);

$lastOk = null;
$firstStart = null;
$lastEnd = null;
$durations = [];

while (true) {
    $start = microtime(true);
    try {
        $client->test->foo->updateOne(['_id' => 1], ['$set' => ['x' => 1]], ['upsert' => true]);
        $ok = true;
    } catch (MongoDB\Driver\Exception\Exception $e) {
        //printf("%s(%d): %s\n", get_class($e), $e->getCode(), $e->getMessage());
        $ok = false;
    }
    $end = microtime(true);
    $duration = $end - $start;

    $stateChanged = ($ok !== $lastOk);

    if (!$stateChanged) {
        $durations[] = $duration;
        if ($firstStart === null) {
            $firstStart = $start;
        }
        $lastEnd = $end;
    }

    if ($stateChanged || count($durations) >= 5000) {
        if ($lastOk !== null) {
            printf("  Number of commands: %d\n", count($durations));
            printf("  Command durations: min=%.6f, max=%.6f, avg=%.6f (seconds)\n", min($durations), max($durations), array_sum($durations) / count($durations));
            printf("  Total duration: %.6f (seconds)\n", ($lastEnd - $firstStart));
        }

        printf("%s since %s\n", ($ok ? 'Success' : 'Failure'), (new DateTime)->format('H:i:s.u'));

        $lastOk = $ok;
        $firstStart = null;
        $durations = [];

        if ($stateChanged) {
            $durations[] = $duration;
            if ($firstStart === null) {
                $firstStart = $start;
            }
            $lastEnd = $end;
        }
    }
}