even more tracing

4 files changed, 33 insertions, 44 deletions

diff --git a/classes/digest.php b/classes/digest.php
index b19c37c5f..d77a83b8c 100644
--- a/classes/digest.php
+++ b/classes/digest.php
@@ -2,6 +2,7 @@
 class Digest
 {
 	static function send_headlines_digests(): void {
+		$scope = Tracer::start(__METHOD__);
 
 		$user_limit = 15; // amount of users to process (e.g. emails to send out)
 		$limit = 1000; // maximum amount of headlines to include
@@ -75,6 +76,8 @@ class Digest
 				}
 			}
 		}
+
+		$scope->close();
 		Debug::log("All done.");
 	}
 
diff --git a/classes/feeds.php b/classes/feeds.php
index 56bf7fc92..68619302f 100755
--- a/classes/feeds.php
+++ b/classes/feeds.php
@@ -49,12 +49,6 @@ class Feeds extends Handler_Protected {
 	const NEVER_GROUP_FEEDS = [ Feeds::FEED_RECENTLY_READ, Feeds::FEED_ARCHIVED ];
 	const NEVER_GROUP_BY_DATE = [ Feeds::FEED_PUBLISHED, Feeds::FEED_STARRED, Feeds::FEED_FRESH ];
 
-	/** @var int|float int on 64-bit, float on 32-bit */
-	private $viewfeed_timestamp;
-
-	/** @var int|float int on 64-bit, float on 32-bit */
-	private $viewfeed_timestamp_last;
-
 	function csrf_ignore(string $method): bool {
 		$csrf_ignored = array("index");
 
@@ -281,8 +275,6 @@ class Feeds extends Handler_Protected {
 					array_push($topmost_article_ids, $id);
 				}
 
-				$this->_mark_timestamp("   labels");
-
 				$line["feed_title"] = $line["feed_title"] ?? "";
 
 				$button_doc = new DOMDocument();
@@ -358,16 +350,12 @@ class Feeds extends Handler_Protected {
 					$line["enclosures"] = [ 'formatted' => '', 'entries' => [] ];
 				}
 
-				$this->_mark_timestamp("   enclosures");
-
 				$line["updated_long"] = TimeHelper::make_local_datetime($line["updated"],true);
 				$line["updated"] = TimeHelper::make_local_datetime($line["updated"], false, null, false, true);
 
 				$line['imported'] = T_sprintf("Imported at %s",
 					TimeHelper::make_local_datetime($line["date_entered"], false));
 
-				$this->_mark_timestamp("   local-datetime");
-
 				if ($line["tag_cache"])
 					$tags = explode(",", $line["tag_cache"]);
 				else
@@ -377,14 +365,12 @@ class Feeds extends Handler_Protected {
 
 				//$line["tags"] = Article::_get_tags($line["id"], false, $line["tag_cache"]);
 
-				$this->_mark_timestamp("   tags");
-
 				$line['has_icon'] = self::_has_icon($feed_id);
 
 			    //setting feed headline background color, needs to change text color based on dark/light
 				$fav_color = $line['favicon_avg_color'] ?? false;
 
-				$this->_mark_timestamp("   pre-color");
+				$c_scope = Tracer::start('colors');
 
 				require_once "colors.php";
 
@@ -400,22 +386,16 @@ class Feeds extends Handler_Protected {
 				    $line['feed_bg_color'] = 'rgba(' . implode(",", $rgba_cache[$feed_id]) . ',0.3)';
 				}
 
-				$this->_mark_timestamp("   color");
-				$this->_mark_timestamp("   pre-hook_render_cdm");
+				$c_scope->close();
 
 				PluginHost::getInstance()->chain_hooks_callback(PluginHost::HOOK_RENDER_ARTICLE_CDM,
 					function ($result, $plugin) use (&$line) {
 						$line = $result;
-						$this->_mark_timestamp("       hook: " . get_class($plugin));
 					},
 					$line);
 
-				$this->_mark_timestamp("   hook_render_cdm");
-
 				$line['content'] = DiskCache::rewrite_urls($line['content']);
 
-				$this->_mark_timestamp("   disk_cache_rewrite");
-
 				/* we don't need those */
 
 				foreach (["date_entered", "guid", "last_published", "last_marked", "tag_cache", "favicon_avg_color",
@@ -430,8 +410,6 @@ class Feeds extends Handler_Protected {
 
 		$a_scope->close();
 
-		$this->_mark_timestamp("end of articles");
-
 		if (!$headlines_count) {
 
 			if ($result instanceof PDOStatement) {
@@ -2503,23 +2481,5 @@ class Feeds extends Handler_Protected {
 		return [$query, $skip_first_id];
 	}
 
-	private function _mark_timestamp(string $label): void {
-
-		if (empty($_REQUEST['timestamps']))
-			return;
-
-		if (!$this->viewfeed_timestamp) $this->viewfeed_timestamp = hrtime(true);
-		if (!$this->viewfeed_timestamp_last) $this->viewfeed_timestamp_last = hrtime(true);
-
-		$timestamp = hrtime(true);
-
-		printf("[%4d ms, %4d abs] %s\n",
-			($timestamp - $this->viewfeed_timestamp_last) / 1e6,
-			($timestamp - $this->viewfeed_timestamp) / 1e6,
-			$label);
-
-		$this->viewfeed_timestamp_last = $timestamp;
-	}
-
 }
 
diff --git a/classes/pluginhost.php b/classes/pluginhost.php
index de2bc84e5..09c8b1671 100755
--- a/classes/pluginhost.php
+++ b/classes/pluginhost.php
@@ -344,6 +344,8 @@ class PluginHost {
 		foreach ($this->get_hooks((string)$hook) as $plugin) {
 			//Debug::log("invoking: " . get_class($plugin) . "->$hook()", Debug::$LOG_VERBOSE);
 
+			$p_scope = Tracer::start("$hook - " . get_class($plugin));
+
 			try {
 				if ($callback($plugin->$method(...$args), $plugin))
 					break;
@@ -352,6 +354,8 @@ class PluginHost {
 			} catch (Error $err) {
 				user_error($err, E_USER_WARNING);
 			}
+
+			$p_scope->close();
 		}
 
 		$scope->close();
@@ -444,7 +448,7 @@ class PluginHost {
 			$class = trim($class);
 			$class_file = strtolower(basename(clean($class)));
 
-			$p_scope = Tracer::start('load_plugin', ['file' => $class_file]);
+			$p_scope = Tracer::start("loading $class_file");
 
 			// try system plugin directory first
 			$file = dirname(__DIR__) . "/plugins/$class_file/init.php";
@@ -507,6 +511,8 @@ class PluginHost {
 						_bind_textdomain_codeset($class, "UTF-8");
 					}
 
+					$i_scope = Tracer::start('init and register plugin');
+
 					try {
 						switch ($kind) {
 							case $this::KIND_SYSTEM:
@@ -532,6 +538,8 @@ class PluginHost {
 						user_error($err, E_USER_WARNING);
 					}
 
+					$i_scope->close();
+
 				}
 			}
 			$p_scope->close();
diff --git a/classes/rssutils.php b/classes/rssutils.php
index 53ad694a8..702675661 100755
--- a/classes/rssutils.php
+++ b/classes/rssutils.php
@@ -68,6 +68,8 @@ class RSSUtils {
 	 * @param array<string, false|string> $options
 	 */
 	static function update_daemon_common(int $limit = 0, array $options = []): int {
+		$scope = Tracer::start(__METHOD__);
+
 		if (!$limit) $limit = Config::get(Config::DAEMON_FEED_LIMIT);
 
 		if (Config::get_schema_version() != Config::SCHEMA_VERSION) {
@@ -283,6 +285,8 @@ class RSSUtils {
 		// Send feed digests by email if needed.
 		Digest::send_headlines_digests();
 
+		$scope->close();
+
 		return $nf;
 	}
 
@@ -349,6 +353,7 @@ class RSSUtils {
 
 	static function update_rss_feed(int $feed, bool $no_cache = false) : bool {
 
+		$scope = Tracer::start(__METHOD__, [], func_get_args());
 		Debug::log("start", Debug::LOG_VERBOSE);
 
 		$pdo = Db::pdo();
@@ -383,16 +388,19 @@ class RSSUtils {
 			if ($user) {
 				if ($user->access_level == UserHelper::ACCESS_LEVEL_READONLY) {
 					Debug::log("error: denied update for $feed: permission denied by owner access level");
+					$scope->close();
 					return false;
 				}
 			} else {
 				// this would indicate database corruption of some kind
 				Debug::log("error: owner not found for feed: $feed");
+				$scope->close();
 				return false;
 			}
 
 		} else {
 			Debug::log("error: feeds table record not found for feed: $feed");
+			$scope->close();
 			return false;
 		}
 
@@ -550,6 +558,7 @@ class RSSUtils {
 				$feed_obj->save();
 			}
 
+			$scope->close();
 			return $error_message == "";
 		}
 
@@ -675,7 +684,7 @@ class RSSUtils {
 				]);
 
 				$feed_obj->save();
-
+				$scope->close();
 				return true; // no articles
 			}
 
@@ -684,6 +693,8 @@ class RSSUtils {
 			$tstart = time();
 
 			foreach ($items as $item) {
+				$a_scope = Tracer::start('article');
+
 				$pdo->beginTransaction();
 
 				Debug::log("=================================================================================================================================",
@@ -1276,6 +1287,7 @@ class RSSUtils {
 				Debug::log("article processed.", Debug::LOG_VERBOSE);
 
 				$pdo->commit();
+				$a_scope->close();
 			}
 
 			Debug::log("=================================================================================================================================",
@@ -1317,10 +1329,12 @@ class RSSUtils {
 			unset($rss);
 
 			Debug::log("update failed.", Debug::LOG_VERBOSE);
+			$scope->close();
 			return false;
 		}
 
 		Debug::log("update done.", Debug::LOG_VERBOSE);
+		$scope->close();
 		return true;
 	}
 
@@ -1485,6 +1499,8 @@ class RSSUtils {
 	 * @return array<int, array<string, string>> An array of filter action arrays with keys "type" and "param"
 	 */
 	static function get_article_filters(array $filters, string $title, string $content, string $link, string $author, array $tags, array &$matched_rules = null, array &$matched_filters = null): array {
+		$scope = Tracer::start(__METHOD__);
+
 		$matches = array();
 
 		foreach ($filters as $filter) {
@@ -1567,6 +1583,8 @@ class RSSUtils {
 			}
 		}
 
+		$scope->close();
+
 		return $matches;
 	}