[NTP] Bug vraiment étrange

Support Debian
#1

J’ai chez moi depuis plus de six ans un serveur NTP (qui est d’ailleurs dans le pool NTP). Ce serveur marche fort bien mais a un bug bizarre depuis le passage à squeeze (sans certitude, je ne me souviens pas de ce bug au début mais bon).
Les faits:

Toutes les 2^22 secondes soit en gros 1 mois 20 jours, le serveur, prend 89,06s ( 89.061056 89.062137 89.060370 89.061128 89.061191 89.061366 89.060620 et 89.060533) d’avance (et est ejecté du pool donc). Les bugs se sont produit à ces dates (et peut être avant):

12/08/2014 13:44:02 30/09/2014 02:56:06 17/11/2014 15:02:38 05/01/2015 04:14:12 22/02/2015 17:21:55 12/04/2015 07:30:46 30/05/2015 20:40:21 18/07/2015 09:48:24

Le prochain est donc prévu le 4 septembre vers 22h53.

Le serveur est un stratum 2 et ça n’est pas du semble-t-il à une dérive du serveur de stratum 1 (un décalage à ce point n’est de toute façon pas possible).
Le noyau est un 2.6.32-5-686 et la ntp est 1:4.2.6.p2+dfsg-1+deb6u3

Sur un autre serveur ntp, lui aussi dans le pool, lui aussi squeeze, avec la même version de ntp mais le noyau de lenny 2.6.26-2-686, il n’y a pas ce bug.

Je pense plutôt à un souci matériel, j’ai le souvenir d’un plantage du module rtc de temps à autre avant de changer de noyau. La machine a été reboutée aux dates suivantes

francois@cerbere:/var/log$ ls -altr dmesg* -rw-r----- 1 root adm 6847 17 avril 2012 dmesg.4.gz -rw-r----- 1 root adm 6456 20 mai 2013 dmesg.3.gz -rw-r----- 1 root adm 6494 19 d�c. 2013 dmesg.2.gz -rw-r----- 1 root adm 7935 7 f�vr. 2014 dmesg.1.gz -rw-r----- 1 root adm 22567 10 avril 2014 dmesg.0 -rw-r----- 1 root adm 23616 7 mai 2014 dmesg le passage en squeeze ayant été fait le 7 février 2014.

C’est un FitPC installé en 2008 (cf fit-pc-des-experiences-t14156-25.html ) qui marche de façon continuelle (là son uptime est de 11:42:58 up 437 days, 3 min, 2 users, load average: 0.13, 0.29, 0.25).

Le bug en lui même ne me gêne pas, je vais faire un «at» régulier qui relancera le démon ntp tous les 2^22 secondes mais j’aimerais avoir une explication notamment savoir pourquoi 89,06s.

Si quelqu’un a une idée. Je poste aussi sur la DUF.

#2

Bonjour François, un truc que je n’ai pas compris dans ta description trés détaillée du problème. Est ce que cette avance de 89,06s est une dérive progressive, et atteint ce seuil elle est détecté, ou bien est ce une variation brutale ?
De ma connaissance, pour de si faible écarts, NTP ne fait pas de variations brutales, mais un rattrapage en douceur.
De plus, si j’ai bien compris l’heure sous linux, la rtc n’est pas l’heure utilisée par le systeme. Le système se fait sa propre heure, et même si la RTC n’est pas stable, l’heure système est stable.
Je vais réviser tout ça, car avec le temps, c’est devenu flou!

édit: C’est bien ce dont je me rappelais:

#3

Dérive brutale: Voilà l’heure du serveur par rapport à un serveur de référence

18; Jul; 09:32:24; -0.001192 18; Jul; 09:37:41; -0.001053 18; Jul; 09:43:06; -0.000326 18; Jul; 09:48:24; 89.060533 18; Jul; 09:53:38; 89.060750 18; Jul; 09:58:52; 89.060771 ou encore

12; Aug; 13:22:56; -0.000347 12; Aug; 13:28:11; -0.000256 12; Aug; 13:33:26; 0.000073 12; Aug; 13:38:42; -0.000186 12; Aug; 13:44:02; 89.061056 12; Aug; 13:49:17; 89.061565 12; Aug; 13:54:31; 89.060864 12; Aug; 13:59:46; 89.061072 Je pense qu’effectivement les 89,06s correspondent à une dérive (normale) de l’horloge système durant les 50 jours, ça fait du 2,12 10^-5 en dérive relative. C’est un ordre de grandeur convenable. Mais dans ce cas pourquoi donc l’heure système s’impose au bout de 2^22s?

