QA (public) » openQA Project (public)

kraih plans to have the benchmark and then identify possibly multiple places where we can optimize. There is no explicit "Z-A" sorting but "opendir" and "readdir" calls which effectively traverse the complete sections of the filesystem which can be very expensive. Instead we should use the information from the database to identify where we actually need a filesystem-lookup.

Opened a PR that removes most of the syscalls completely. https://github.com/os-autoinst/openQA/pull/4189

kraih wrote:

PR has been merged, let's see how it performs in production.

could you check?

There's currently a limit_assets task running (see https://openqa.suse.de/minion/jobs?task=limit_assets and https://openqa.suse.de/minion/jobs?id=2972890 in particular). It has already been running for more than half an hour. Not sure whether that's bad because it most likely actually needs to clean up lots of assets and this was more about the idle case. So I would trigger another asset cleanup right after the one which has just finished to check.

Even with only ensure_size it is still running for over 10 minutes now. It looks like database updates are still slowing it down:

poll([{fd=13, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=13, revents=POLLIN}])
recvfrom(13, "2\0\0\0\4n\0\0\0\4C\0\0\0\rUPDATE 1\0Z\0\0\0\5I", 262144, 0, NULL, NULL) = 30
sendto(13, "B\0\0\0002\0dbdpg_p16636_7\0\0\0\0\2\0\0\0\007719"..., 73, MSG_NOSIGNAL, NULL, 0) = 73
poll([{fd=13, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=13, revents=POLLIN}])
recvfrom(13, "2\0\0\0\4n\0\0\0\4C\0\0\0\rUPDATE 1\0Z\0\0\0\5I", 262144, 0, NULL, NULL) = 30
sendto(13, "B\0\0\0003\0dbdpg_p16636_7\0\0\0\0\2\0\0\0\007719"..., 74, MSG_NOSIGNAL, NULL, 0) = 74
poll([{fd=13, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=13, revents=POLLIN}])
recvfrom(13, "2\0\0\0\4n\0\0\0\4C\0\0\0\rUPDATE 1\0Z\0\0\0\5I", 262144, 0, NULL, NULL) = 30
sendto(13, "B\0\0\0003\0dbdpg_p16636_7\0\0\0\0\2\0\0\0\007719"..., 74, MSG_NOSIGNAL, NULL, 0) = 74

I suspect that these are the updates for the "fixed" state of the asset.

Even when updating the database only if the "fixed status" changes it takes long to run stat all those files, e.g. the job I'm currently testing is already running for 10 minutes. The remaining syscalls are clearly related to the code which determines whether an asset is fixed:

getpid()                                = 12496
stat("/var/lib/openqa/share/factory/other/07110482-cve", {st_mode=S_IFREG|0644, st_size=2010, ...}) = 0
getpid()                                = 12496
stat("/var/lib/openqa/share/factory/other/07100435-net.tirpc_tests", {st_mode=S_IFREG|0644, st_size=2753, ...}) = 0
getpid()                                = 12496
stat("/var/lib/openqa/share/factory/other/07100432-sched", {st_mode=S_IFREG|0644, st_size=371, ...}) = 0
getpid()                                = 12496
stat("/var/lib/openqa/share/factory/iso/SLE-15-SP1-Installer-DVD-s390x-Build47.3-Media1.iso", 0x55999732d4f0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
stat("/var/lib/openqa/share/factory/iso/fixed/SLE-15-SP1-Installer-DVD-s390x-Build47.3-Media1.iso", 0x55999732d4f0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
stat("/var/lib/openqa/share/factory/iso/SLE-15-SP1-Installer-DVD-s390x-Build47.3-Media1.iso", 0x55999732d4f0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
stat("/var/lib/openqa/share/factory/iso/fixed/SLE-15-SP1-Installer-DVD-s390x-Build47.3-Media1.iso", 0x55999732d4f0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
stat("/var/lib/openqa/share/factory/iso/SLE-15-SP1-Installer-DVD-s390x-Build47.3-Media1.iso", 0x55999732d4f0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
getpid()                                = 12496
stat("/var/lib/openqa/share/factory/hdd/SLES-15-SP3-aarch64-minimal_installed_for_LTP_broken.qcow2", 0x55999732d4f0) = -1 ENOENT (Datei oder Verzeichnis nicht gefunden)
stat("/var/lib/openqa/share/factory/hdd/fixed/SLES-15-SP3-aarch64-minimal_installed_for_LTP_broken.qcow2", {st_mode=S_IFREG|0644, st_size=1179385856, ...}) = 0
getpid()                                = 12496
stat("/var/lib/openqa/share/factory/other/06203626-syscalls", {st_mode=S_IFREG|0644, st_size=30774, ...}) = 0
getpid()                                = 12496
stat("/var/lib/openqa/share/factory/other/06203625-dio", {st_mode=S_IFREG|0644, st_size=2184, ...}) = 0

When only updating the "fixed status" for assets which we've already seen it goes faster as all the stat calls from the previous comment #97979#note-14 go away. I'm not sure whether it is safe to do so, though.

Additionally, the update calls from #97979#note-13 remain because these are actually about updating the last job of each asset. I suppose that's really something we want although we could likely also skip it if the last job doesn't change anyways.

Parsing each asset's timestamp takes quite a long time, likely because it involves several syscalls per asset:

getpid()                                = 30348
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
flock(3, LOCK_EX)                       = 0
write(3, "[2021-09-23T13:16:41.0904 CEST] "..., 113) = 113
flock(3, LOCK_UN)

So even when skipping all filesystem checks for assets we have already seen it takes 19 minutes. So we likely want to optimize the points from the last two paragraphs in my previous comment.

I've been creating two PRs, one containing optimizations which should not change the behavior (https://github.com/os-autoinst/openQA/pull/4226/files) and one with additional optimizations which slightly change the behavior (https://github.com/os-autoinst/openQA/pull/4227).

I'm not sure yet whether the syscalls in #97979#note-15 actually come from the timestamp parsing. After some local testing it doesn't seem to cause these syscalls so it is likely just some logging.

mkittler wrote:

I've been creating two PRs, one containing optimizations which should not change the behavior (https://github.com/os-autoinst/openQA/pull/4226/files) and one with additional optimizations which slightly change the behavior (https://github.com/os-autoinst/openQA/pull/4227).

I'm not sure yet whether the syscalls in #97979#note-15 actually come from the timestamp parsing. After some local testing it doesn't seem to cause these syscalls so it is likely just some logging.

openQA#4226 got merged

I've been creating a ticket for further improvements so the "dangerous" PR could be implemented as an optional feature: https://progress.opensuse.org/issues/99393

PR for fixing the regression: https://github.com/os-autoinst/openQA/pull/4250

I found it by looking at the Minion dashboard. We have a monitoring alert and it would have triggered after a certain amount of failed jobs. For other reasons we cannot lower the threshold but there are already tickets for improving the situation. And obviously the file system alert would have fired as well at some point.

By the way, the PR has been merged and deployed and seems to work.