From fd5e0f98c4174bea254b790606f323b0ca73292a Mon Sep 17 00:00:00 2001 From: Andrew Dolgov Date: Sun, 9 Apr 2023 22:31:42 +0300 Subject: even more tracing --- classes/digest.php | 3 +++ classes/feeds.php | 44 ++------------------------------------------ classes/pluginhost.php | 10 +++++++++- classes/rssutils.php | 20 +++++++++++++++++++- 4 files changed, 33 insertions(+), 44 deletions(-) (limited to 'classes') 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 $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> 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; } -- cgit v1.2.3