Page MenuHomePhabricator

Announcing work done on profiling MediaWiki
Closed, InvalidPublic

Description

I was concerned about the time spent by mediawiki in the Cite extension. So, on my server, I ran a profiler on the master branch of mediawiki while it was parsing (with the core parser, not parsoid) a copy of the page Falsifiability. Here is a graphical representation of the result.

For each node in the graph, the first number in the parenthesis is the time in milliseconds spent in the node after excluding the time spent in its children. The second time includes the time spent in its children. The colors are based on the exclusive time. Darker colors are for larger exclusive times. They are attributed in such a way that the total exclusive time for each color is approximately the same. Many profilers remove nodes with very small execution times. This profiler groups them in ColorGroup nodes instead. To get a nicer graph I had a colorGroup that includes nodes with up to 70 ms. So, there is some lost of information inside these groups.

We can see that approximately 1.5 seconds was spent exclusively on a total of 81 processes inside the node with label "braceSubstitution_#invoke:citation/CS1". It is the node with the darkest color. We can also see that not much time was spent in comparison in the Cite extension processes:

  • 85.1 ms in a total of 106 "extensionSubstitution_ref" processes under "braceSubstitution_#invoke:Footnotes"
  • 116.6 ms in a total of 2 "extensionSubstitution_references" processes under "internalParse" (indirectly through ColorGroup nodes).
  • Not shown, hidden in a group, there is a 63.4 ms "extensionSubstitution_ref".
  • There are also a lot of small ref processes hidden in the colorGroups, but they had up to less than 100 ms.

This is telling me that the Cite extension is not where you can improve the total performance.

Each node in the graph is an aggregation of similar processes selected by profiling statements that I have inserted in the code: you decide which process segments will be monitored. The label of each node is selected by the profiling statements. (There are more than 200 different labels some hidden in colorGroups, but I only inserted 3 profiling statements to generate them.) For each node, there is one and only one arrow with a +n label toward it, usually going downward. The +n means that there are this arrow and n extra hidden arrows toward the node. Thus the target node is an aggregation of n + 1 process segments.

The other arrows , usually going upward, with a number n without the "+" informs that n processes in the target are parts of processes in the source: the source is calling indirectly the target.

Event Timeline

Reedy renamed this task from Announcing work done on profiling wikimedia to Announcing work done on profiling MediaWiki.Mar 17 2024, 8:39 PM

Hi @dominic.mayers, thanks for taking the time to look into this and sharing this! Is there something actionable in this task, and if there is in which software component? (Sorry, this isn't clear after a quick read...)

I was looking for a way to profile mediawiki with that level of details and could not find anything. So, I created my own profiler adapted to the situation. I have, of course, seen the profiling information available in the html source, but it is not comparable. It is an invitation for mediawiki to offer that kind of profiling info to developers.

Thank you Reedy. The profiler I created produces a call graph similar to Kcachegrind. There is an added value to see the connection between the different processes. Also, the profiler I created is way more precise in terms of where the time is spent than what I see in the daily flame graph. For example, the flame graph mentions "braceSubstitution" whereas my profiler monitors "braceSubstitution_safesubst:#invoke:Annotated link", "braceSubstitution_#invoke:citation/CS1", etc. It may have considered 20 or more different calls to braceSubstitution - I did not count. These different calls to "braceSubstitution" behave completely differently, so it is pertinent information. At this stage, the profiler needs improvement: it is necessary to group small processes to have a graph that can be presented and look nice, but it is also necessary to be able to search these groups and to have more informative labels for them.

If you've made a profiler, why not submit it as a pull request to MediaWiki?

Otherwise, as is, your task (as it stands) isn't very actionable. Especially as the task title shows you're "saying I've done this thing", only showing the results, and not linking any code etc.

Maybe this was not the right place to present the profiler. Indeed, I know, at this stage, it's not asking for anything else than comments on the kind of profiling that can be inferred from the output. If there is no interest, I will stop here. The code is not important. It's the idea that matters at this stage.

If you want a discussion, https://lists.wikimedia.org/postorius/lists/mediawiki-l.lists.wikimedia.org/ is possibly a better place. Or some onwiki talk page, which may or may not exist.

If you've got specific asks for "our" profiler, that's fine to request here, but they need to be a bit more specific and actionable :)

This place for discussions is what I was looking for. I hope that it is a very active place.

Hi. This is not a general discussion forum, but an issue tracker to plan and manage work. For general discussions, please check the links on https://www.mediawiki.org/wiki/Communication .

Closing this task for the time being as there is currently nothing actionable in this task, but please feel free to reopen (or file a new task) if there is code to review or future work to plan. Thanks!