5 Jun
2020
5 Jun
'20
9:29 a.m.
Hello all,
I have a question regarding cache size and it’s using. We are running
knot-resolver on RaspberryPI 4 (as secondary cache). Previously we had
256MB cache as tmpfs and hit issue that process crashed due to “No space
left on device (workdir '/var/lib/knot-resolver')” I doubled the site to
512MB, but same issue occurs. My question is why it crash even from the
logs the usage of cache is about 80 percent (same in the case with 256MB).
I taught that kres-cache-gc is taking care about its size and it does not
allow to full the cache and prevent writing to it in the way that main
process crash. Should we increase the cache size or we hit a some bug? Any
other suggestion what could cause that cache is full and not “cleared”?
Thank you for tip and have a nice day. Petr Kyselak
Config:
/etc/fstab
tmpfs /var/cache/knot-resolver tmpfs
rw,size=512m,uid=knot-resolver,gid=knot-resolver,nosuid,nodev,noexec,mode=0700
0 00
-- Cache size
cache.size = cache.fssize() - 10*MB
Logs:
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Cache analyzed in 1.41
secs, 1038386 records, limit category is 100.
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: 0 records to be deleted
using 0.00 MBytes of temporary memory, 0 records skipped due to memory
limit.
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Deleted 0 records (0
already gone) types
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: It took 0.00 secs, 0
transactions (OK)
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Usage: 81.32% (428077056 /
526385152)
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Cache analyzed in 1.41
secs, 1038420 records, limit category is 100.
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: 0 records to be deleted
using 0.00 MBytes of temporary memory, 0 records skipped due to memory
limit.
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Deleted 0 records (0
already gone) types
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: It took 0.00 secs, 0
transactions (OK)
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Usage: 81.32% (428077056 /
526385152)
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Cache analyzed in 1.41
secs, 1038420 records, limit category is 100.
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: 0 records to be deleted
using 0.00 MBytes of temporary memory, 0 records skipped due to memory
limit.
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Deleted 0 records (0
already gone) types
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: It took 0.00 secs, 0
transactions (OK)
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Usage: 81.32% (428077056 /
526385152)
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Cache analyzed in 1.41
secs, 1038421 records, limit category is 100.
Jun 4 16:32:32 dns-cache-2 kresd[672]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[672]: [cache] clearing error, falling back
Jun 4 16:32:32 dns-cache-2 kresd[672]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing error, falling back
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing failed to get
./.cachelock; retry later
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing error, falling back
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing failed to get
./.cachelock; retry later
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing error, falling back
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing failed to get
./.cachelock; retry later
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
…
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)1.service: Main process
exited, code=killed, status=11/SEGV
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing failed to get
./.cachelock; retry later
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing error, falling back
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing failed to get
./.cachelock; retry later
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
…
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)1.service: Failed with result
'signal'.
…
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)2.service: Main process
exited, code=killed, status=11/SEGV
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing failed to get
./.cachelock; retry later
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing error, falling back
…
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)2.service: Failed with result
'signal'.
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -17
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing error, falling back
…
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] MDB_BAD_TXN, probably
overfull
Jun 4 16:32:32 dns-cache-2 kresd[675]: [cache] clearing because overfull,
ret = -28
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)1.service: Service
RestartSec=100ms expired, scheduling restart.
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)1.service: Scheduled restart
job, restart counter is at 1.
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)2.service: Service
RestartSec=100ms expired, scheduling restart.
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)2.service: Scheduled restart
job, restart counter is at 1.
Jun 4 16:32:32 dns-cache-2 kresd[30052]: [system] error while loading
config: /usr/lib/knot-resolver/sandbox.lua:400: can't open cache path
'/var/cache/knot-resolver'; working directory '/var/lib/knot-resolver';
No
space left on device (workdir '/var/lib/knot-resolver')
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)1.service: Main process
exited, code=exited, status=1/FAILURE
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)1.service: Failed with result
'exit-code'.
Jun 4 16:32:32 dns-cache-2 kresd[30051]: [system] error while loading
config: /usr/lib/knot-resolver/sandbox.lua:400: can't open cache path
'/var/cache/knot-resolver'; working directory '/var/lib/knot-resolver';
No
space left on device (workdir '/var/lib/knot-resolver')
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)2.service: Main process
exited, code=exited, status=1/FAILURE
Jun 4 16:32:32 dns-cache-2 systemd[1]: kresd(a)2.service: Failed with result
'exit-code'.
5 Jun
5 Jun
1:46 p.m.
Hello.
The part with "No space left" seems quite clear to me. The emergency
with cache file being deleted and re-created should never happen when GC
works, though. Deleted files may get held a while by other kresd and
kres-cache-gc, and since recent versions we fully pre-allocate the new
cache. Increasing your tmpfs size would probably avoid the
out-of-space, but I'm way more concerned about the GC not working well
and those SIGSEGVs (80% is way too low to cause problems).
Can you confirm that you use a recent knot-resolver version? And
perhaps, where are your packages from and 32/64-bit?
Additionally, a coredump from any of those crashes would be nice, but
maybe we can find something even without it. (easiest via coredumpctl in
your case, I suppose)
--Vladimir
2:28 p.m.
Hi,
thanks for the detailed report.
On 05/06/2020 13.46, Vladimír Čunát wrote:
Increasing your tmpfs size would probably avoid the
out-of-space, but I'm way more concerned about the GC not working well
and those SIGSEGVs (80% is way too low to cause problems).
I think there might be some issue with the usage calculation in GC.
Perhaps you could try to lower the limit to trigger GC to something like
60% (down from the default 80%), and see if the issue persists? It can
be done by passing "-u 60" when launching kres-cache-gc.
On 05/06/2020 09.29, Petr Kyselák wrote:
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]: Cache
analyzed in 1.41
secs, 1038386 records, limit category is 100.
This shouldn't be related to the issue, but 1.4 secs is a long time to
analyze the cache, considering there's just 1 second delay before it is
triggered again. It's understandable given you're running it on
Raspberry Pi, but I'd consider changing the delay to something like 1
minute to prevent GC from consuming too much CPU. This can be done with
"-d 60000" argument to kres-cache-gc.
You can check how kres-cache-gc is executed from systemd by running:
$ systemctl cat kres-cache-gc.service | grep ExecStart
Then, you can override the arguments for the kres-cache-gc by creating a
systemd override for the kres-cache-gc.service unit:
$ systemctl edit kres-cache-gc.service
[Service]
ExecStart=<original_command> -u 60 -d 60000
And restart the kres-cache-gc.service. I'd be interested to know if the
issue persists with the lower GC limit.
--
Tomas Krizek
PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869
3:40 p.m.
Thank you for your reply.
OS:
# uname -a
Linux dns-cache-2 4.19.97-v7l+ #1294 SMP Thu Jan 30 13:21:14 GMT 2020
armv7l GNU/Linux
knot-resolver:
# dpkg-query -l | grep knot
ii knot-resolver 5.1.0-1
armhf caching, DNSSEC-validating DNS resolver
ii knot-resolver-module-http 5.1.0-1 all
HTTP/2 module for Knot Resolver
ii knot-resolver-release 1.7-1 all
Knot Resolver official upstream repositories
ii libknot10:armhf 2.9.4-1
armhf DNS shared library from Knot DNS
ii libknot8:armhf 2.7.6-2
armhf Authoritative domain name server (shared library)
source point to:
https://download.opensuse.org/repositories/home:/CZ-NIC:/knot-resolver-late…
Hope it is not an issue to run this build on raspbian OS.
I will try to modify kres-cache-gc.service as you suggest and let you know,
but this will take a few days.
Just FYI
we are running the same setup on two other servers but OS is CentOS 7
(64bit ) and same version of knot-resolver 5.1.0 and it works just fine.
pá 5. 6. 2020 v 14:28 odesílatel Tomas Krizek <tomas.krizek(a)nic.cz> napsal:
Hi,
thanks for the detailed report.
On 05/06/2020 13.46, Vladimír Čunát wrote:
Increasing your tmpfs size would probably avoid
the
out-of-space, but I'm way more concerned about the GC not working well
and those SIGSEGVs (80% is way too low to cause problems).
I think there might be some issue with the usage calculation in GC.
Perhaps you could try to lower the limit to trigger GC to something like
60% (down from the default 80%), and see if the issue persists? It can
be done by passing "-u 60" when launching kres-cache-gc.
On 05/06/2020 09.29, Petr Kyselák wrote:
Jun 4 16:32:05 dns-cache-2 kres-cache-gc[548]:
Cache analyzed in 1.41
secs, 1038386 records, limit category is 100.
This shouldn't be related to the issue, but 1.4 secs is a long time to
analyze the cache, considering there's just 1 second delay before it is
triggered again. It's understandable given you're running it on
Raspberry Pi, but I'd consider changing the delay to something like 1
minute to prevent GC from consuming too much CPU. This can be done with
"-d 60000" argument to kres-cache-gc.
You can check how kres-cache-gc is executed from systemd by running:
$ systemctl cat kres-cache-gc.service | grep ExecStart
Then, you can override the arguments for the kres-cache-gc by creating a
systemd override for the kres-cache-gc.service unit:
$ systemctl edit kres-cache-gc.service
[Service]
ExecStart=<original_command> -u 60 -d 60000
And restart the kres-cache-gc.service. I'd be interested to know if the
issue persists with the lower GC limit.
--
Tomas Krizek
PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869
8 Jun
8 Jun
4:37 p.m.
Thanks!
So far I managed to reproduce all the issues except for crashing.
(without Raspbian or Pi) We'll keep looking into those.
On 6/5/20 3:40 PM, Petr Kyselák wrote:
Hope it is not an issue to run this build on raspbian
OS.
The crashes themselves might be related. Raspbian [faq] discourages
such mixing. The "WILL NOT RUN" probably doesn't apply here (I think
it's just about v7 instruction support), but there are also parts like
"libraries build slightly differently". Still, I understand too little
about the compatibility, so it's well possible that none of your issues
is related this mixing of binaries.
[faq]
https://www.raspbian.org/RaspbianFAQ#Can_I_mix_packages_from_the_Debian_rep…
--Vladimir
1 Jul
1 Jul
4:04 p.m.
Hello.
On 6/8/20 4:37 PM, Vladimír Čunát wrote:
So far I managed to reproduce all the issues except
for crashing.
(without Raspbian or Pi) We'll keep looking into those.
These issues were fixed in today's 5.1.2 release. That is, except the
crashes which we still haven't managed to reproduce even once, and I
don't know what they're about. In case they do happen, the best
approach would probably be to analyze the coredump.
--Vladimir
2 Jul
2 Jul
11:04 a.m.
Hello,
thank you for your hard work. Yesterday I updated to 5.1.2.
Just for information. Suggested settings "-u 60 -d 60000" (on version
5.1.1) still lead to the issue with:
Jun 28 18:20:00 dns-cache-2 kresd[18328]: [cache] MDB_BAD_TXN, probably
overfull Jun 28 18:20:00 dns-cache-2 kresd[18328]: [cache] clearing because
overfull, ret = -28
I will keep an eye on 5.1.2 and let you know in week(s).
Thank you and have a nice day.
st 1. 7. 2020 v 16:04 odesílatel Vladimír Čunát <vladimir.cunat(a)nic.cz>
napsal:
Hello.
On 6/8/20 4:37 PM, Vladimír Čunát wrote:
So far I managed to reproduce all the issues
except for crashing.
(without Raspbian or Pi) We'll keep looking into those.
These issues were fixed in today's 5.1.2 release. That is, except the
crashes which we still haven't managed to reproduce even once, and I
don't know what they're about. In case they do happen, the best
approach would probably be to analyze the coredump.
--Vladimir
11:16 a.m.
On 7/2/20 11:04 AM, Petr Kyselák wrote:
Just for information. Suggested settings "-u 60
-d 60000" (on version
5.1.1) still lead to the issue
Yes, that's now expected on 32-bit 5.1.1 kres-cache-gc. An integer
overflow there commonly leads to collecting way few records, so the
cache overflows. With >= 5.1.2 you shouldn't need to tweak the GC
settings to avoid overfilling (but the above should also be OK).
--Vladimir
1620
days inactive
1647
days old
knot-resolver-users@lists.nic.cz
7 comments
3 participants
participants (3)
-
Petr Kyselák -
Tomas Krizek -
Vladimír Čunát