https://integration.wikimedia.org/ci/job/mwext-php72-phan-seccheck-docker/713/console - 21 minutes
https://integration.wikimedia.org/ci/job/mwext-php72-phan-seccheck-docker/763/console - 17 minutes
Based on https://integration.wikimedia.org/ci/job/mwext-php72-phan-seccheck-docker/buildTimeTrend this is an order of magnitude slower than all other repos, so filing a bug.
| Subject | Author | Repo | Branch | Lines +/- | |
|---|---|---|---|---|---|
| [DNM] Jenkins test | Daimona Eaytoy | mediawiki/extensions/TimedMediaHandler | master | +5 -1 |
Uhm, I'd like to use xdebug for this, but phan would get way slower (around 5x), and doing that on an already-slow extension could be painful. So I think I'll just start removing pieces from the extension and see what's causing the slowness.
Change 523730 had a related patch set uploaded (by Daimona Eaytoy; owner: Daimona Eaytoy):
[mediawiki/extensions/TimedMediaHandler@master] Testing jenkins runtime for seccheck
OK So this is more complicated than it seems. I ran seccheck 2.0.1 on TMH master (with ast 1.0.1, PHP 7.3.4), and it completed in normal time. Ran it again, same result. I've also added a line to print the runtime and ran it 3 more times, taking respectively 73, 51 and 51 seconds. My machine is pretty powerful, but not so much to explain the 18 minutes of runtime of the change above. I also note that zuul is a little busy right now, but again, not so much to explain all this slowness: see for instance here. It started 6 minutes after the TMH one and finished in 12 seconds.
So it must have to do with the CI config. Maybe some phan/seccheck bug only happening under certain environment conditions? Trying to add phan to TMH and see the runtime could be a first step in understanding where the problem is likely to be found.
Note: after writing the rant above I realized that I ran seccheck with another version of vendor, likely including phan 2.2.5. Nevertheless, re-installing phan 1.3.2 and running again gave 53, 53 and 53 seconds (yeah, pretty constant).
Natively, with php path/to/phan -d . -k path/to/mwext-fast-config.php -p. That's why I suspect it has to do with the image config.
Does maybe ci have less memory available? (When i used to test on my old laptop with low ram when ram ran out things slowed to a crawl (presumably lot of swapping)
Some more runs from today (second one intentionally triggered by me):
Maybe? But you'd think we'd then see similar slowdowns on other repos too. But when I check the build times for this job, it's only TMH that's being slow. Do you think somehow TMH is the only one hitting that threshold?
Hrm. I ran it through the container on my laptop and couldn't reproduce any slowdown (comparing against other extensions on my laptop). For reference, here's the command I used: time docker run --user=1000 --rm --env THING_SUBNAME="extensions/TimedMediaHandler" -v ~/gerrit/mediawiki/core:/mediawiki -v ~/.cache:/cache docker-registry.wikimedia.org/releng/mediawiki-phan-seccheck:latest -m checkstyle.
This is definitely true. Having less than 2GB of RAM can lead to a ~x5 slowness or worse.
OK so this is now pretty reliable (and consistent).
Maybe? But you'd think we'd then see similar slowdowns on other repos too. But when I check the build times for this job, it's only TMH that's being slow. Do you think somehow TMH is the only one hitting that threshold?
Maybe it has lots of dependencies and there's a lot of code to parse? Note, however, that such code wouldn't be analyzed, and that's when the higher memory usage occurs (obviously). Either way, TMH doesn't seem to be so big, especially if compared to other (big) extensions with normal runtimes, like WB.
Hrm. I ran it through the container on my laptop and couldn't reproduce any slowdown (comparing against other extensions on my laptop). For reference, here's the command I used: time docker run --user=1000 --rm --env THING_SUBNAME="extensions/TimedMediaHandler" -v ~/gerrit/mediawiki/core:/mediawiki -v ~/.cache:/cache docker-registry.wikimedia.org/releng/mediawiki-phan-seccheck:latest -m checkstyle.
Well, it's weird. I wonder if we could do what I said in T228137#5337224, but in gerrit; i.e., start butchering the repo and see if there's a specific file that's causing the slowdown. However, I wouldn't be surprised if it'll be slow even without files.
Of note, we don't have a live progress bar for CI, so we don't know at which phase of the analysis the slowdown happens.
Found it. The problem is somewhere in the ID3Handler / getid3 library. The reason that we couldn't reproduce it locally was because we probably didn't have that library installed.
{ "extra": { "merge-plugin": { "include": [ "extensions/TimedMediaHandler/composer.json" ] } } }
Create that in the root of your core checkout, and run composer update in core, which should pull in getid3. Then try running phan-taint-check again.
Mine is stalled at: analyze ██████▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 13% 2145MB/2145MB for about 5 minutes now.
Of course...
Mine is stalled at: analyze ██████▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 13% 2145MB/2145MB for about 5 minutes now.
And mine at analyze ██████▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 13% 2150MB/2151MB, yes. I'll butcher that library and will let you know.
So, for now, I managed to get this down to the ID3Handler class in TMH, and part of the getid3.php file in the library. I suspect this has to do with the $info property inside getid3, but I'm still unsure. Apparently it needs several methods in getid3 to exist, in order to remain stalled. I'll probably continue investigating tomorrow.
P8769 is the minimum I could find for now in the getid3 class. Inside the extension, you'll only need the following:
class ID3Handler extends TimedMediaHandler {
/**
* @param string $path
* @return array
*/
protected function getID3( $path ) {
$getID3 = new getID3();
$getID3->analyze( $path );
}
}Now I suspect it could have to do with $info, but also with recursion. Also note that analysing only the 2 files above is really fast. The "slow" version pasted above takes roughly 4 seconds, while the quick one (that you'd get by removing some stuff) will take 0.5s. It's not much, but it's still recognizable.
At this point, xdebug should be usable. I'll do that tomorrow anyway (now for real).
I continued digging the code, but TBH I'm not getting anywhere. I managed to reproduce the issue with a version of the plugin having only 250 lines of visitor, but still nothing. This seems to be a combination of several factors. Almost surely, it has to do with the insane nesting level inside the $info property (which is bad practice anyway, but nvm), and class/method reanalysis for dependent method/vars. Also, xdebug doesn't help much due to some phan dark magic.
So if someone wants to continue investigating, feel free to; I won't mostly be around for the next week.
A little update: xdebug says that there's a cycle, which is where the slowness happens. (UnionType|GenericArrayType)::hasTemplateTypeRecursive is called like 5 million times for my simplified scratch, and that's obviously super-heavy. The call triggering the loop happens in UnionTypeVisitor::analyzeProp (obviously for the $info prop). For some reason, that prop's type_set is a deeply nested array of types (I suspect it has 5 million nesting levels looking at the code, but I didn't check), and thus the long recursion.
As for why the type_set is this crazy, I (still) don't know.
By the way, there is now a stub for getID3.php, so this may not use the composer version
I've tried running phan+taint-check on TimedMediaHandler (using mw-phan 0.10.2) and the issue is gone, apparently. Of note, I didn't run it on the whole TMH repo, but rather on the snippet at T228137#5343561. It finished in an instant.