[22:16:51] has anyone ever looked at the performance impact of Flow\Hooks::onDeletedContributionsLineEnding on the ContributionsLineEnding hook? [22:35:28] I was wondering why 48% of the time for Special:Contributions/ was spent in Hooks::run() - unfortunately, I was not aware of existing profiling methods to see execution times per hook, so had to hack a few files to track the values of microtime(true) (begin & end) in a global array, cumulative for each event [22:35:45] and Flow\Hooks::onDeletedContributionsLineEnding seemed responsible for a majority of the time [22:50:15] That method is here: https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/extensions/Flow/+/refs/heads/master/includes/Hooks.php#827 and seems to be mostly just a wrapper around https://gerrit.wikimedia.org/r/plugins/gitiles/mediawiki/extensions/Flow/+/refs/heads/master/includes/Formatter/ContributionsFormatter.php#24 [22:51:32] You should be able to capture a full profile using XHgui: https://wikitech.wikimedia.org/wiki/X-Wikimedia-Debug#Request_profiling [22:52:30] My recommendation would be to then file a Phabricator task with a link to the captured profile showing the issue. [22:56:30] dpifke: oh, sorry, I should have mentioned that I tested it on a non-Wikimedia site I manage, albeit I presume the same 'issue' exists on Wikimedia wikis as well - will take a profile [23:00:01] If it's doing something pathological, it isn't immediately obvious to me from looking at the code, but I'm mostly a systems guy, not a Mediawiki internals guy. :) [23:00:16] https://performance.wikimedia.org/xhgui/url/view?url=%2F%2Ff665228c-f2c0-4aa3-80aa-14727f8341bb%2Fwiki%2FSpecial%3AContributions%2FSouthparkfan if this would be working... [23:02:03] Should show up if you click on the timestamp, not the URL. [23:02:35] https://performance.wikimedia.org/xhgui/run/view?id=5f2ddc60bb8544186b5996d3 doesn't work either [23:03:14] Hmm, looking. [23:03:57] visiting https://www.mediawiki.org/wiki/Special:Contributions/Southparkfan with "XHGui" and "Inline profile" is enough, if you want to look at the profile [23:10:55] one could say 'hookrunner takes less time on enwiki and nlwiki (wikis without Flow enabled) Contribs than on mediawikiwiki' and 'mediawikiwiki has Flow enabled, enwiki and nlwiki' don't, so Flow must be the culprit/causing impact, but without taking other factors into account, it sounds like confirmation bias :) [23:11:36] So the XHGui error is that its emitting an empty profile. Not clear to me why that is, but it's doing it on this end as well. [23:12:01] The inline profile does help, but I don't know enough to say whether it looks reasonable or not. [23:13:17] If you open a task in Phabricator, someone can take a look if this is expected behavior or not. [23:16:17] got it, I will do that [23:16:21] thanks! [23:17:11] Thanks for reporting it! [23:17:40] yw [23:38:19] So I was able to get a full profile by checking just XHGui (and not inline profile): https://performance.wikimedia.org/xhgui/run/view?id=5f2de5c63f3dfad15b2fb491 [23:39:16] Gonna file a bug on that, because it's non-obvious, as well as on getting a better error message when clicking on a zero-byte profile. [23:41:47] thanks, currently writing the phab task for Flow [23:44:19] onDeletedContributionsLineEnding is present there, but I'm not sure how to read that data [23:44:50] and sorting on a field in xhgui is very slow, due to the number of functions :p [23:50:49] Filed a couple of tasks on fixing the profiler: https://phabricator.wikimedia.org/T259950 and https://phabricator.wikimedia.org/T259952 [23:58:14] Clicking through the child functions on https://performance.wikimedia.org/xhgui/run/symbol?id=5f2de5c63f3dfad15b2fb491&symbol=Flow%5CHooks%3A%3AonDeletedContributionsLineEnding you can see how it's spending its time. The whole function is taking about 220ms, most of which is spread amongst various formatting functions. [23:59:15] (Sorting by "inclusive wall time" should be closest match to inserting microtime calls.)