From e18295a3644a92280384bdb2a68e0ac436fea376 Mon Sep 17 00:00:00 2001 From: Andrew Dolgov Date: Sun, 9 Apr 2023 22:15:16 +0300 Subject: more tracing --- classes/article.php | 10 ++++++++++ classes/counters.php | 8 ++++---- classes/diskcache.php | 35 ++++++++++++++++++++++++++++++----- classes/feeds.php | 34 +++++++++++++++++----------------- classes/pluginhost.php | 29 ++++++++++++++++++++++++++--- classes/pref/feeds.php | 2 +- classes/rpc.php | 2 +- classes/sanitizer.php | 3 +++ 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>} */ 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 */ 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> */ 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> */ 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> */ private static function get_global(): array { - $scope = Tracer::start(__FUNCTION__); + $scope = Tracer::start(__METHOD__); $ret = [ [ @@ -248,7 +248,7 @@ class Counters { * @return array> */ private static function get_virt(): array { - $scope = Tracer::start(__FUNCTION__); + $scope = Tracer::start(__METHOD__); $ret = []; @@ -304,7 +304,7 @@ class Counters { * @return array> */ 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('' . $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"] = " _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 */ 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 ... */ $res_frag = array(); -- cgit v1.2.3