Edit: J’ai redémarré le serveur, dans ce cas le prochain bug aura lieu le 5 septembre et non le 4 si c’est du au serveur lui même.

#4

c’est un des fonctionnement possible de NTP: recaler périodiquement les 2 horloges.
Mais il y a beaucoup de fonctionnements possibles, et de réglages possibles.
tldp.org/HOWTO/Clock-2.html

#5

Hum, j’ai regardé si c’était le cas. Rien de tel ici, j’ai regardé la signification de chacun des drapeaux de /sys/class/rtc/rtc0 et leur état. Il n’y a rien de lié à ça. Par contre ça m’a donné une idée, c’est de mettre à l’heure l’horloge système dans un mois pour voir si le décalage sera de 89,06s ou moins.

#6

La commande timedatectl peut servir à ça, et à bien d’autres choses.
Il y a aussi moyen de configurer ntpd pour qu’il fasse le contraire de la configuration par défaut, c’est à dire qu’il mette à l’heure la RTC régulièrement avec l’horloge systéme comme référence; c’est plus adapté pour un serveur qui est par définition toujours connecté (contrairement à un laptop).
Il semblerait qu’il y ai la possibilité de faire une synchro via un module kernel

ça doit étre une config de hwclock.
J’avais regardé tout ça lorsque je configurai des magnétoscope avec mythtv, mais mes souvenirs sont lointains …

édit: encore un truc configurable

#7

les problémes connus de ntpd
support.ntp.org/bin/view/Support/KnownOsIssues
rien vu qui ressemble à ton problème

edit: un truc quand même qui s’en rapproche:

[quote]9.2.4.2.3. Lost ticks causing clock instability

From gossamer-threads.com/lists/linux/kernel/494604

In 2.6, some code has been added to watch for “lost ticks” and increment the jiffies counter to compensate for them. A “lost tick” is when timer interrupts are masked for so long that ticks pile up and the kernel doesn’t see each one individually, so it loses count.

Lost ticks are a real problem, especially in 2.6 with the base interrupt rate having been increased to 1000 Hz, and it’s good that the kernel tries to correct for them. However, detecting when a tick has truly been lost is tricky. The code that has been added (both in timer_tsc.c’s mark_offset_tsc and timer_pm.c’s mark_offset_pmtmr) is overly simplistic and can get false positives. Each time this happens, a spurious extra tick gets added in, causing the kernel’s clock to go faster than real time. [/quote]

#8

J’ai retrouvé quelques infos que j’avais cherché à l’époque

[quote] CONFIG_RTC_SYSTOHC

Device Drivers -> RTC -> Set the RTC time based on NTP synchronization

The help says:

If you say yes here, the system time (wall clock) will be stored
in the RTC specified by RTC_HCTOSYS_DEVICE approximately every 11
minutes if userspace reports synchronized NTP status.
[/quote]

ntpd ne fait que des ajustement en douceur des horloges, alors que ntpdate peut faire des discontinuités. Il est donc recommandé de ne pas utiliser ntpdate.

#9

Doc lue, CONFIG_RTC_SYSTOHC met bien à jour l’horloge hardware avec l’heure système toutes les 11 minutes et non l’inverse. Cela devrait le faire sur ma machine, sauf si j’ai fait un hctosys à un moment donné (c’est possible mais guère important puisque lancé ntp remet la synchronisation). Bref cela devrait le faire sur le serveur et ne le fait peut être pas.

Mettre à jour régulièrement l’horloge hardware est une bonne idée mais ça ne répond pas au souci. J’avais bien pensé autoriser une adaptation à partir d’un décalage plus garnd, mais partant de 89,06s, sachant que l’écart est divisé par 2 toutes les 1024s, il faut en gros 4h pour le remettre à une heure correcte, ça fait beaucoup.

#10

ntpd ne fait que des ajustements en douceur, sauf en cas de très gros écarts.
Reste à comprendre pourquoi ntpd fait ce saut de 89sec. On dirait qu’il ne fait rien pour rattrapper e retard pendant longtemps, et lorsque la dérive est trop importante, il recale brutalement.
Ce n’est pas du tout son fonctionnement normal. Même si l’écart est grand entre les horloges, et que la machine accède aux serveur de temps, le système fera toujours confiance aux serveurs de temps. Ce n’est qu’en cas d’indisponibilité de ceux ci que le système se cale sur l’horloge RTC.
On dirait que ntpd déconne complètement sur ce serveur, voire qu’il est inactif, et qu’un autre logiciel effectue ce recalage brutal.

