[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

thcipriani edited projects, added Release-Engineering-Team (Blocking 隣); removed Release-Engineering-Team (CI & Testing services), Release-Engineering-Team-TODO (2020-10-01 to 2020-12-31 (Q2)). thcipriani closed this task as "Resolved". thcipriani added a comment. Calling this resolved. I

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar closed subtask T299211: Request increased quota for integration Cloud VPS project as Resolved. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc: aborrero, dcaro, Aklapper,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2022-01-14T13:49:34Z] Restarting all CI Docker agents via Horizon to apply new flavor settings T265615 T299211 TASK DETAIL

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a subtask: T299211: Request increased quota for integration Cloud VPS project. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc: aborrero, dcaro, Aklapper, dduvall, bd808,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

dcaro added a comment. I've added a burst configuration for 3x the iops for 10s for that flavor, might require stopping and starting (not restarting) the VMs: root@cloudvirt1024:~# openstack --os-project-id integration flavor show g2.cores8.ram24.disk80.4xiops

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added subscribers: dcaro, aborrero. hashar added a comment. I have talked to @aborrero and @dcaro about the limits. They are inclined to further tune the limit like has been done last year by Andrew ( T266777#6589231 ) and

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. @awight potentially though `tmpfs` goes in memory and is expensive. A run with core + Wikibase and all the npm dependencies turn out to be around 9G iirc which is a lot to put in RAM. I was looking at a stall build today and it `iotop` definitely showed up the

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

awight added a comment. This is just a walk-by comment so feel free to ignore, but didn't we have a nearly identical issue last year, and the solution was to put all these little files in a tmpfs which could simply be unmounted when the container is destroyed? If this sounds like something

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I have checked in Docker and it does a `os.removeAll` which is waited for completion. If a container has huge amount of files that have to be deleted, that would file the memory cache for writes which is is known in Linux as the Dirty memory. From `proc(5)`: >

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Lucas_Werkmeister_WMDE updated the task description. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar, Lucas_Werkmeister_WMDE Cc: Aklapper, dduvall, bd808, jeena, Daimona, thcipriani,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Pfff I am not focusing today. The `INFO:backend.MySQL:Terminating MySQL` is the last message send by Quibble and it has indeed completed (at max roughly 2 seconds after the message got written). What is taking age and got thoroughly investigated previously is the

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Quibble terminates MySQL via `quibble.backend.Backend.stop()` which does: def stop(self): if self.server is not None: self.log.info('Terminating %s', self.__class__.__name__) self.server.terminate() try:

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar reopened this task as "Open". hashar added a comment. Sorry @Lucas_Werkmeister_WMDE , I have missed your comment. @kostajh raised it again today so reopening. 21:26:14 hashar: does it seem normal for `INFO:backend.MySQL:Terminating MySQL` to take ~2 minutes? looking at

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Lucas_Werkmeister_WMDE added a comment. This seems to have been increasing again, especially in Selenium builds; some recent examples: - 3m29s in https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/88456/console - 12m25s(!) in

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Andrew closed subtask T266777: integration instances suffer from high IO latency due to Ceph as Resolved. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar, Andrew Cc: Aklapper, dduvall,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar closed this task as "Resolved". hashar added a comment. That has been more or less fixed by raising the newish IO quota for the integration instances. It is still not ideal and enhancements will be made later on via the infrastructure task T266777

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar merged a task: T267075: Pipeline jobs freezing during teardown. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc: Aklapper, dduvall, bd808, jeena, Daimona, thcipriani, hashar,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar merged a task: T267075: Pipeline jobs freezing during teardown. hashar added subscribers: jeena, bd808, dduvall, Aklapper. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc:

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. @Lucas_Werkmeister_WMDE yes Wikibase kind of highlights the issue since it has so many files. I have also noticed the disk slowness on various other jobs though, some started to timeout as a result due to the number of IO operations they perform. I thought

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a subtask: T266777: integration instances suffer from high IO latency due to Ceph. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc: Daimona, thcipriani, hashar, awight,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Lucas_Werkmeister_WMDE added a comment. I guess Wikibase might be hit harder than other extensions by the deletion slowness due to a larger volume of files in the `node_modules` of subprojects like Wikidata Bridge? TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 636908 **abandoned** by Hashar: [operations/puppet@production] ci: run docker with debug logging Reason: I have removed the patch from the integration puppet master and reloaded docker https://gerrit.wikimedia.org/r/636908 TASK DETAIL

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I have found out the root cause which is in the underlying infrastructure. Will file a task about it tomorrow. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I have looked at it live by running strace profiling against `dockerd` while a container was being reaped: name=strace -C -e trace=file -f -p `pidof dockerd` % time seconds usecs/call callserrors syscall -- --- ---

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. So my best assumption is that the source code / package install etc are done inside the Docker container. Upon removal, Docker spends a lot of time to delete all those files which might explain the issue. If that is true, that can be reproduced by spawning a

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Looks like the container is stuck in `removing` status. For a build with: 13:09:39 INFO:backend.MySQL:Terminating MySQL 13:10:33 [wmf-quibble-selenium-php72-docker] $ /bin/bash -xe /tmp/jenkins4716707043969520657.sh Running `docker container inspect` in

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 636908 had a related patch set uploaded (by Hashar; owner: Hashar): [operations/puppet@production] ci: run docker with debug logging https://gerrit.wikimedia.org/r/636908 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. No with child tracing (`-f`) and time spent in system call (`-T`). PID 23094 invokes `epoll_pwait` which resumes after 3 seconds for whatever reason. name=strace -s 128 -tt -yy -T -f [pid 23092] 10:21:51.923319 write(2, "time=\"2020-10-28T10:21:51Z\"

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. With `TINY_VERBOSITY=3` and `docker -D -l debug run`: 08:58:27 [INFO tini (1)] Main child exited normally (with status '1') 08:58:28 time="2020-10-28T08:58:28Z" level=debug msg="[hijack] End of stdout" 08:58:38 Build step 'Execute shell' marked build as

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 634481 **abandoned** by Hashar: [integration/quibble@master] (DO NOT SUBMIT) test dummy full run Reason: https://gerrit.wikimedia.org/r/634481 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I have done various hacking here and there nothing conclusive. I have rolled back: - https://integration.wikimedia.org/ci/job/integration-quibble-fullrun/ - Dockerd --- Dockerd running with `docker: true` gives a lot more logs in the journal. At

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-27T13:19:54Z] Enabling puppet again on CI agent (that also causes Docker/containerd to be rolled back) # T265615 TASK DETAIL https://phabricator.wikimedia.org/T265615

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-27T13:20:30Z] Enable Docker daemon debug mode on integration-agent-docker-1001 via Horizon https://horizon.wikimedia.org/project/instances/837fff63-ed52-4c2f-823d-936801056fd2/ # T265615

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 636621 **merged** by jenkins-bot: [integration/config@master] jjb: disable workspace size collection https://gerrit.wikimedia.org/r/636621 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 636621 had a related patch set uploaded (by Hashar; owner: Hashar): [integration/config@master] jjb: disable workspace size collection https://gerrit.wikimedia.org/r/636621 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Same for Docker 19.03.13 / 1.3.7 . wmf-quibble-selenium-php72-docker builds still have a minute delay or so. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc:

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-26T12:00:01Z] Upgrading docker-ce to 19.03.13 and containerd to 1.3.7 on integration-agent-docker-1001, integration-agent-docker-1002, integration-agent-docker-1003 and integration-agent-docker-1004 # T265615

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I have upgraded containerd from 1.2.10-3 to 1.2.13-2 on eight hosts but that unfortunately does not seem to help :-( TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To:

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. For later reference: 11:23:24 INFO:backend.MySQL:Terminating MySQL 11:24:41 [wmf-quibble-selenium-php72-docker] $ /bin/bash -xe /tmp/jenkins937915457220888713.sh And in containerd the log shows the process got reaped properly?: Oct 26 10:56:21

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-26T11:12:10Z] Upgrading containerd.io from 1.2.10 to 1.2.13-2 on integration-agent-docker-1005, integration-agent-docker-1006, integration-agent-docker-1007, integration-agent-docker-1008 # T265615

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-26T11:03:32Z] Bring back integration-agent-docker-1020 . It is not the only one affected by T265615 which probably rules out Ceph as the slowness root cause (T260916

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-26T10:56:59Z] Upgrading containerd.io from 1.2.10 to 1.2.13-2 on integration-agent-docker-1001, integration-agent-docker-1002, integration-agent-docker-1003, integration-agent-docker-1004 # T265615

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I was watching integration-agent-docker-1004 which had 3 builds involving Quibble. I have opened pages using the Jenkins monitoring interface that lets one list processes and java threads. As soon as one showed the delay I refreshed the two pages. On the list

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar claimed this task. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar Cc: thcipriani, hashar, awight, kostajh, Lucas_Werkmeister_WMDE, Alter-paule, Beast1978, Un1tY, Akuckartz,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Next fun, digging into Jenkins! I looked at https://integration.wikimedia.org/ci/job/wmf-quibble-selenium-php72-docker/64820/ which got affected by the same issue (all times are UTC): counterexample 18:08:34 [wmf-quibble-selenium-php72-docker] $

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 634465 **abandoned** by Hashar: [integration/config@master] jjb: wmf job with quibble 44 Reason: https://gerrit.wikimedia.org/r/634465 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. After many attempts, I finally got a lead https://integration.wikimedia.org/ci/job/integration-quibble-fullrun/153/console The job executes a shell script utils/ci-fullrun.sh in integration/quibble.git, I have edited it to `echo CI FULLRUN completed` when the

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. I tried various combination and I can not reproduce it. Maybe it is race condition between us sending SIGKILL (`self.server.kill()`) and python reaping the processed on garbage collection when we set `self.server = None` :-\ TASK DETAIL

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Gave it a try with a bit more logging. One run with a 2 seconds delay which is too short and trigger a SIGKILL: 00:22:05.191 INFO:quibble.commands:Shutting down backends: 00:22:05.191 INFO:backend.MySQL:Stopping MySQL 00:22:05.192

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 634481 had a related patch set uploaded (by Hashar; owner: Hashar): [integration/quibble@master] (DO NOT SUBMIT) test dummy full run https://gerrit.wikimedia.org/r/634481 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. CI for `integration/quibble` does have a job that runs it entirely against mediawiki/core. The last few builds show more or less show the same issue: 00:11:36.278 INFO:backend.MySQL:Terminating MySQL 00:11:41.731 Archiving artifacts 00:11:09.274

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. To rule out Quibble 0.0.45, I have create a dummy job using docker-registry.wikimedia.org/releng/quibble-stretch-php72:0.0.44-s5. And it is still affected: 00:21:32.612 INFO:backend.MySQL:Terminating MySQL 00:22:36.029 [wmf-quibble44-selenium-php72-docker]

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a project: Patch-For-Review. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: gerritbot Cc: hashar, awight, kostajh, Lucas_Werkmeister_WMDE, Alter-paule, Beast1978, Un1tY,

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

