[SOLVED] High Load because of PVE Storage checks

[Apollon77]

I test wise add a PBS storage to my 7 host PVE cluster ... the results was that in the pbs I had 2 processes with 130% CPU and a flooded syslog with authentication requests ... every second roughly 1 request per host ... It also feels like the hosts (especially one with the worst hardware) was slowed down api wise a lot (it took again PVE web interface to lead e.g. a host summary). It restored to original performance directly as I disabled the pbs storage in pve again.

I think the idea to do an API call once per second migth not be the best ...

Is this already known?

Thank you,

Ingo

 

[fabian]

https://bugzilla.proxmox.com/show_bug.cgi?id=2903 is part of that, but the only recurring API call should be the status one which should be quite fast.. can you check the access logs whether any other requests occur that often from your PVE hosts?

 

[Apollon77]

Where I can find access logs of the pbs?

 

[Apollon77]

PS: I also checked: The syslog
>
Jul 30 08:31:16 pbs proxmox-backup-api[612]: successful auth for user 'backup@pbs'

comes 14 times per second ... so basically 2 per second from each PVE host ...

 

[Apollon77]

And when this runs the pve api itself (so NOT the pbs one!) is behaving very slow ... so it seems that this high frequency of calls makes the pve api more of a problem then for the pbs api!! So maybe it is also more a ""backup-integration in PVE" issue then a pure pbs issue.
PBS API was behaving ok and so here only the syslog was hammered with these logs ...

 

[fabian]

hm, it seems like request logging is not implemented for PBS (yet). I only see 2 requests (+2 logins) per configured datastore every 10s (when pvestatd runs) - one for checking whether the storage is online, and one for the actual status. are the PVE hosts clustered? if not, are there migrations or replications going on?

 

[Apollon77]

It is a PVE HS Cluster with 7 hosts. No migrations or replications running.

But I can reproduce that completely: As soon as I enable the pbs storage in PVE it starts ... when I disable the pbs stprage it stops

 

[fabian]

very strange indeed. if you want you can wrap 'proxmox-backup-client' with a shell script that dumps the parameters, then we'd get a better idea what kind of requests they are. or you wait until request logging is implemented in PBS.

 

[Apollon77]

Could you provice me such a shell script then I can try on one host

 

[fabian]

mv /usr/bin/proxmox-backup-client /usr/bin/proxmox-backup-client.orig
echo '#!/bin/bash\necho "$(date) - $@" >> /tmp/pbs-client.log\nproxmox-backup-client.orig "$@"' > /usr/bin/proxmox-backup-client
chmod +x /usr/bin/proxmox-backup-client

now /tmp/pbs-client.log should fill with lines like the following:

Fri Jul 31 11:31:55 CEST 2020 - status --output-format=json --repository test@pbs@127.0.0.1:backuptest
Fri Jul 31 11:31:55 CEST 2020 - status --output-format=json --repository test@pbs@127.0.0.1:backuptest

two of those for every datastore configured, every 10s is the baseline. anything else should be triggered by actions like backup/restore, backup storage content view, ...

 

[Apollon77]

Ok, here we go
I changed that on one host.
I enabled the storage via PVE ... and immediately it started flooding again. I did nothing else ... no backups, no nothings

Fri Jul 31 13:38:10 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:10 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:10 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:10 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:10 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:11 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:12 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:12 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:12 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:12 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:13 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:13 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:14 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:14 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:15 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:15 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:15 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:15 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:16 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:16 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:17 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:17 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:18 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:18 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:18 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:20 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Fri Jul 31 13:38:20 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
...

and it stopped as I disabled the storage again

I'm on the "free" ap repo and also checked ... no updates outstanding on PVE

 

[fabian]

interesting. so these are either calls to the status method of the PBS storage plugin, or more likely, calls to 'activate' the storage. could you cross check with your pveproxy access log for that time range? any worker tasks running at the time? thanks!

 

[Apollon77]

Ok, I reasearched more and I have news. I found basically the reason ... I had one script running which collected some statistic and it seems that this script is checking shared storaged "per node"

BUT in the end after disabling this I still see TWO calls per Host every 10s ...

Mon Aug  3 23:04:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:30 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:30 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:40 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:40 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:50 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:50 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:59 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:04:59 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:09 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:09 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:19 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:29 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:30 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:40 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:40 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:49 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:49 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:59 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1
Mon Aug  3 23:05:59 CEST 2020 - status --output-format=json --repository backup@pbs@192.168.178.131:backup-store1

 

[fabian]

yes, those two are by pvestatd which collects storage statistics every 10s. they can still be optimized further (cache ticket, only 1 call)

 

[Apollon77]

Ok, then "solved". Sorry for the stress