[SOLVED] Starke Verzögerung von pve-daily-update.service

toheine · Jan 27, 2022

Hallo zusammen,

ich möchte hier folgende Frage in die Runde werfen und freue mich über Antworten.

Es geht um einen 6-Node-Promox-Cluster der grundsätzlich sauber läuft und ich keine großen Probleme sehe. Allerdings meldet das Monitoring jede Nacht, dass drei der 6 PVEs (pvehost04-06) einen starken Delay mit dem Service pve-daily-update haben. systemctl status pve-daily-update.service gibt hierzu auszugsweise folgendes aus:

Bash:

Jan 27 02:04:07 pvehost06 systemd[1]: Starting Daily PVE download activities...
Jan 27 02:17:12 pvehost06 pveupdate[1633739]: <root@pam> starting task UPID:pvehost06:[...]

Es werden keine Fehler erzeugt. Der Service tut augenscheinlich was er soll. Ein manuelles apt update geht auch ratz-fatz.

Ich stolpere da drüber weil das Monitoring jede Nacht 6 unnötige Notifications wirft (3x crit und 3x ok nach 20 Minuten). Ursprünglich hatte ich gedacht, dass ich in Checkmk diesen Service einfach mit einem 30-Minuten-Delay versehe und Ruhe ist. Jetzt möchte ich aber doch eher die Ursache finden zumal ja bei den identisch konfiguriereten pvehost01-03 keine Verzögerung auftritt.

Hat hier jemand einen Ansatz für mich oder ist über ein ähnliches Problem gestolpert?

Danke schon Mal.

Viele Grüße

Tobi

mira · Jan 27, 2022

Der pve-daily-update.timer hat ein RandomizedDelayUSec=4h definiert. Das heißt der Server wird bis zu 4h delayed, und dieses Delay zufällig gewählt.

Der pve-daily-update.service sollte somit täglich zwischen 2:00 und 6:00 laufen.

toheine · Jan 27, 2022

Danke für die schnelle Antwort. Ich bin mir aber nicht sicher ob das die Ursache ist. Der Timer ruft ja den Service (jeden Tag zu anderen Zeiten auf). Das kann ich mit journalctl -u pve-daily-update.service für die letzten 3 Monate einsehen. Aber wenn der der Service dann mal ausgelöst wird, erfolgt halt immer ziemlich genau ein 13-Minuten-Delay. Und das nur auf 3 von 6 Nodes.

mira · Jan 27, 2022

Was sagen denn die Befehle systemctl show pve-daily-update.timer und systemctl show pve-daily-update.service?

toheine · Jan 27, 2022

systemctl show pve-daily-update.timer sagt:

Bash:

root@pvehost06 ~ # systemctl show pve-daily-update.timer
Unit=pve-daily-update.service
TimersCalendar={ OnCalendar=*-*-* 02:00:00 ; next_elapse=Fri 2022-01-28 02:00:00 CET }
OnClockChange=no
OnTimezoneChange=no
NextElapseUSecRealtime=Fri 2022-01-28 05:58:58 CET
NextElapseUSecMonotonic=0
LastTriggerUSec=Thu 2022-01-27 02:04:07 CET
LastTriggerUSecMonotonic=1month 3d 22h 35min 42.048032s
Result=success
AccuracyUSec=1min
RandomizedDelayUSec=4h
FixedRandomDelay=no
Persistent=yes
WakeSystem=no
RemainAfterElapse=yes
Id=pve-daily-update.timer
Names=pve-daily-update.timer
Requires=sysinit.target -.mount
WantedBy=timers.target
Conflicts=shutdown.target
Before=pve-daily-update.service shutdown.target timers.target
After=time-sync.target -.mount sysinit.target
Triggers=pve-daily-update.service
RequiresMountsFor=/var/lib/systemd/timers
Description=Daily PVE download activities
LoadState=loaded
ActiveState=active
FreezerState=running
SubState=waiting
FragmentPath=/lib/systemd/system/pve-daily-update.timer
UnitFileState=enabled
UnitFilePreset=enabled
StateChangeTimestamp=Thu 2022-01-27 02:17:14 CET
StateChangeTimestampMonotonic=2971129284811
InactiveExitTimestamp=Wed 2022-01-26 21:12:04 CET
InactiveExitTimestampMonotonic=2952818948059
ActiveEnterTimestamp=Wed 2022-01-26 21:12:04 CET
ActiveEnterTimestampMonotonic=2952818948059
ActiveExitTimestamp=Wed 2022-01-26 21:12:04 CET
ActiveExitTimestampMonotonic=2952818947940
InactiveEnterTimestamp=Wed 2022-01-26 21:12:04 CET
InactiveEnterTimestampMonotonic=2952818947940
CanStart=yes
CanStop=yes
CanReload=no
CanIsolate=no
CanClean=state
CanFreeze=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureJobMode=replace
IgnoreOnIsolate=no
NeedDaemonReload=no
JobTimeoutUSec=infinity
JobRunningTimeoutUSec=infinity
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Wed 2022-01-26 21:12:04 CET
ConditionTimestampMonotonic=2952818947958
AssertTimestamp=Wed 2022-01-26 21:12:04 CET
AssertTimestampMonotonic=2952818947960
Transient=no
Perpetual=no
StartLimitIntervalUSec=10s
StartLimitBurst=5
StartLimitAction=none
FailureAction=none
SuccessAction=none
InvocationID=4965c76108cb4d06b1efbc3d2318d1a5
CollectMode=inactive