gerritbot added a comment. Change 634465 had a related patch set uploaded (by Hashar; owner: Hashar): [integration/config@master] jjb: wmf job with quibble 44 https://gerrit.wikimedia.org/r/634465 TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Stashbot added a comment. Mentioned in SAL (#wikimedia-releng) [2020-10-16T07:48:42Z] Disabling integration-agent-docker-1020 (the sole agent using Ceph): it is too slow # T260916 T265615 TASK DETAIL

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added a comment. Looking at some random builds, it usually takes 15 / 20 seconds to start the next command which is a bug by itself: 00:17:39.940 INFO:backend.MySQL:Terminating MySQL 00:17:55.311 [wmf-quibble-selenium-php72-docker] $ /bin/bash -xe

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar triaged this task as "High" priority. hashar added a comment. Will look at it tomorrow and try to at least reproduce the issue. TASK DETAIL https://phabricator.wikimedia.org/T265615 EMAIL PREFERENCES https://phabricator.wikimedia.org/settings/panel/emailpreferences/ To: hashar

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

hashar added subscribers: kostajh, awight, hashar. hashar edited projects, added Continuous-Integration-Infrastructure, Release-Engineering-Team-TODO (2020-10-01 to 2020-12-31 (Q2)), Release-Engineering-Team (CI & Testing services); removed Continuous-Integration-Config. hashar added a comment.

[Wikidata-bugs] [Maniphest] T265615: Terminating MySQL takes several minutes in (Wikibase?) CI jobs

Lucas_Werkmeister_WMDE created this task. Lucas_Werkmeister_WMDE added projects: Quibble, Continuous-Integration-Config, Wikidata. TASK DESCRIPTION I’ve noticed that the “Terminating MySQL” step at the end of a CI build can take several minutes. For example, in this recent job