more tracing

8 files changed, 92 insertions, 31 deletions

diff --git a/classes/article.php b/classes/article.php
index 10833cc8d..f4c271118 100755
--- a/classes/article.php
+++ b/classes/article.php
@@ -298,6 +298,8 @@ class Article extends Handler_Protected {
 	 * @return array{'formatted': string, 'entries': array<int, array<string, mixed>>}
 	 */
 	static function _format_enclosures(int $id, bool $always_display_enclosures, string $article_content, bool $hide_images = false): array {
+		$scope = Tracer::start(__METHOD__);
+
 		$enclosures = self::_get_enclosures($id);
 		$enclosures_formatted = "";
 
@@ -324,6 +326,7 @@ class Article extends Handler_Protected {
 			$enclosures_formatted, $enclosures, $id, $always_display_enclosures, $article_content, $hide_images);
 
 		if (!empty($enclosures_formatted)) {
+			$scope->close();
 			return [
 					'formatted' => $enclosures_formatted,
 					'entries' => []
@@ -367,6 +370,7 @@ class Article extends Handler_Protected {
 			}
 		}
 
+		$scope->close();
 		return $rv;
 	}
 
@@ -374,6 +378,7 @@ class Article extends Handler_Protected {
 	 * @return array<int, string>
 	 */
 	static function _get_tags(int $id, int $owner_uid = 0, ?string $tag_cache = null): array {
+		$scope = Tracer::start(__METHOD__);
 
 		$a_id = $id;
 
@@ -422,6 +427,7 @@ class Article extends Handler_Protected {
 			$sth->execute([$tags_str, $id, $owner_uid]);
 		}
 
+		$scope->close();
 		return $tags;
 	}
 
@@ -516,6 +522,8 @@ class Article extends Handler_Protected {
 	 * @return array<int, array<int, int|string>>
 	 */
 	static function _get_labels(int $id, ?int $owner_uid = null): array {
+		$scope = Tracer::start(__METHOD__, []);
+
 		$rv = array();
 
 		if (!$owner_uid) $owner_uid = $_SESSION["uid"];
@@ -561,6 +569,8 @@ class Article extends Handler_Protected {
 		else
 			Labels::update_cache($owner_uid, $id, array("no-labels" => 1));
 
+		$scope->close();
+
 		return $rv;
 	}
 
diff --git a/classes/counters.php b/classes/counters.php
index 378abac89..fcf28f938 100644
--- a/classes/counters.php
+++ b/classes/counters.php
@@ -145,7 +145,7 @@ class Counters {
 	 * @return array<int, array<string, int|string>>
 	 */
 	private static function get_feeds(array $feed_ids = null): array {
-		$scope = Tracer::start(__FUNCTION__);
+		$scope = Tracer::start(__METHOD__);
 
 		$ret = [];
 
@@ -221,7 +221,7 @@ class Counters {
 	 * @return array<int, array<string, int|string>>
 	 */
 	private static function get_global(): array {
-		$scope = Tracer::start(__FUNCTION__);
+		$scope = Tracer::start(__METHOD__);
 
 		$ret = [
 			[
@@ -248,7 +248,7 @@ class Counters {
 	 * @return array<int, array<string, int|string>>
 	 */
 	private static function get_virt(): array {
-		$scope = Tracer::start(__FUNCTION__);
+		$scope = Tracer::start(__METHOD__);
 
 		$ret = [];
 
@@ -304,7 +304,7 @@ class Counters {
 	 * @return array<int, array<string, int|string>>
 	 */
 	static function get_labels(array $label_ids = null): array {
-		$scope = Tracer::start(__FUNCTION__);
+		$scope = Tracer::start(__METHOD__);
 
 		$ret = [];
 
diff --git a/classes/diskcache.php b/classes/diskcache.php
index 0965c4388..f53b6caad 100644
--- a/classes/diskcache.php
+++ b/classes/diskcache.php
@@ -221,7 +221,11 @@ class DiskCache implements Cache_Adapter {
 	}
 
 	public function remove(string $filename): bool {
-		return $this->adapter->remove($filename);
+		$scope = Tracer::start(__METHOD__);
+		$rc = $this->adapter->remove($filename);
+		$scope->close();
+
+		return $rc;
 	}
 
 	public function set_dir(string $dir) : void {
@@ -244,7 +248,11 @@ class DiskCache implements Cache_Adapter {
 	}
 
 	public function exists(string $filename): bool {
-		return $this->adapter->exists(basename($filename));
+		$scope = Tracer::start(__METHOD__);
+		$rc = $this->adapter->exists(basename($filename));
+		$scope->close();
+
+		return $rc;
 	}
 
 	/**
@@ -260,7 +268,11 @@ class DiskCache implements Cache_Adapter {
 	 * @return int|false Bytes written or false if an error occurred.
 	 */
 	public function put(string $filename, $data) {
-		return $this->adapter->put(basename($filename), $data);
+		$scope = Tracer::start(__METHOD__);
+		$rc = $this->adapter->put(basename($filename), $data);
+		$scope->close();
+
+		return $rc;
 	}
 
 	/** @deprecated we can't assume cached files are local, and other storages
@@ -304,7 +316,7 @@ class DiskCache implements Cache_Adapter {
 	}
 
 	public function send(string $filename) {
-		$scope = Tracer::start(__FUNCTION__, ['filename' => $filename]);
+		$scope = Tracer::start(__METHOD__, ['filename' => $filename]);
 
 		$filename = basename($filename);
 
@@ -401,8 +413,14 @@ class DiskCache implements Cache_Adapter {
 	// plugins work on original source URLs used before caching
 	// NOTE: URLs should be already absolutized because this is called after sanitize()
 	static public function rewrite_urls(string $str): string {
+		$scope = Tracer::start(__METHOD__);
+
 		$res = trim($str);
-		if (!$res) return '';
+
+		if (!$res) {
+			$scope->close();
+			return '';
+		}
 
 		$doc = new DOMDocument();
 		if (@$doc->loadHTML('<?xml encoding="UTF-8">' . $res)) {
@@ -414,6 +432,8 @@ class DiskCache implements Cache_Adapter {
 			$need_saving = false;
 
 			foreach ($entries as $entry) {
+				$e_scope = Tracer::start('entry', ['tagName' => $entry->tagName]);
+
 				foreach (array('src', 'poster') as $attr) {
 					if ($entry->hasAttribute($attr)) {
 						$url = $entry->getAttribute($attr);
@@ -445,6 +465,8 @@ class DiskCache implements Cache_Adapter {
 
 					$entry->setAttribute("srcset", RSSUtils::encode_srcset($matches));
 				}
+
+				$e_scope->close();
 			}
 
 			if ($need_saving) {
@@ -454,6 +476,9 @@ class DiskCache implements Cache_Adapter {
 				$res = $doc->saveHTML();
 			}
 		}
+
+		$scope->close();
+
 		return $res;
 	}
 }
diff --git a/classes/feeds.php b/classes/feeds.php
index 9707d5e45..56bf7fc92 100755
--- a/classes/feeds.php
+++ b/classes/feeds.php
@@ -71,7 +71,7 @@ class Feeds extends Handler_Protected {
 
 		$disable_cache = false;
 
-		$this->_mark_timestamp("init");
+		$scope = Tracer::start(__METHOD__, [], func_get_args());
 
 		$reply = [];
 		$rgba_cache = [];
@@ -157,8 +157,6 @@ class Feeds extends Handler_Protected {
 			$qfh_ret = $this->_get_headlines($params);
 		}
 
-		$this->_mark_timestamp("db query");
-
 		$vfeed_group_enabled = get_pref(Prefs::VFEED_GROUP_BY_FEED) &&
 			!(in_array($feed, self::NEVER_GROUP_FEEDS) && !$cat_view);
 
@@ -176,6 +174,8 @@ class Feeds extends Handler_Protected {
 		$reply['search_query'] = [$search, $search_language];
 		$reply['vfeed_group_enabled'] = $vfeed_group_enabled;
 
+		$p_scope = Tracer::start('plugin_menu_items');
+
 		$plugin_menu_items = "";
 		PluginHost::getInstance()->chain_hooks_callback(PluginHost::HOOK_HEADLINE_TOOLBAR_SELECT_MENU_ITEM2,
 			function ($result) use (&$plugin_menu_items) {
@@ -208,13 +208,15 @@ class Feeds extends Handler_Protected {
 					},
 					$feed, $cat_view, $qfh_ret);
 
-		$this->_mark_timestamp("object header");
+		$p_scope->close();
+
+		$a_scope = Tracer::start('articles');
 
 		$headlines_count = 0;
 
 		if ($result instanceof PDOStatement) {
 			while ($line = $result->fetch(PDO::FETCH_ASSOC)) {
-				$this->_mark_timestamp("article start: " . $line["id"] . " " . $line["title"]);
+				$aa_scope = Tracer::start('article', ['id' => $line['id']]);
 
 				++$headlines_count;
 
@@ -232,8 +234,6 @@ class Feeds extends Handler_Protected {
 						$line, $max_excerpt_length);
 				}
 
-				$this->_mark_timestamp("   hook_query_headlines");
-
 				$id = $line["id"];
 
 				// frontend doesn't expect pdo returning booleans as strings on mysql
@@ -312,6 +312,7 @@ class Feeds extends Handler_Protected {
 					$line);
 
 				$line["buttons"] = "";
+
 				PluginHost::getInstance()->chain_hooks_callback(PluginHost::HOOK_ARTICLE_BUTTON,
 					function ($result, $plugin) use (&$line, &$button_doc) {
 						if ($result && $button_doc->loadXML($result)) {
@@ -335,13 +336,9 @@ class Feeds extends Handler_Protected {
 					},
 					$line);
 
-				$this->_mark_timestamp("   pre-sanitize");
-
 				$line["content"] = Sanitizer::sanitize($line["content"],
 					$line['hide_images'], null, $line["site_url"], $highlight_words, $line["id"]);
 
-				$this->_mark_timestamp("   sanitize");
-
 				if (!get_pref(Prefs::CDM_EXPANDED)) {
 					$line["cdm_excerpt"] = "<span class='collapse'>
 						<i class='material-icons' onclick='return Article.cdmUnsetActive(event)'
@@ -352,8 +349,6 @@ class Feeds extends Handler_Protected {
 					}
 				}
 
-				$this->_mark_timestamp("   pre-enclosures");
-
 				if ($line["num_enclosures"] > 0) {
 					$line["enclosures"] = Article::_format_enclosures($id,
 						sql_bool_to_bool($line["always_display_enclosures"]),
@@ -429,10 +424,12 @@ class Feeds extends Handler_Protected {
 
 				array_push($reply['content'], $line);
 
-				$this->_mark_timestamp("article end");
+				$aa_scope->close();
 			}
 		}
 
+		$a_scope->close();
+
 		$this->_mark_timestamp("end of articles");
 
 		if (!$headlines_count) {
@@ -494,7 +491,7 @@ class Feeds extends Handler_Protected {
 			}
 		}
 
-		$this->_mark_timestamp("end");
+		$scope->close();
 
 		return array($topmost_article_ids, $headlines_count, $feed, $disable_cache, $reply);
 	}
@@ -987,7 +984,7 @@ class Feeds extends Handler_Protected {
 	 * @throws PDOException
 	 */
 	static function _get_counters($feed, bool $is_cat = false, bool $unread_only = false, ?int $owner_uid = null): int {
-		$scope = Tracer::start(__FUNCTION__, [], func_get_args());
+		$scope = Tracer::start(__METHOD__, [], func_get_args());
 
 		$n_feed = (int) $feed;
 		$need_entries = false;
@@ -1497,6 +1494,8 @@ class Feeds extends Handler_Protected {
 	 */
 	static function _get_headlines($params): array {
 
+		$scope = Tracer::start(__METHOD__, [], func_get_args());
+
 		$pdo = Db::pdo();
 
 		// WARNING: due to highly dynamic nature of this query its going to quote parameters
@@ -1989,8 +1988,9 @@ class Feeds extends Handler_Protected {
 			$res = $pdo->query($query);
 		}
 
-		return array($res, $feed_title, $feed_site_url, $last_error, $last_updated, $search_words, $first_id, $vfeed_query_part != "", $query_error_override);
+		$scope->close();
 
+		return array($res, $feed_title, $feed_site_url, $last_error, $last_updated, $search_words, $first_id, $vfeed_query_part != "", $query_error_override);
 	}
 
 	/**
diff --git a/classes/pluginhost.php b/classes/pluginhost.php
index ab26780c7..de2bc84e5 100755
--- a/classes/pluginhost.php
+++ b/classes/pluginhost.php
@@ -339,6 +339,7 @@ class PluginHost {
 	 */
 	function chain_hooks_callback(string $hook, Closure $callback, &...$args): void {
 		$method = strtolower((string)$hook);
+		$scope = Tracer::start(__METHOD__, ['hook' => $hook]);
 
 		foreach ($this->get_hooks((string)$hook) as $plugin) {
 			//Debug::log("invoking: " . get_class($plugin) . "->$hook()", Debug::$LOG_VERBOSE);
@@ -352,6 +353,8 @@ class PluginHost {
 				user_error($err, E_USER_WARNING);
 			}
 		}
+
+		$scope->close();
 	}
 
 	/**
@@ -431,6 +434,8 @@ class PluginHost {
 	 * @param PluginHost::KIND_* $kind
 	 */
 	function load(string $classlist, int $kind, int $owner_uid = null, bool $skip_init = false): void {
+		$scope = Tracer::start(__METHOD__);
+
 		$plugins = explode(",", $classlist);
 
 		$this->owner_uid = (int) $owner_uid;
@@ -439,18 +444,21 @@ class PluginHost {
 			$class = trim($class);
 			$class_file = strtolower(basename(clean($class)));
 
+			$p_scope = Tracer::start('load_plugin', ['file' => $class_file]);
+
 			// try system plugin directory first
 			$file = dirname(__DIR__) . "/plugins/$class_file/init.php";
 
 			if (!file_exists($file)) {
 				$file = dirname(__DIR__) . "/plugins.local/$class_file/init.php";
 
-				if (!file_exists($file))
+				if (!file_exists($file)) {
+					$p_scope->close();
 					continue;
+				}
 			}
 
 			if (!isset($this->plugins[$class])) {
-
 				// WIP hack
 				// we can't catch incompatible method signatures via Throwable
 				// this also enables global tt-rss safe mode in case there are more plugins like this
@@ -464,6 +472,8 @@ class PluginHost {
 
 					$_SESSION["safe_mode"] = 1;
 
+					$p_scope->getSpan()->setTag('error', 'plugin is blacklisted');
+					$p_scope->close();
 					continue;
 				}
 
@@ -474,16 +484,21 @@ class PluginHost {
 
 				} catch (Error $err) {
 					user_error($err, E_USER_WARNING);
+
+					$p_scope->getSpan()->setTag('error', $err);
+					$p_scope->close();
 					continue;
 				}
 
 				if (class_exists($class) && is_subclass_of($class, "Plugin")) {
-
 					$plugin = new $class($this);
 					$plugin_api = $plugin->api_version();
 
 					if ($plugin_api < self::API_VERSION) {
 						user_error("Plugin $class is not compatible with current API version (need: " . self::API_VERSION . ", got: $plugin_api)", E_USER_WARNING);
+
+						$p_scope->getSpan()->setTag('error', 'plugin is not compatible with API version');
+						$p_scope->close();
 						continue;
 					}
 
@@ -516,11 +531,15 @@ class PluginHost {
 					} catch (Error $err) {
 						user_error($err, E_USER_WARNING);
 					}
+
 				}
 			}
+			$p_scope->close();
 		}
 
 		$this->load_data();
+
+		$scope->close();
 	}
 
 	function is_system(Plugin $plugin): bool {
@@ -613,6 +632,8 @@ class PluginHost {
 	}
 
 	private function load_data(): void {
+		$scope = Tracer::start(__METHOD__);
+
 		if ($this->owner_uid && !$this->data_loaded && get_schema_version() > 100)  {
 			$sth = $this->pdo->prepare("SELECT name, content FROM ttrss_plugin_storage
 				WHERE owner_uid = ?");
@@ -624,6 +645,8 @@ class PluginHost {
 
 			$this->data_loaded = true;
 		}
+
+		$scope->close();
 	}
 
 	private function save_data(string $plugin): void {
diff --git a/classes/pref/feeds.php b/classes/pref/feeds.php
index 42adf23ca..fb7e01af8 100755
--- a/classes/pref/feeds.php
+++ b/classes/pref/feeds.php
@@ -1104,7 +1104,7 @@ class Pref_Feeds extends Handler_Protected {
 	 * @return array<string, mixed>
 	 */
 	private function feedlist_init_feed(int $feed_id, ?string $title = null, bool $unread = false, string $error = '', string $updated = ''): array {
-		$scope = Tracer::start(__FUNCTION__, [], func_get_args());
+		$scope = Tracer::start(__METHOD__, []);
 
 		if (!$title)
 			$title = Feeds::_get_title($feed_id, false);
diff --git a/classes/rpc.php b/classes/rpc.php
index 977b88d46..afd3c0c79 100755
--- a/classes/rpc.php
+++ b/classes/rpc.php
@@ -106,7 +106,7 @@ class RPC extends Handler_Protected {
 	}
 
 	function getAllCounters(): void {
-		$scope = Tracer::start(__FUNCTION__);
+		$scope = Tracer::start(__METHOD__);
 
 		@$seq = (int) $_REQUEST['seq'];
 
diff --git a/classes/sanitizer.php b/classes/sanitizer.php
index 8b4584a28..28874d16f 100644
--- a/classes/sanitizer.php
+++ b/classes/sanitizer.php
@@ -63,6 +63,7 @@ class Sanitizer {
 	 * @return false|string The HTML, or false if an error occurred.
 	 */
 	public static function sanitize(string $str, ?bool $force_remove_images = false, int $owner = null, string $site_url = null, array $highlight_words = null, int $article_id = null) {
+		$scope = Tracer::start(__METHOD__);
 
 		if (!$owner && isset($_SESSION["uid"]))
 			$owner = $_SESSION["uid"];
@@ -223,6 +224,8 @@ class Sanitizer {
 
 		$res = $doc->saveHTML();
 
+		$scope->close();
+
 		/* strip everything outside of <body>...</body> */
 
 		$res_frag = array();