und

systemctl show pve-daily-update.service erzeugt folgende Ausgabe:

Bash:

root@pvehost06 ~ # systemctl show pve-daily-update.service
Type=oneshot
Restart=no
NotifyAccess=none
RestartUSec=100ms
TimeoutStartUSec=infinity
TimeoutStopUSec=1min 30s
TimeoutAbortUSec=1min 30s
TimeoutStartFailureMode=terminate
TimeoutStopFailureMode=terminate
RuntimeMaxUSec=infinity
WatchdogUSec=0
WatchdogTimestampMonotonic=0
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=0
ControlPID=0
FileDescriptorStoreMax=0
NFileDescriptorStore=0
StatusErrno=0
Result=success
ReloadResult=success
CleanResult=success
UID=[not set]
GID=[not set]
NRestarts=0
OOMPolicy=stop
ExecMainStartTimestamp=Thu 2022-01-27 02:04:07 CET
ExecMainStartTimestampMonotonic=2970342068113
ExecMainExitTimestamp=Thu 2022-01-27 02:17:14 CET
ExecMainExitTimestampMonotonic=2971129284225
ExecMainPID=1633739
ExecMainCode=1
ExecMainStatus=0
ExecStart={ path=/usr/bin/pveupdate ; argv[]=/usr/bin/pveupdate ; ignore_errors=no ; start_time=[Thu 2022-01-27 02:04:07 CET] ; stop_time=[Thu 2022-01-27 02:17>
ExecStartEx={ path=/usr/bin/pveupdate ; argv[]=/usr/bin/pveupdate ; flags= ; start_time=[Thu 2022-01-27 02:04:07 CET] ; stop_time=[Thu 2022-01-27 02:17:14 CET]>
Slice=system.slice
MemoryCurrent=[not set]
CPUUsageNSec=2299748000
EffectiveCPUs=
EffectiveMemoryNodes=
TasksCurrent=[not set]
IPIngressBytes=[no data]
IPIngressPackets=[no data]
IPEgressBytes=[no data]
IPEgressPackets=[no data]
IOReadBytes=18446744073709551615
IOReadOperations=18446744073709551615
IOWriteBytes=18446744073709551615
IOWriteOperations=18446744073709551615
Delegate=no
CPUAccounting=yes
CPUWeight=[not set]
StartupCPUWeight=[not set]
CPUShares=[not set]
StartupCPUShares=[not set]
CPUQuotaPerSecUSec=infinity
CPUQuotaPeriodUSec=infinity
AllowedCPUs=
AllowedMemoryNodes=
IOAccounting=no
IOWeight=[not set]
StartupIOWeight=[not set]
BlockIOAccounting=no
BlockIOWeight=[not set]
StartupBlockIOWeight=[not set]
MemoryAccounting=yes
DefaultMemoryLow=0
DefaultMemoryMin=0
MemoryMin=0
MemoryLow=0
MemoryHigh=infinity
MemoryMax=infinity
MemorySwapMax=infinity
MemoryLimit=infinity
DevicePolicy=auto
TasksAccounting=yes
TasksMax=154400
IPAccounting=no
ManagedOOMSwap=auto
ManagedOOMMemoryPressure=auto
ManagedOOMMemoryPressureLimitPercent=0%
UMask=0022
LimitCPU=infinity
LimitCPUSoft=infinity
LimitFSIZE=infinity
LimitFSIZESoft=infinity
LimitDATA=infinity
LimitDATASoft=infinity
LimitSTACK=infinity
LimitSTACKSoft=8388608
LimitCORE=infinity
LimitCORESoft=0
LimitRSS=infinity
LimitRSSSoft=infinity
LimitNOFILE=524288
LimitNOFILESoft=1024
LimitAS=infinity
LimitASSoft=infinity
LimitNPROC=514667
LimitNPROCSoft=514667
LimitMEMLOCK=65536
LimitMEMLOCKSoft=65536
LimitLOCKS=infinity
LimitLOCKSSoft=infinity
LimitSIGPENDING=514667
LimitSIGPENDINGSoft=514667
LimitMSGQUEUE=819200
LimitMSGQUEUESoft=819200
LimitNICE=0
LimitNICESoft=0
LimitRTPRIO=0
LimitRTPRIOSoft=0
LimitRTTIME=infinity
LimitRTTIMESoft=infinity
RootHashSignature=
OOMScoreAdjust=0
CoredumpFilter=0x33
Nice=0
IOSchedulingClass=0
IOSchedulingPriority=0
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
CPUAffinity=
CPUAffinityFromNUMA=no
NUMAPolicy=n/a
NUMAMask=
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardInputData=
StandardOutput=journal
StandardError=inherit
TTYReset=no
TTYVHangup=no
TTYVTDisallocate=no
SyslogPriority=30
SyslogLevelPrefix=yes
SyslogLevel=6
SyslogFacility=3
LogLevelMax=-1
LogRateLimitIntervalUSec=0
LogRateLimitBurst=0
SecureBits=0
CapabilityBoundingSet=cap_chown cap_dac_override cap_dac_read_search cap_fowner cap_fsetid cap_kill cap_setgid cap_setuid cap_setpcap cap_linux_immutable cap_n>
AmbientCapabilities=
DynamicUser=no
RemoveIPC=no
MountFlags=
PrivateTmp=no
PrivateDevices=no
ProtectClock=no
ProtectKernelTunables=no
ProtectKernelModules=no
ProtectKernelLogs=no
ProtectControlGroups=no
PrivateNetwork=no
PrivateUsers=no
PrivateMounts=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=no
UtmpMode=init
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=2147483646
LockPersonality=no
RuntimeDirectoryPreserve=no
RuntimeDirectoryMode=0755
StateDirectoryMode=0755
CacheDirectoryMode=0755
LogsDirectoryMode=0755
ConfigurationDirectoryMode=0755
TimeoutCleanUSec=infinity
MemoryDenyWriteExecute=no
RestrictRealtime=no
RestrictSUIDSGID=no
RestrictNamespaces=no
MountAPIVFS=no
KeyringMode=private
ProtectProc=default
ProcSubset=all
ProtectHostname=no
KillMode=control-group
KillSignal=15
RestartKillSignal=15
FinalKillSignal=9
SendSIGKILL=yes
SendSIGHUP=no
WatchdogSignal=6
Id=pve-daily-update.service
Names=pve-daily-update.service
Requires=sysinit.target system.slice
Wants=network-online.target pve-cluster.service
Conflicts=shutdown.target
Before=shutdown.target
After=pve-daily-update.timer network-online.target sysinit.target system.slice systemd-journald.socket pve-cluster.service basic.target
TriggeredBy=pve-daily-update.timer
Description=Daily PVE download activities
LoadState=loaded
ActiveState=inactive
FreezerState=running
SubState=dead
FragmentPath=/lib/systemd/system/pve-daily-update.service
UnitFileState=static
UnitFilePreset=enabled
StateChangeTimestamp=Thu 2022-01-27 02:17:14 CET
StateChangeTimestampMonotonic=2971129284361
InactiveExitTimestamp=Thu 2022-01-27 02:04:07 CET
InactiveExitTimestampMonotonic=2970342068277
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestamp=Thu 2022-01-27 02:17:14 CET
InactiveEnterTimestampMonotonic=2971129284361
CanStart=yes
CanStop=yes
CanReload=no
CanIsolate=no
CanFreeze=yes
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureJobMode=replace
IgnoreOnIsolate=no
NeedDaemonReload=no
JobTimeoutUSec=infinity
JobRunningTimeoutUSec=infinity
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Thu 2022-01-27 02:04:07 CET
ConditionTimestampMonotonic=2970342048227
AssertTimestamp=Thu 2022-01-27 02:04:07 CET
AssertTimestampMonotonic=2970342048229
Transient=no
Perpetual=no
StartLimitIntervalUSec=10s
StartLimitBurst=5
StartLimitAction=none
FailureAction=none
SuccessAction=none
InvocationID=cbeca086bf724c59aaa05ce022e56482
CollectMode=inactive
lines 224-246/246 (END)

Danke für die Hilfe!

mira · Jan 27, 2022

Dauert ein pveupdate ebenfalls so lange wenn es direkt aufgerufen wird?
pveupdate macht noch einiges mehr als nur apt update aufzurufen. Also kann es an mehreren Dingen liegen.

toheine · Jan 27, 2022

Tatsächlich: Das dauert so ziemlich genau die gleichen 13 Minuten. Ich habe den Befehl pveupdate um 13:28 Uhr gestartet und journalctl liefert folgende Ausgabe dazu:

Bash:

Jan 27 13:41:51 pvehost06 pveupdate[3803197]: <root@pam> starting task UPID:pvehost06:003AA827:11F442F1:61F2930F:aptupdate::root@pam:
Jan 27 13:41:52 pvehost06 pveupdate[3844135]: update new package list: /var/lib/pve-manager/pkgupdates
Jan 27 13:41:53 pvehost06 systemd[1]: Starting Check_MK (10.1.0.14:45582)...
Jan 27 13:41:53 pvehost06 pveupdate[3803197]: <root@pam> end task UPID:pvehost06:003AA827:11F442F1:61F2930F:aptupdate::root@pam: OK

Im Taskviewer sieht es so aus als hätte der Aufruf nur 2 Sekunden gedauert:

mira · Jan 27, 2022

Benötigt das Starten von anderen Tasks ebenfalls so lange?
Man könnte versuchen pveproxy und pvedaemon neuzustarten (systemctl restart pveproxy.service pvedaemon.service).

toheine · Jan 27, 2022

Benötigt das Starten von anderen Tasks ebenfalls so lange?

Eigentlich sind mir keine Verzögerungen aufgefallen. Wenn das Ding nicht an Checkmk hängen würde, hätte ich den Delay überhaupt nicht gemerkt.

Man könnte versuchen pveproxy und pvedaemon neuzustarten (systemctl restart pveproxy.service pvedaemon.service).

... das habe ich gemacht. Ging schnell und fehlerfrei durch.

mira · Jan 27, 2022

Wenn es sonst keine Beeinträchtigungen gibt, und ein `pveupdate` auch nach dem Restart von Proxy und Daemon so lange benötigt, liegt es womöglich an einen der folgenden Aufrufe:

Code:

eval { PVE::API2::Subscription->update({ node => $nodename }); };
eval { PVE::APLInfo::update($dccfg->{http_proxy}); };

Wie sieht es aus wenn du ein pvesubscription update und ein pveam update aufrufst?

toheine · Jan 31, 2022

Hallo Mira,

sorry für die Verzögerung. Ich habe das jetzt mal gecheckt. Ich habe die beiden Befehle abgeschickt. pvesubscription update läuft ohne Verzögerung durch. Aber pveam update hat eine starke Verzögerung. Ich hab mir im Anschluss angeschaut, was außer Deinen Code-Zeilen noch in /us/bin/pveupdate steht. Hier wird auf die Log-Datei /var/log/pveam.log verwiesen. Diese hat soeben folgende Ausgabe erzeugt:

Code:

2022-01-31 14:50:53 starting update
2022-01-31 14:50:53 start download http://download.proxmox.com/images/aplinfo-pve-7.dat.asc
2022-01-31 14:53:03 download finished: 200 OK
2022-01-31 14:53:03 start download http://download.proxmox.com/images/aplinfo-pve-7.dat.gz
2022-01-31 14:55:14 download finished: 200 OK
2022-01-31 14:55:14 signature verification: gpgv: Signature made Thu Dec  2 18:40:29 2021 CET
2022-01-31 14:55:14 signature verification: gpgv:                using RSA key 28139A2F830BD68478A1A01FDD4BA3917E23BF59
2022-01-31 14:55:14 signature verification: gpgv: Good signature from "Proxmox Bullseye Release Key <proxmox-release@proxmox.com>"
2022-01-31 14:55:14 update successful
2022-01-31 14:55:14 start download https://releases.turnkeylinux.org/pve/aplinfo.dat.asc
2022-01-31 14:59:37 download finished: 200 OK
2022-01-31 14:59:37 start download https://releases.turnkeylinux.org/pve/aplinfo.dat.gz
2022-01-31 15:03:59 download finished: 200 OK
2022-01-31 15:03:59 signature verification: gpgv: Signature made Sun Nov  7 12:25:46 2021 CET
2022-01-31 15:03:59 signature verification: gpgv:                using RSA key 694CFF26795A29BAE07B4EB585C25E95A16EB94D
2022-01-31 15:03:59 signature verification: gpgv: Good signature from "Turnkey Linux Release Key <release@turnkeylinux.com>"
2022-01-31 15:03:59 update successful

Jetzt habe ich zumindest eine Ahnung woher die 13 Minuten kommen. Allerdings verstehe ich überhaupt nicht warum das so lange dauert. Node 1 zum Vergleich:

Code:

2022-01-31 15:18:23 starting update
2022-01-31 15:18:23 start download http://download.proxmox.com/images/aplinfo-pve-7.dat.asc
2022-01-31 15:18:23 download finished: 200 OK
2022-01-31 15:18:23 start download http://download.proxmox.com/images/aplinfo-pve-7.dat.gz
2022-01-31 15:18:23 download finished: 200 OK
2022-01-31 15:18:23 signature verification: gpgv: Signature made Thu Dec  2 18:40:29 2021 CET
2022-01-31 15:18:23 signature verification: gpgv:                using RSA key 28139A2F830BD68478A1A01FDD4BA3917E23BF59
2022-01-31 15:18:23 signature verification: gpgv: Good signature from "Proxmox Bullseye Release Key <proxmox-release@proxmox.com>"
2022-01-31 15:18:23 update successful
2022-01-31 15:18:23 start download https://releases.turnkeylinux.org/pve/aplinfo.dat.asc
2022-01-31 15:18:23 download finished: 200 OK
2022-01-31 15:18:23 start download https://releases.turnkeylinux.org/pve/aplinfo.dat.gz
2022-01-31 15:18:24 download finished: 200 OK
2022-01-31 15:18:24 signature verification: gpgv: Signature made Sun Nov  7 12:25:46 2021 CET
2022-01-31 15:18:24 signature verification: gpgv:                using RSA key 694CFF26795A29BAE07B4EB585C25E95A16EB94D
2022-01-31 15:18:24 signature verification: gpgv: Good signature from "Turnkey Linux Release Key <release@turnkeylinux.com>"
2022-01-31 15:18:24 update successfull

Jetzt wo dank Deiner Hilfe die Ursache gefunden scheint ... wäre ich dankbar für einen Tipp der das Problem noch löst ;-)

Danke schon Mal.

Viele Grüße

Tobi

toheine · Jan 31, 2022

Ich hab die Ursache gefunden. Die IPv6-Konfiguration auf den den Nodes 4 bis 6 passt nicht. Daher versuchen diese Geräte den Download per ipv6, laufen dann in den Timeout und ziehen dann die Infos per IPv4 nach.

Search

Search

[SOLVED] Starke Verzögerung von pve-daily-update.service

toheine

Member

mira

Proxmox Staff Member

toheine

Member

mira

Proxmox Staff Member

toheine

Member

mira

Proxmox Staff Member

toheine

Member

mira

Proxmox Staff Member

toheine

Member

mira

Proxmox Staff Member

toheine

Member

toheine

Member

We value your privacy