#11

[quote=“piratebab”]ntpd ne fait que des ajustements en douceur, sauf en cas de très gros écarts.
Reste à comprendre pourquoi ntpd fait ce saut de 89sec. On dirait qu’il ne fait rien pour rattrapper e retard pendant longtemps, et lorsque la dérive est trop importante, il recale brutalement.[/quote]Non, au contraire. Il est parfaitement ajusté (tu as la courbe sur 24h glissante ici: ), l’étonnant est ce décrochement brutal qui semble soit un pbm de retenue, soit peut être un calage soudain sur l’heure hardware si celle ci n’est pas ajustée. Mais pendant tout le temps le serveur était parfaitement ajusté avec un écart d’au maximum 5ms[quote]
Ce n’est pas du tout son fonctionnement normal.[…]
On dirait que ntpd déconne complètement sur ce serveur, voire qu’il est inactif, et qu’un autre logiciel effectue ce recalage brutal.[/quote]
ntp fonctionne parfaitement sauf à cet instant précis, je gère 5 serveurs dans le pool fr.pool.ntp.org (2 ipv6 et 3 ipv4), ça me permet de voir entre autres si l’un d’entre eux dérive ce qui n’a jamais été le cas. De plus le recalage fait passer de l’heure exacte à une heure inexacte (seule l’horloge système pourrait ne pas être à l’heure éventuellement).

#12

c’est vraiment étrange ce comportement.
essaie de tracker la RTC et l’heure système à intervalles réguliers pour voir si il y a une dérive continue.
Si c’est le cas, ntp et le kernel ne font pas leur boulot de recalage de la RTC, ou la RTC ne se laisse pas mettre à jour.
Il y a un test intéressant à faire (pas toujours possible). Tu coupes le serveur pendant 24 heures et tu mesures la dérive de la RTC. et tu regardes si au boot le systeme recale bien la RTC.

#13

Oui je pourrais, je vais plutôt attendre trnaquillement 15 jours et regarder si il y a un décalage: 89s sur 50 jous, ça se voit au bout d’une semaine à 15 jours et ça évitera une suspension du service. Mais quel que soit le souci de cet horloge RTC, ça n’explique pas cette bascule soudaine; L’heure RTC ne sert strictement à rien sur mon serveur excepté au démarrage.
NB: Tu peux tester le serveur si tu veux, c’est entre autres clefagreg.dnsalias.org

#14

si tu constates un décalage, c’est que ni le kernel, ni le ntpd ne font leur boulot, ou que la RTC ne se laisse pas mettre à jour par ces 2 là.
Ce qui n’est pas normal non plus, c’est le recalage de l’horloge système sur la RTC. ntpd n’est pas censé faire ça par défaut. Soit tu as une config particulière de ntpd (config d’un device peu connecté à internet dont la RTC est réputée fiable et est donc prise comme référence), soit tu as un autre logiciel qui prends l’initiative de ce recalage (ntpdate ?)

#15

[quote=“piratebab”]si tu constates un décalage, c’est que ni le kernel, ni le ntpd ne font leur boulot, ou que la RTC ne se laisse pas mettre à jour par ces 2 là.
Ce qui n’est pas normal non plus, c’est le recalage de l’horloge système sur la RTC. ntpd n’est pas censé faire ça par défaut.[/quote]
Je détaille ce que je comprends: Tu as deux heures, la RTC (horloge hardware) peu fiable, et l’heure système, fiable surtout quand un ntp la cale sur d’autres serveurs.

Au démarrage, l’heure système est initialisée par l’heure hardware puis elle est ajustée:

  • par le noyau par une estimation de la dérive dont les paramètres sont dans /etc/adjtime, paramètres ajustés au fur et à mesure.
  • Par un serveur NTP qui se cale sur d’autres machines de la façon suivante: S envoit un signal à son temps t et reçoit le temps t’ de reception de ce signal du serveur S’, puis S’ envoit au signal un temps T’ qui est reçu par S au temps T. Le temps de transmission est d=((T-t)- (T’-t’))/2 et le décalage entre les horloges est t’-t - d. Après il y a une pondération si il y a plusieurs serveurs de référence.

Cette heure système est dans tous les cas beaucoup plus fiable que l’heure hardware. La configuration standard consiste à ce que le noyau corrige l’heure hardware (l’heure RTC donc) régulièrement soit donc toutes les 11 minutes. Ce réglage dépend du statut de l’horloge interne (lisible par exemple par ntpdc -c kerninfo). De ce que j’ai compris, si une correction manuelle est faite (par hwclock --systohc), alors cette mise à jour automatique toutes les 11 minutes peut se désactiver. Par contre ntpd active cette mise à jour automatique.

Le serveur dont on parle a un réglage standard commun à mes 4 autres serveurs NTP, donc notamment l’horloge RTC devrait être mise à jour automatiquement. ntpd fonctionne parfaitement sauf tout les 2^22s ou apparait un décalage soudain de 89,06s. Ce décalage n’est pas une correction de ntpd (trop gros). Je ne sais pas à l’heure actuelle si c’est l’heure RTC non corrigée qui s’est imposée, simplement ce décalage de 89,06s est compatible avec une dérive de l’horloge RTC non corrigée, c’est une hypothèse que je conserve, mais c’est peut être du à autre chose. Ça n’est pas un acquis.

ntpdate ne peut être utilisée en même temps que ntp (il gueule) sauf à changer de port. adjtimex pourrait être en cause mais n’est pas présent.

Il est très probable qu’il s’agit d’un bug matériel ne serait ce que parce qu’à configuration égale c’est un bug que je ne retrouve pas ailleurs. Le souci est que le temps que je m’aperçoive du décalage soudain, l’heure système (devenue soudaint mauvaise donc) a de toute façon écrasé l’heure RTC.

#16

Faire le suivi de l’heure système et de l’heure RTC me semble un bon début. S’il n’y a pas d’écart constaté c’est qu’un élément extérieur viens mettre son grain de sel.

#17

En fait tout se passe comme si pendant une période de 89,06s la machine se gelait, dans cette hypothèse, on verrait peu de temps avant. J’ai fait un programme qui me compare l’heure système et leur matérielle, à suivre…

#18

Autre chose qui m’incite à penser à des interruptions non traitées:
Voilà un partie du fichier de log (j’"ai une manie, je je fais des logs de
tout):
Dans l’ordre, Jour, Mois, Heure, Minutes, Seconde, Decalage avec
un autre serveur NTP, temps en secondes depuis le début de la journée
et enfin temps écoulé jusqu’à la ligne suivante.

18 Jul 9 32 24 -0,001192 34344 317 18 Jul 9 37 41 -0,001053 34661 325 18 Jul 9 43 6 -0,000326 34986 318 18 Jul 9 48 24 89,060533 35304 314 18 Jul 9 53 38 89,06075 35618 314 18 Jul 9 58 52 89,060771 35932 318 18 Jul 10 4 10 89,061083 36250 314 18 Jul 10 9 24 89,060588 36564 315 18 Jul 10 14 39 89,060753 36879 403 18 Jul 10 21 22 -0,000297 37282 314 18 Jul 10 26 36 -0,000587 37596 314
On voit bien le souci à 09:48:24, on voit bien que malgré le décalage
de leur système, le temps écoulé entre deux enregistrements restde de l’ordre
de 315s. On voit également que lorsque j’ai remis la machine à l’heure,
il y a un décalage de l’ordre de 89s (403 - 89 = 314). Le script est un

while /bin/true; do betises diverses sleep 300 done
sleep appelle xnanosleep qui appelle nanosleep. La norme POSIX indique que

[quote]«Configurer la valeur de l’horloge CLOCK_REALTIME avec clock_settime() ne
doit pas avoir d’effet sur les threads bloqués attendant un service de temps
relatif basé sur cette horloge. Cela inclut la fonction nanosleep() ;
En conséquence, ces services de temps doivent expirer lorsque la durée
relative demandée est atteinte, indépendamment de l’ancienne ou
la nouvelle valeur de l’horloge. »[/quote]

En clair donc, il y eu pour la machine 314s d’interruption horloge entre chaque
ligne, changement d’heure ou pas. Lorsque j’ai changé d’heure, lui faisant rattraper
les 89,06s perdus, on retrouve ces 89,06s dans l’expression du temps écoulé entre deux
mesures (314s vraies + 89s de décalage du à ma remise à l’heure). Par contre, lors
du bug, il n’y a pas de décalage dans le temps écoulé, on aurait du avoir
314-89=225 [À ce stade, je félicite les 5 qui sont encore en train de lire!]. Bref
tout ça pour dire qu’on dirait bien que la machine s’est figée 89s ou que c’est
tout comme. Vraiment mystérieux ce truc.

#19

As-tu moyen de faire une copie complète du disque dur et de faire tourner tous tes services de la même manière sur une autre machine ? Juste pour pouvoir écarter ou confirmer le problème matériel.

#20

Hum, non ça me parait difficile de bloquer une machine 2 mois.