Merge pull request #461 from shish/dbtime

Log time spent in database (and some other minor performance debugging tweaks)

core/database.class.php

@@ -284,6 +284,9 @@ class MemcacheCache implements CacheEngine {
 			$this->memcache = new Memcache;
 			@$this->memcache->pconnect($hp[0], $hp[1]);
 		}
+		else {
+			print "no memcache"; exit;
+		}
 	}
 
 	/**
@@ -292,10 +295,11 @@ class MemcacheCache implements CacheEngine {
 	 */
 	public function get($key) {
 		assert(!is_null($key));
-		if((DEBUG_CACHE === true) || (is_null(DEBUG_CACHE) && @$_GET['DEBUG_CACHE'])) {
-			file_put_contents("data/cache.log", "Cache lookup: $key\n", FILE_APPEND);
-		}
 		$val = $this->memcache->get($key);
+		if((DEBUG_CACHE === true) || (is_null(DEBUG_CACHE) && @$_GET['DEBUG_CACHE'])) {
+			$hit = $val === false ? "miss" : "hit";
+			file_put_contents("data/cache.log", "Cache $hit: $key\n", FILE_APPEND);
+		}
 		if($val !== false) {
 			$this->hits++;
 			return $val;
@@ -380,6 +384,7 @@ class Database {
 	 * @var null|PDO
 	 */
 	private $db = null;
+	public $dbtime = 0.0;
 
 	/**
 	 * Meta info about the database engine.
@@ -576,7 +581,10 @@ class Database {
 	 * @return array
 	 */
 	public function get_all($query, $args=array()) {
-		return $this->execute($query, $args)->fetchAll();
+		$_start = microtime(true);
+		$data = $this->execute($query, $args)->fetchAll();
+		$this->dbtime += microtime(true) - $_start;
+		return $data;
 	}
 
 	/**
@@ -587,7 +595,9 @@ class Database {
 	 * @return mixed|null
 	 */
 	public function get_row($query, $args=array()) {
+		$_start = microtime(true);
 		$row = $this->execute($query, $args)->fetch();
+		$this->dbtime += microtime(true) - $_start;
 		return $row ? $row : null;
 	}
 
@@ -599,11 +609,13 @@ class Database {
 	 * @return array
 	 */
 	public function get_col($query, $args=array()) {
+		$_start = microtime(true);
 		$stmt = $this->execute($query, $args);
 		$res = array();
 		foreach($stmt as $row) {
 			$res[] = $row[0];
 		}
+		$this->dbtime += microtime(true) - $_start;
 		return $res;
 	}
 
@@ -615,11 +627,13 @@ class Database {
 	 * @return array
 	 */
 	public function get_pairs($query, $args=array()) {
+		$_start = microtime(true);
 		$stmt = $this->execute($query, $args);
 		$res = array();
 		foreach($stmt as $row) {
 			$res[$row[0]] = $row[1];
 		}
+		$this->dbtime += microtime(true) - $_start;
 		return $res;
 	}
 
@@ -631,7 +645,9 @@ class Database {
 	 * @return mixed
 	 */
 	public function get_one($query, $args=array()) {
+		$_start = microtime(true);
 		$row = $this->execute($query, $args)->fetch();
+		$this->dbtime += microtime(true) - $_start;
 		return $row[0];
 	}
 

core/user.class.php

@@ -67,7 +67,7 @@ class User {
 	 */
 	public static function by_session(/*string*/ $name, /*string*/ $session) {
 		global $config, $database;
-		$row = $database->cache->get("user-session-$name-$session");
+		$row = $database->cache->get("user-session:$name-$session");
 		if(!$row) {
 			if($database->get_driver_name() === "mysql") {
 				$query = "SELECT * FROM users WHERE name = :name AND md5(concat(pass, :ip)) = :sess";
@@ -76,7 +76,7 @@ class User {
 				$query = "SELECT * FROM users WHERE name = :name AND md5(pass || :ip) = :sess";
 			}
 			$row = $database->get_row($query, array("name"=>$name, "ip"=>get_session_ip($config), "sess"=>$session));
-			$database->cache->set("user-session-$name-$session", $row, 600);
+			$database->cache->set("user-session:$name-$session", $row, 600);
 		}
 		return is_null($row) ? null : new User($row);
 	}

core/util.inc.php

@@ -1344,12 +1344,13 @@ function get_debug_info() {
 	else {
 		$commit = " (".$config->get_string("commit_hash").")";
 	}
-	$time = sprintf("%5.2f", microtime(true) - $_load_start);
+	$time = sprintf("%.2f", microtime(true) - $_load_start);
+	$dbtime = sprintf("%.2f", $database->dbtime);
 	$i_files = count(get_included_files());
 	$hits = $database->cache->get_hits();
 	$miss = $database->cache->get_misses();
 
-	$debug = "<br>Took $time seconds and {$i_mem}MB of RAM";
+	$debug = "<br>Took $time seconds (db:$dbtime) and {$i_mem}MB of RAM";
 	$debug .= "; Used $i_files files and $_execs queries";
 	$debug .= "; Sent $_event_count events";
 	$debug .= "; $hits cache hits and $miss misses";

ext/featured/main.php

@@ -60,13 +60,13 @@ class Featured extends Extension {
 		global $config, $database, $page, $user;
 		$fid = $config->get_int("featured_id");
 		if($fid > 0) {
-			$image = $database->cache->get("featured_image_object-$fid");
+			$image = $database->cache->get("featured_image_object:$fid");
 			if($image === false) {
 				$image = Image::by_id($fid);
 				if($image) { // make sure the object is fully populated before saving
 					$image->get_tag_array();
 				}
-				$database->cache->set("featured_image_object-$fid", $image, 600);
+				$database->cache->set("featured_image_object:$fid", $image, 600);
 			}
 			if(!is_null($image)) {
 				if(class_exists("Ratings")) {

ext/index/main.php

@@ -260,10 +260,10 @@ class Index extends Extension {
 				#log_debug("index", "Search for ".implode(" ", $search_terms), false, array("terms"=>$search_terms));
 				$total_pages = Image::count_pages($search_terms);
 				if(SPEED_HAX && $count_search_terms === 0 && ($page_number < 10)) { // extra caching for the first few post/list pages
-					$images = $database->cache->get("post-list-$page_number");
+					$images = $database->cache->get("post-list:$page_number");
 					if(!$images) {
 						$images = Image::find_images(($page_number-1)*$page_size, $page_size, $search_terms);
-						$database->cache->set("post-list-$page_number", $images, 600);
+						$database->cache->set("post-list:$page_number", $images, 600);
 					}
 				}
 				else {

ext/pm/main.php

@@ -197,7 +197,7 @@ class PrivMsg extends Extension {
 	private function count_pms(User $user) {
 		global $database;
 
-		$count = $database->cache->get("pm-count-{$user->id}");
+		$count = $database->cache->get("pm-count:{$user->id}");
 		if(is_null($count) || $count === false) {
 			$count = $database->get_one("
 					SELECT count(*)
@@ -205,7 +205,7 @@ class PrivMsg extends Extension {
 					WHERE to_id = :to_id
 					AND is_read = :is_read
 			", array("to_id" => $user->id, "is_read" => "N"));
-			$database->cache->set("pm-count-{$user->id}", $count, 600);
+			$database->cache->set("pm-count:{$user->id}", $count, 600);
 		}
 		return $count;
 	}

ext/statsd/main.php

@@ -23,6 +23,7 @@ class StatsDInterface extends Extension {
 		$time = microtime(true) - $_load_start;
 		StatsDInterface::$stats["shimmie.$type.hits"] = "1|c";
 		StatsDInterface::$stats["shimmie.$type.time"] = "$time|ms";
+		StatsDInterface::$stats["shimmie.$type.time-db"] = "{$database->dbtime}|ms";
 		StatsDInterface::$stats["shimmie.$type.memory"] = memory_get_peak_usage(true)."|c";
 		StatsDInterface::$stats["shimmie.$type.files"] = count(get_included_files())."|c";
 		StatsDInterface::$stats["shimmie.$type.queries"] = $_execs."|c";

lib/context.php

@@ -20,7 +20,7 @@ function ctx_log_msg($func, $text, $type) {
             microtime(true), # returning a float is 5.0+
             php_uname('n'),  # gethostname() is 5.3+
 			posix_getpid(),
-			posix_getpid(), //gettid(),
+			function_exists("hphp_get_thread_id") ? hphp_get_thread_id() : posix_getpid(),
             $type, $func, $text
         );
 	}