Improve photo loading speed

database.sql

@@ -1,6 +1,6 @@
 -- ------------------------------------------
--- Friendica 2020.12-dev (Red Hot Poker)
+-- Friendica 2020.12-rc (Red Hot Poker)
--- DB_UPDATE_VERSION 1383
+-- DB_UPDATE_VERSION 1384
 -- ------------------------------------------
 
 
@@ -1045,6 +1045,7 @@ CREATE TABLE IF NOT EXISTS `photo` (
 	`contact-id` int unsigned NOT NULL DEFAULT 0 COMMENT 'contact.id',
 	`guid` char(16) NOT NULL DEFAULT '' COMMENT 'A unique identifier for this photo',
 	`resource-id` char(32) NOT NULL DEFAULT '' COMMENT '',
+	`hash` char(32) COMMENT 'hash value of the photo',
 	`created` datetime NOT NULL DEFAULT '0001-01-01 00:00:00' COMMENT 'creation date',
 	`edited` datetime NOT NULL DEFAULT '0001-01-01 00:00:00' COMMENT 'last edited date',
 	`title` varchar(255) NOT NULL DEFAULT '' COMMENT '',
@@ -1772,5 +1773,3 @@ CREATE VIEW `workerqueue-view` AS SELECT
 	FROM `process`
 			INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid`
 			WHERE NOT `workerqueue`.`done`;
-
-

src/Database/PostUpdate.php

@@ -98,6 +98,9 @@ class PostUpdate
 		if (!self::update1383()) {
 			return false;
 		}
+		if (!self::update1384()) {
+			return false;
+		}
 
 		return true;
 	}
@@ -115,7 +118,7 @@ class PostUpdate
 			return true;
 		}
 
-		Logger::log("Start", Logger::DEBUG);
+		Logger::info("Start");
 
 		$end_id = DI::config()->get("system", "post_update_1194_end");
 		if (!$end_id) {
@@ -126,7 +129,7 @@ class PostUpdate
 			}
 		}
 
-		Logger::log("End ID: ".$end_id, Logger::DEBUG);
+		Logger::info("End ID: ".$end_id);
 
 		$start_id = DI::config()->get("system", "post_update_1194_start");
 
@@ -145,14 +148,14 @@ class PostUpdate
 			DBA::escape(Protocol::DFRN), DBA::escape(Protocol::DIASPORA), DBA::escape(Protocol::OSTATUS));
 		if (!$r) {
 			DI::config()->set("system", "post_update_version", 1194);
-			Logger::log("Update is done", Logger::DEBUG);
+			Logger::info("Update is done");
 			return true;
 		} else {
 			DI::config()->set("system", "post_update_1194_start", $r[0]["id"]);
 			$start_id = DI::config()->get("system", "post_update_1194_start");
 		}
 
-		Logger::log("Start ID: ".$start_id, Logger::DEBUG);
+		Logger::info("Start ID: ".$start_id);
 
 		$r = q($query1.$query2.$query3."  ORDER BY `item`.`id` LIMIT 1000,1",
 			intval($start_id), intval($end_id),
@@ -162,13 +165,13 @@ class PostUpdate
 		} else {
 			$pos_id = $end_id;
 		}
-		Logger::log("Progress: Start: ".$start_id." position: ".$pos_id." end: ".$end_id, Logger::DEBUG);
+		Logger::info("Progress: Start: ".$start_id." position: ".$pos_id." end: ".$end_id);
 
 		q("UPDATE `item` ".$query2." SET `item`.`global` = 1 ".$query3,
 			intval($start_id), intval($pos_id),
 			DBA::escape(Protocol::DFRN), DBA::escape(Protocol::DIASPORA), DBA::escape(Protocol::OSTATUS));
 
-		Logger::log("Done", Logger::DEBUG);
+		Logger::info("Done");
 	}
 
 	/**
@@ -186,7 +189,7 @@ class PostUpdate
 			return true;
 		}
 
-		Logger::log("Start", Logger::DEBUG);
+		Logger::info("Start");
 		$r = q("SELECT `contact`.`id`, `contact`.`last-item`,
 			(SELECT MAX(`changed`) FROM `item` USE INDEX (`uid_wall_changed`) WHERE `wall` AND `uid` = `user`.`uid`) AS `lastitem_date`
 			FROM `user`
@@ -202,7 +205,7 @@ class PostUpdate
 		}
 
 		DI::config()->set("system", "post_update_version", 1206);
-		Logger::log("Done", Logger::DEBUG);
+		Logger::info("Done");
 		return true;
 	}
 
@@ -222,7 +225,7 @@ class PostUpdate
 
 		$id = DI::config()->get("system", "post_update_version_1279_id", 0);
 
-		Logger::log("Start from item " . $id, Logger::DEBUG);
+		Logger::info("Start from item " . $id);
 
 		$fields = array_merge(Item::MIXED_CONTENT_FIELDLIST, ['network', 'author-id', 'owner-id', 'tag', 'file',
 			'author-name', 'author-avatar', 'author-link', 'owner-name', 'owner-avatar', 'owner-link', 'id',
@@ -236,7 +239,7 @@ class PostUpdate
 		$items = Item::select($fields, $condition, $params);
 
 		if (DBA::errorNo() != 0) {
-			Logger::log('Database error ' . DBA::errorNo() . ':' . DBA::errorMessage());
+			Logger::info('Database error ' . DBA::errorNo() . ':' . DBA::errorMessage());
 			return false;
 		}
 
@@ -297,7 +300,7 @@ class PostUpdate
 
 		DI::config()->set("system", "post_update_version_1279_id", $id);
 
-		Logger::log("Processed rows: " . $rows . " - last processed item:  " . $id, Logger::DEBUG);
+		Logger::info("Processed rows: " . $rows . " - last processed item:  " . $id);
 
 		if ($start_id == $id) {
 			// Set all deprecated fields to "null" if they contain an empty string
@@ -309,13 +312,13 @@ class PostUpdate
 			foreach ($nullfields as $field) {
 				$fields = [$field => null];
 				$condition = [$field => ''];
-				Logger::log("Setting '" . $field . "' to null if empty.", Logger::DEBUG);
+				Logger::info("Setting '" . $field . "' to null if empty.");
 				// Important: This has to be a "DBA::update", not a "Item::update"
 				DBA::update('item', $fields, $condition);
 			}
 
 			DI::config()->set("system", "post_update_version", 1279);
-			Logger::log("Done", Logger::DEBUG);
+			Logger::info("Done");
 			return true;
 		}
 
@@ -379,7 +382,7 @@ class PostUpdate
 
 		$id = DI::config()->get("system", "post_update_version_1281_id", 0);
 
-		Logger::log("Start from item " . $id, Logger::DEBUG);
+		Logger::info("Start from item " . $id);
 
 		$fields = ['id', 'guid', 'uri', 'uri-id', 'parent-uri', 'parent-uri-id', 'thr-parent', 'thr-parent-id'];
 
@@ -390,7 +393,7 @@ class PostUpdate
 		$items = DBA::select('item', $fields, $condition, $params);
 
 		if (DBA::errorNo() != 0) {
-			Logger::log('Database error ' . DBA::errorNo() . ':' . DBA::errorMessage());
+			Logger::info('Database error ' . DBA::errorNo() . ':' . DBA::errorMessage());
 			return false;
 		}
 
@@ -431,17 +434,17 @@ class PostUpdate
 
 		DI::config()->set("system", "post_update_version_1281_id", $id);
 
-		Logger::log("Processed rows: " . $rows . " - last processed item:  " . $id, Logger::DEBUG);
+		Logger::info("Processed rows: " . $rows . " - last processed item:  " . $id);
 
 		if ($start_id == $id) {
-			Logger::log("Updating item-uri in item-activity", Logger::DEBUG);
+			Logger::info("Updating item-uri in item-activity");
 			DBA::e("UPDATE `item-activity` INNER JOIN `item-uri` ON `item-uri`.`uri` = `item-activity`.`uri` SET `item-activity`.`uri-id` = `item-uri`.`id` WHERE `item-activity`.`uri-id` IS NULL");
 
-			Logger::log("Updating item-uri in item-content", Logger::DEBUG);
+			Logger::info("Updating item-uri in item-content");
 			DBA::e("UPDATE `item-content` INNER JOIN `item-uri` ON `item-uri`.`uri` = `item-content`.`uri` SET `item-content`.`uri-id` = `item-uri`.`id` WHERE `item-content`.`uri-id` IS NULL");
 
 			DI::config()->set("system", "post_update_version", 1281);
-			Logger::log("Done", Logger::DEBUG);
+			Logger::info("Done");
 			return true;
 		}
 
@@ -1019,6 +1022,7 @@ class PostUpdate
 
 		return false;
 	}
+
 	/**
 	 * Remove orphaned photo entries
 	 *
@@ -1059,4 +1063,52 @@ class PostUpdate
 		Logger::info('Done', ['deleted' => $deleted]);
 		return true;
 	}
+
+	/**
+	 * update the "hash" field in the photo table
+	 *
+	 * @return bool "true" when the job is done
+	 * @throws \Friendica\Network\HTTPException\InternalServerErrorException
+	 * @throws \ImagickException
+	 */
+	private static function update1384()
+	{
+		// Was the script completed?
+		if (DI::config()->get("system", "post_update_version") >= 1384) {
+			return true;
+		}
+
+		$condition = ["`hash` IS NULL"];
+		Logger::info('Start', ['rest' => DBA::count('photo', $condition)]);
+
+		$rows = 0;
+		$photos = DBA::select('photo', [], $condition, ['limit' => 10000]);
+
+		if (DBA::errorNo() != 0) {
+			Logger::error('Database error', ['no' => DBA::errorNo(), 'message' => DBA::errorMessage()]);
+			return false;
+		}
+
+		while ($photo = DBA::fetch($photos)) {
+			$img = Photo::getImageForPhoto($photo);
+			if (!empty($img)) {
+				$md5 = md5($img->asString());
+			} else {
+				$md5 = '';
+			}
+			DBA::update('photo', ['hash' => $md5], ['id' => $photo['id']]);
+			++$rows;
+		}
+		DBA::close($photos);
+
+		Logger::info('Processed', ['rows' => $rows]);
+
+		if ($rows <= 100) {
+			DI::config()->set("system", "post_update_version", 1384);
+			Logger::info('Done');
+			return true;
+		}
+
+		return false;
+	}
 }

src/Database/View.php

@@ -117,11 +117,11 @@ class View
 			$sql = sprintf("DROP TABLE IF EXISTS `%s`", DBA::escape($name));
 		}
 
-		if ($verbose) {
+		if (!empty($sql) && $verbose) {
 			echo $sql . ";\n";
 		}
 
-		if ($action) {
+		if (!empty($sql) && $action) {
 			DBA::e($sql);
 		}
 

src/Model/Photo.php

@@ -305,6 +305,7 @@ class Photo
 			"contact-id" => $cid,
 			"guid" => $guid,
 			"resource-id" => $rid,
+			"hash" => md5($Image->asString()),
 			"created" => $created,
 			"edited" => DateTimeFormat::utcNow(),
 			"filename" => basename($filename),

src/Module/Conversation/Network.php

@@ -218,6 +218,7 @@ class Network extends BaseModule
 		$unseen = Item::exists($condition);
 
 		if ($unseen) {
+			/// @todo handle huge "unseen" updates in the background to avoid timeout errors
 			Item::update(['unseen' => false], $condition);
 		}
 	}

src/Module/Photo.php

@@ -40,8 +40,9 @@ class Photo extends BaseModule
 	 * Fetch a photo or an avatar, in optional size, check for permissions and
 	 * return the image
 	 */
-	public static function init(array $parameters = [])
+	public static function rawContent(array $parameters = [])
 	{
+		$totalstamp = microtime(true);
 		$a = DI::app();
 		// @TODO: Replace with parameter from router
 		if ($a->argc <= 1 || $a->argc > 4) {
@@ -66,7 +67,9 @@ class Photo extends BaseModule
 
 		$customsize = 0;
 		$photo = false;
+		$scale = null;
 		// @TODO: Replace with parameter from router
+		$stamp = microtime(true);
 		switch($a->argc) {
 			case 4:
 				$customsize = intval($a->argv[2]);
@@ -90,6 +93,7 @@ class Photo extends BaseModule
 				}
 				break;
 		}
+		$fetch = microtime(true) - $stamp;
 
 		if ($photo === false) {
 			throw new \Friendica\Network\HTTPException\NotFoundException();
@@ -97,10 +101,12 @@ class Photo extends BaseModule
 
 		$cacheable = ($photo["allow_cid"] . $photo["allow_gid"] . $photo["deny_cid"] . $photo["deny_gid"] === "") && (isset($photo["cacheable"]) ? $photo["cacheable"] : true);
 
+		$stamp = microtime(true);
 		$img = MPhoto::getImageForPhoto($photo);
+		$data = microtime(true) - $stamp;
 
 		if (is_null($img) || !$img->isValid()) {
-			Logger::log("Invalid photo with id {$photo["id"]}.");
+			Logger::warning("Invalid photo with id {$photo["id"]}.");
 			throw new \Friendica\Network\HTTPException\InternalServerErrorException(DI::l10n()->t('Invalid photo with id %s.', $photo["id"]));
 		}
 
@@ -116,20 +122,34 @@ class Photo extends BaseModule
 
 		header("Content-type: " . $img->getType());
 
+		$stamp = microtime(true);
 		if (!$cacheable) {
 			// it is a private photo that they have no permission to view.
 			// tell the browser not to cache it, in case they authenticate
 			// and subsequently have permission to see it
 			header("Cache-Control: no-store, no-cache, must-revalidate");
 		} else {
-			$md5 = md5($img->asString());
+			$md5 = $photo['hash'] ?: md5($img->asString());
 			header("Last-Modified: " . gmdate("D, d M Y H:i:s", time()) . " GMT");
 			header("Etag: \"{$md5}\"");
 			header("Expires: " . gmdate("D, d M Y H:i:s", time() + (31536000)) . " GMT");
 			header("Cache-Control: max-age=31536000");
 		}
+		$checksum = microtime(true) - $stamp;
 
+		$stamp = microtime(true);
 		echo $img->asString();
+		$output = microtime(true) - $stamp;
+
+		$total = microtime(true) - $totalstamp;
+		$rest = $total - ($fetch + $data + $checksum + $output);
+
+		if (!is_null($scale) && ($scale < 4)) {
+			Logger::info('Performance:', ['scale' => $scale, 'resource' => $photo['resource-id'],
+				'total' => number_format($total, 3), 'fetch' => number_format($fetch, 3),
+				'data' => number_format($data, 3), 'checksum' => number_format($checksum, 3),
+				'output' => number_format($output, 3), 'rest' => number_format($rest, 3)]);
+		}
 
 		exit();
 	}

static/dbstructure.config.php

@@ -55,7 +55,7 @@
 use Friendica\Database\DBA;
 
 if (!defined('DB_UPDATE_VERSION')) {
-	define('DB_UPDATE_VERSION', 1383);
+	define('DB_UPDATE_VERSION', 1384);
 }
 
 return [
@@ -1101,6 +1101,7 @@ return [
 			"contact-id" => ["type" => "int unsigned", "not null" => "1", "default" => "0", "foreign" => ["contact" => "id", "on delete" => "restrict"], "comment" => "contact.id"],
 			"guid" => ["type" => "char(16)", "not null" => "1", "default" => "", "comment" => "A unique identifier for this photo"],
 			"resource-id" => ["type" => "char(32)", "not null" => "1", "default" => "", "comment" => ""],
+			"hash" => ["type" => "char(32)", "comment" => "hash value of the photo"],
 			"created" => ["type" => "datetime", "not null" => "1", "default" => DBA::NULL_DATETIME, "comment" => "creation date"],
 			"edited" => ["type" => "datetime", "not null" => "1", "default" => DBA::NULL_DATETIME, "comment" => "last edited date"],
 			"title" => ["type" => "varchar(255)", "not null" => "1", "default" => "", "comment" => ""],