Created
September 16, 2013 21:07
-
-
Save bjori/6586633 to your computer and use it in GitHub Desktop.
The MongoDB Profiling example, using the PHP Stream Notification API
For more info, see: http://bjori.blogspot.com/2013/09/query-logging-and-profiling-in-mongodb.html
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
<?php | |
class MongoNotifications { | |
public $reqs = array(); | |
/* Our callback function | |
* The prototype is define by the PHP Stream Notification system: http://php.net/stream_notification_callback | |
*/ | |
function update($notification_code, $severity, $message, $message_code, $bytes_transferred, $bytes_max) { | |
switch($notification_code) { | |
/* For now, lets focus on the TYPE_LOG, and ignore the others */ | |
case MONGO_STREAM_NOTIFY_TYPE_LOG: | |
/* This notification only uses two arguments, so we can ignore the rest */ | |
return $this->logMessage($message_code, $message); | |
default: | |
} | |
} | |
/* Our logging function | |
* The $code describes the operation being executed, | |
* and $message is a json serialized array, packed with information | |
* Note: If ext/json is not available, $message with be PHP serialize()d instead | |
*/ | |
function logMessage($code, $message) { | |
$data = json_decode($message, true); | |
switch($code) { | |
/* Write operations are a one way street in MongoDB, so these don't end with a | |
* MONGO_STREAM_NOTIFY_LOG_RESPONSE_HEADER. | |
* When using WriteConcern (defaults to 1), and additional query (command) is | |
* sent to check for errors, called getLastError*/ | |
case MONGO_STREAM_NOTIFY_LOG_INSERT: | |
case MONGO_STREAM_NOTIFY_LOG_UPDATE: | |
case MONGO_STREAM_NOTIFY_LOG_DELETE: | |
case MONGO_STREAM_NOTIFY_LOG_GETMORE: | |
case MONGO_STREAM_NOTIFY_LOG_KILLCURSOR: | |
case MONGO_STREAM_NOTIFY_LOG_BATCHINSERT: | |
/* We only care about the query and response headers, for now */ | |
break; | |
/* We´ve got a query */ | |
case MONGO_STREAM_NOTIFY_LOG_QUERY: | |
/* Retrieve the Wire protocol Request ID, so we can match it with the | |
* Response headers once the query as executed */ | |
$reqid = $data["server"]["request_id"]; | |
/* Log all the metadata we have about the query, and add the start time */ | |
$this->reqs[$reqid] = $data; | |
$this->reqs[$reqid]["start"] = microtime(true); | |
break; | |
/* The query has executed on the server, and now we are reading the | |
* response headers */ | |
case MONGO_STREAM_NOTIFY_LOG_RESPONSE_HEADER: | |
// Get the Request ID this respose is for | |
$id = $data["server"]["request_id"]; | |
/* The driver runs some commands internally, such as isMaster() to | |
* sanitycheck the connection to the server, these commands currently | |
* don't trigger the notification system - that may/will change in the | |
* future though */ | |
if (!isset($this->reqs[$id])) { | |
return; | |
} | |
// Fetch the request info | |
$req = $this->reqs[$id]; | |
// End the timer | |
$end = microtime(true); | |
// Add the ending time, and how long it took | |
$req["ended"] = $end; | |
$req["total"] = $end - $req["start"]; | |
$this->reqs[$id] = $req; | |
break; | |
default: | |
// Unknown log message code, ignore | |
} | |
} | |
function getRequests() { | |
return $this->reqs; | |
} | |
} | |
/* Some Helper Functions */ | |
/* Split a Server Hash to extract the server name from it */ | |
function getServerName($hash) { | |
list($server, $replicaset, $dbname, $pid) = explode(";", $hash); | |
return $server; | |
} | |
/* Resolve the server type to a readable string */ | |
function getServerType($type) { | |
switch($type) { | |
// FIXME: Do we not export these as constants? | |
case 0x01: return "STANDALONE"; | |
case 0x02: return "PRIMARY"; | |
case 0x04: return "SECONDARY"; | |
case 0x10: return "MONGOS"; | |
} | |
} | |
/* Resolve Cursor (Query) Options to something meaningful */ | |
function getCursorOptions($opts) { | |
// FIXME: Do we not export these as constants? | |
if (($opts & 0x04) == 0x04) { | |
return "slaveOkay"; | |
} | |
return "Primary Only"; | |
} | |
/* Boilerplate stuff to setup a ReplicaSet connection */ | |
// My replicaset seed list | |
$seeds = "toddler.local:30200,toddler.local:30201"; | |
// MongoDB Connection options | |
$moptions = array( | |
// Don't wait to long on servers that are down | |
"connectTimeoutMS" => 300, | |
// Read from secondaries, if available | |
"readPreference" => MongoClient::RP_SECONDARY_PREFERRED, | |
// My local ReplicaSet name | |
"replicaSet" => "REPLICASET", | |
// Don't wait more then a second to confirm Replication | |
"wTimeoutMS" => 1000, | |
); | |
/* Registering a stream context! This is the fun part! */ | |
// Create an instance of our callback object | |
$mn = new MongoNotifications; | |
// No Stream Context Options, for now | |
$coptions = array(); | |
// Configure the Notification Stream Context Parameter to call MongoNotification->update() | |
$cparams = array("notification" => array($mn, "update")); | |
// Create the Stream Context | |
$ctx = stream_context_create($coptions, $cparams); | |
$doptions = array("context" => $ctx); | |
// Instanciate a MongoClient with all our options | |
$mc = new MongoClient($seeds, $moptions, $doptions); | |
// Query the example collection in the test database | |
// you should probably change this to something meaningful | |
$collection = $mc->selectCollection("test", "example"); | |
// Random search criteria, you should change this to something meaningful | |
$criteria = array("search" => "criteria"); | |
// Add some sorting & limit for the fun of it | |
$cursor = $collection->find($criteria)->skip(13)->limit(5)->sort(array("_id" => 1)); | |
// Count on a secondary (we constructed the MongoClient with SECONDARY_PREFERRED) | |
$count = $cursor->count(); | |
echo "We have $count results in total\n"; | |
// Fetch the data from a primary | |
$cursor->setReadPreference(MongoClient::RP_PRIMARY); | |
/* The query isn't execute until we start iterating over it.. */ | |
foreach($cursor as $doc) { | |
} | |
// Fetch our requests from our logger | |
$reqs = $mn->getRequests(); | |
foreach($reqs as $request) { | |
printf("Hit %s (which is a %s, I asked for %s) with:\n%s\n", | |
getServerName($request["server"]["hash"]), | |
getServerType($request["server"]["type"]), | |
getCursorOptions($request["info"]["options"]), | |
json_encode($request["query"], JSON_PRETTY_PRINT) | |
); | |
printf("Skipping the first %d matches, limiting the results to %d documents..\n", | |
$request["info"]["skip"], | |
$request["info"]["limit"] | |
); | |
printf("Server execution time+network latency: %.8f sec\n\n", $request["total"]); | |
} |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment