Page MenuHomePhabricator

Drastic increase of "The time allocated for running scripts has expired." errors for Lua/Scribunto string functions
Closed, ResolvedPublic

Description

In the last 12 hours a drastic increase of computing times of Lua string functions occured which produces error messages like "The time allocated for running scripts has expired." ("Die zum Ausführen von Skripten vorgesehene Zeit ist abgelaufen.") This is mainly related to Lua string functions find, gsub, sub, and len.

Example report from the HTML source code of https://de.wikivoyage.org/wiki/Halle_(Saale)

Lua time usage: 10.012/10.000 seconds
Lua memory usage: 14452033/52428800 bytes
Lua Profile:
    Scribunto_LuaSandboxCallback::callParserFunction                2720 ms       27.4%
    Scribunto_LuaSandboxCallback::gsub                              1680 ms       16.9%
    Scribunto_LuaSandboxCallback::find                              1100 ms       11.1%
    Scribunto_LuaSandboxCallback::getEntity                          740 ms        7.4%
    Scribunto_LuaSandboxCallback::addStatementUsage                  720 ms        7.2%
    Scribunto_LuaSandboxCallback::sub                                720 ms        7.2%
    Scribunto_LuaSandboxCallback::len                                540 ms        5.4%
    Scribunto_LuaSandboxCallback::getEntityStatements                340 ms        3.4%
    ?                                                                160 ms        1.6%
    init <Modul:CountryData/Geography>                               140 ms        1.4%
    [others]                                                        1080 ms       10.9%
Number of Wikibase entities loaded: 141/400

This problem newer occurred before. In the example mentioned gsub calls took no longer than 100 ms at all.

Event Timeline

The increase of computing time of the functions mentioned is about a factor of 30!

Aklapper renamed this task from Strong reduction of computing time of Lua/Scribunto string functions needed to Drastic increase of "The time allocated for running scripts has expired." errors for Lua/Scribunto string functions.Mar 23 2021, 7:31 AM

Are you sure this has only changed in the last 12 hours? I ask because we haven't really deployed anything significant (like a new MW version) in that timespan.

December 2020 - https://web.archive.org/web/20201205115059/https://de.wikivoyage.org/wiki/Halle_(Saale)

<!-- 
NewPP limit report
Parsed by mw1328
Cached time: 20201205113608
Cache expiry: 86400
Dynamic content: true
Complications: []
CPU time usage: 8.160 seconds
Real time usage: 10.645 seconds
Preprocessor visited node count: 16095/1000000
Post‐expand include size: 1697827/2097152 bytes
Template argument size: 1130/2097152 bytes
Highest expansion depth: 14/40
Expensive parser function count: 145/500
Unstrip recursion depth: 0/20
Unstrip post‐expand size: 261546/5000000 bytes
Lua time usage: 5.992/10.000 seconds
Lua memory usage: 14945561/52428800 bytes
Lua Profile:
    Scribunto_LuaSandboxCallback::callParserFunction                2760 ms       45.8%
    Scribunto_LuaSandboxCallback::getEntity                          820 ms       13.6%
    Scribunto_LuaSandboxCallback::addStatementUsage                  640 ms       10.6%
    Scribunto_LuaSandboxCallback::getEntityStatements                300 ms        5.0%
    ?                                                                120 ms        2.0%
    init <Modul:CountryData/Geography>                               120 ms        2.0%
    Scribunto_LuaSandboxCallback::addSiteLinksUsage                  120 ms        2.0%
    Scribunto_LuaSandboxCallback::getAllExpandedArguments            120 ms        2.0%
    recursiveClone <mwInit.lua:41>                                    80 ms        1.3%
    Scribunto_LuaSandboxCallback::gsub                                80 ms        1.3%
    [others]                                                         860 ms       14.3%
Number of Wikibase entities loaded: 162/400
-->
<!--
Transclusion expansion time report (%,ms,calls,template)
100.00% 8546.381      1 -total
 86.93% 7429.100    255 Vorlage:VCard
  4.74%  404.843      1 Vorlage:Quickbar_Ort
  3.20%  273.750      1 Vorlage:Mapframe
  2.08%  177.448      4 Vorlage:Marker
  0.62%   52.887      6 Vorlage:Buch
  0.58%   49.726      1 Vorlage:GeoData
  0.38%   32.655      7 Vorlage:Abk
  0.33%   27.804      1 Vorlage:IstInKat
  0.32%   27.200      1 Vorlage:Einzelnachweise
-->

Now I am making several changes on https://de.wikivoyage.org/wiki/Modul:VCard and its submodules. To prevent (many) error messages I am checking https://de.wikivoyage.org/wiki/Kategorie:Seiten_mit_Skriptfehlern (pages with scripting failures) twice per day and after code changes. That's why I think that the jump in time consumption occurred 12 (or not more then 24) hours ago. The time consumption of https://de.wikivoyage.org/wiki/Halle_(Saale) is checked weekly because it is one of the most time consuming articles. We would earlier detect the changes by Debian upgrades made in January, 2021. We observed similar results to December 2021 a few days ago.

I am really wondering of the time consumption increase of gsub from about 80 ms to about 2000 ms.

We had to do these checks because there were several problems with huge performance changes in the past (for instance T265562, T189409). Other time consuming functions are callParserFunction and addStatementUsage (not really solved) but these problems are another tasks.

Because of frequently used templates (250 times of vCard in the article of Halle (Saale)) it is easier to detect performance changes.

From https://de.wikivoyage.org/wiki/Spezial:Version I learned that the last Mediawiki version is of

1.36.0-wmf.35 (b0cfbbe)
23:07, 22. Mär. 2021
...
Lua sandbox: 3.0.3
Lua: 5.1.5

This is the night before I detected the increase of computing time.

I think I found the failure: it is a damaged / erroneous mw.text library, especially mw.text.split and mw.text.trim!

I checked all my changes within the last days and found the cause in https://de.wikivoyage.org/wiki/Modul:Marker_utilities. I replaced

		if mu.isSet( typeItem.wd ) then
			for _, qid in ipairs( mw.text.split( typeItem.wd, ',', true ) ) do
				qid = mw.text.trim( qid )
				if qid ~= '' then
					mu.types[ qid ] = key
				end	
			end
		end

by

		if mu.isSet( typeItem.wd ) then
--			for _, qid in ipairs( mw.text.split( typeItem.wd, ',', true ) ) do
			for qid in string.gmatch( typeItem.wd .. ',', '([^,]+)' ) do
--				qid = mw.text.trim( qid )
				qid = qid:gsub( '^[%c%s]+', '' ):gsub( '[%c%s]+$', '' )
				if qid ~= '' then
					mu.types[ qid ] = key
				end
			end
		end

and I saved 3.000 ms of computing time!

typeItem.wd comes from the table Modul:Marker utilities/Types containing about 500 items. Most of them uses a wd field with Q (Wikidata) identifiers, for instance wd = "Q100355757,Q25653,Q1478783". The aim of the small script is to split this string and put them into another table. Maybe I found this failure because such a lot of iterations were made.

Maybe this is a long-term failure discovered only now!

RolandUnger changed the subtype of this task from "Task" to "Bug Report".Mar 25 2021, 7:45 AM
RolandUnger claimed this task.
RolandUnger changed the subtype of this task from "Bug Report" to "Task".

@RolandUnger, I don't understand why the task is resolved. Isn't the mw.text library still broken?

The functions mentioned are not really broken but non-performant. For instance, I was using about 100.000 split operations in 250 templates. Firstly, I did it with mw.text.split(), and it took about 3,000 ms. Then I replaced these convenient but slow functions with Lua functions like match() and gmatch(), and the same took only a few ms. 3,000 ms computing time is really much and finally it caused an allocation-time error.

So, it's a performance and documentation problem. So I advice to use Lua functions instead of mw.text.split() especially in case of a single split character like a comma or set of commas. In the documentation this fact of non-performance should be mentioned. Surely, the mw.text can be improved. But this problem is of low priority. Because I found another solution I closed this task. There are other performance problems which I like to be solved.