Je n’ai pas bien compris ton log.
que c’est il passé à 09:48:24 .Est ce un échelon “spontané” de l’heure système, ou bien une intervention de ta part ?
[quote=“piratebab”]Je n’ai pas bien compris ton log.
que c’est il passé à 09:48:24 .Est ce un échelon “spontané” de l’heure système, ou bien une intervention de ta part ?[/quote]
Ben c’est le bug. Un décalage soudain qui apparait. Semble-t-il tout ce passe comme si la machine était resté gelée 89,06s. L’expérience avec nanosleep est intéressante car sleep est censé être indépendant d’un changement de l’horloge entre temps. Hors ici, sleep a suivi le changement de temps. Mon intervention est après, à la remise à l’heure. Là on voit bien que le temps apparent de l’éxécution est plus long (403s), compte tenu du fait que j’ai avancé l’horloge de 89,06s (retard qu’elle avait pris), le temps réel d’éxécution est 403-89=314 ce qui est normal.
Je ne comprends pas ton raisonnement. Si sleep est indépendant de l’horloge système, lors du bug, il ne se passe rien sur le temps de calcul, donc la machine tourne normalement, elle ne se fige pas.
C’est l’horloge système qui fait un saut. L’hormoge hwclock étant un fichier, tu pourrais essayer de tracer qui écrit dans ce fichier (et aussi qui le lit, ça peut étre surprenant).
quand au rattrapage manuel, je ne comprends pas. Si sleep est indépendant de l’horloge systeme, pourquoi cette augmentation du temps de calcul ?
Ce qui s’affiche (314, 318, 403, etc) est la différence entre le temps sur un serveur NTP distant et l’heure système de ma machine. Donc, entre 09:43:06 (heure système lue) et 09:48:24, alors que pour ma machine, il s’est passé 318s, il s’est en fait déroulé 318s+89s=407s. L’horloge système a pris un retard soudain de 89s, comme nanosleep est indépendant de l’heure système, si tout c’était passé normalement, au lieu de 318s, il y aurait du avoir affichée la différence entre l’heure système lue (soit l’heure réelle - 89s) et l’heure lue d’avant soit l’heure réelle d’avant, c’est à dire 318s-89s=29s. Ça n’est pas le cas, donc la boucle entre 09:43:06 (heure système lue) et 09:48:24 (heure système lu) n’a pas duré 318s mais 318+89= 407s. En clair le nanosleep n’a pas marché.
Par contre, entre 10:14:39 et 10:21:22, la c’est moi qui est remis l’horloge à l’heure, je l’ai avancé de 89s. Comme ci dessus, sleep est indépendant des changements d’heure et 315s plus tard environ, la ligne s’affiche avec donc la différence entre les deux heures, cela aurait du être 315s environ mais comme j’ai avancé l’heure de 89s, il s’y rajoute 89s et on tombe sur le 403s.
Cela montre que ça n’est pas un souci d’horloge système qui est modifié mais un souci global du système: Tout a été interrompu pendant 89s.
[quote]
C’est l’horloge système qui fait un saut. L’hormoge hwclock étant un fichier, tu pourrais essayer de tracer qui écrit dans ce fichier (et aussi qui le lit, ça peut étre surprenant).[/quote]
Depuis deux jours, je logue la différence heure système - heure RTC. Je lis constamment 0.
[quote]
quand au rattrapage manuel, je ne comprends pas. Si sleep est indépendant de l’horloge systeme, pourquoi cette augmentation du temps de calcul ?[/quote]
Cf ci dessus. Ce qui est affiché est la différence entre heure lue et heure précédente lue.
Wahouuuu c’est la quatrième dimension ! Faut arrêter déjà que le commun des mortels s’interroge pour effectuer une mise à niveau alors là franchement … 
@piratebab: voilà une feuille de calcul qui résume le raisonnement. Elle montre ce que serait la situation dans le cas où il n’y aurait eu aucune interruption dans le décompte système du temps, c’est à dire dans le cas où l’interruption timer fonctionne bien.
À la ligne 5 tu as un 225 qui aurait du apparaitre dans mes logs et qui n’y ait pas. La seule explication est que les interruptions timers n’ont plus été traitées ou mal traitées.
La question est pourquoi.
Comme prévu, le décalage RTC/heure système est toujours de 0.
simulation.ods (13.1 KB)
Tu as dit tout au début que l’intervalle entre ce blocage est de 2²², tu l’as déduis de tes observations des derniers décalage ? Es-ce une valeur approximative ou précise ?
2²² = 4 Mio
Il y a peut être un truc de ce coté, genre fuite mémoire qui sature un tampon/cache/…
2^22s correspond à l’intervalle de temps entre chaque fois que le bug se produit: Ce bug s’est produit
aux dates suivantes:
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
L’écart entre chacun de ces dates est, à l’imprecision de mes logs près, à une période très précise et constante qui semble être 2^22 secondes à la précision de mes logs près. C’est trop proche pour être une coïncidence à mon avis, par contre cette période ne correspond pas à 2^32 ms. Je n’ai aucune explication, je ne pense pas que ça soit liée à une taille RAM, par contre je suspecte nettement un problème de retenue dans un registre du système effectuant des interruptions régulièrement.
En tout cas, tu es maintenant certain que les mécanismes de recalage de la RTC fonctionnent.
Un blocage de 89 sec d’un serveur qui passerait inaperçu avec toutes les surveillances que tu as mis ?
ca parait peu probable.
et une horloge système qui se fige 89 sec, idem.
bizarre, bizarre …
[quote=“piratebab”]En tout cas, tu es maintenant certain que les mécanismes de recalage de la RTC fonctionnent.
Un blocage de 89 sec d’un serveur qui passerait inaperçu avec toutes les surveillances que tu as mis ?
ca parait peu probable. [/quote]Il ne passe pas inaperçu puisque je m’en aperçois dans les 5mn, simplement si tout est gelé, ben rien ne se déclenche à commencer par les systèmes de vérification.[quote]
et une horloge système qui se fige 89 sec, idem.
bizarre, bizarre …[/quote]Oui, je pense vraiment à un souci matériel spécifique à cette machine.
Un truc qui fige jusqu’à l’horloge système, c’est du lourd!
J’ai trouvé de la lecture passionante: kernel.org/doc/Documentatio … ighres.txt
Il est aussi expliqué comment fonctionne nanosleep (il a son propre timer, indépendant de celui de l’horloge système).
Je ne vois pas comment le systéme complet peux se figer alors que l’horloge est traitée par interruption (softirq, mais irq quand même!)
Dans ton cas, on dirait que le dynamic tick considère que le system est endormi, et donc reprogramme un tick dans 89 sec.
C’est pour ça que pense à un problème hardware avec un système gelé avec sans doute rien qui s’exécute, aucune interruption pendant les 89s. Mais je voudrais comprendre l’origine de ces 89s…
Je viens de reprendre depuis le début, et j’ai compris ce que yu veux dire: les 2 timers, celui de l’horloge et celui de nanosleep, bien qu"étant totalement indépendante, se prennent ce décalage.
Un truc qui bloque toutes les interruptions, je ne vois pas trop.
Je ne connais pas bien les softirq, j’ai toujours travaillé sur les hard.
Bien le bug est passé comme prévu, voilà ce que ça donne:
22:52:26 <---- HEURE SUR UN AUTRE SERVEUR NTP: heure exacte donc
vendredi 4 septembre 2015, 22:52:26 (UTC+0200) <---- DATE MACHINE
0 <--- HEURE système moins HEURE RTC en secondes
22:52:34
vendredi 4 septembre 2015, 22:52:34 (UTC+0200)
0
22:52:43
vendredi 4 septembre 2015, 22:52:43 (UTC+0200)
0
22:52:54
vendredi 4 septembre 2015, 22:52:54 (UTC+0200)
-89
22:53:02
vendredi 4 septembre 2015, 22:53:02 (UTC+0200)
-89
22:53:10
vendredi 4 septembre 2015, 22:53:10 (UTC+0200)
-89
[..]
22:59:46
vendredi 4 septembre 2015, 22:59:46 (UTC+0200)
-89
22:59:54
vendredi 4 septembre 2015, 22:59:54 (UTC+0200)
-89
23:00:02
vendredi 4 septembre 2015, 23:00:02 (UTC+0200)
0 <--------------- RECALAGE heure RTC sans intervention
23:00:11
vendredi 4 septembre 2015, 23:00:11 (UTC+0200)
0
23:00:19
vendredi 4 septembre 2015, 23:00:19 (UTC+0200)
0
Le serveur NTP a été relancé à 16354 ntpd Fri Sep 4 23:46:17 2015
parce que il avait toujours un décalage de 89s avec le reste du monde.
Log de poolntp (heure GMT):
1441409460,"2015-09-04 23:31:00",-0.0000973939895629883,1,-13.7
1441408361,"2015-09-04 23:12:41",-0.00238072872161865,1,-15.5
1441407236,"2015-09-04 22:53:56",0.000102996826171875,1,-17.3
1441406139,"2015-09-04 22:35:39",-0.0020374059677124,1,-19.3
1441405024,"2015-09-04 22:17:04",-0.0000807046890258789,1,-21.4
1441403883,"2015-09-04 21:58:03",-0.00218832492828369,1,-23.6 <--- RELANCE SERVEUR
1441402698,"2015-09-04 21:38:18",-89.0613644123077,-4,-25.8
1441401493,"2015-09-04 21:18:13",-89.0638047456741,-4,-23
1441400294,"2015-09-04 20:58:14",-89.0625076293945,-4,-20 <---- DECALAGE SERVEUR
1441399167,"2015-09-04 20:39:27",0.00154829025268555,1,20
1441398054,"2015-09-04 20:20:54",-0.000956535339355469,1,20
1441396948,"2015-09-04 20:02:28",0.00281929969787598,1,20
1441395821,"2015-09-04 19:43:41",-0.00122296810150146,1,20
Bilan:
- J’avais redémarré le serveur. Si le bug est lié au serveur NTP, le prochain aurait eu lieu le Dimanche 6/09 au matin et non le 4/09. C’est donc indépendant du serveur NTP.
- L’heure prévu du bug ([mono]Le prochain est donc prévu le 4 septembre vers 22h53.[/mono]) était parfaite.
- Le fait que l’heure système ne décroche jamais de l’heure d’un autre serveur NTP montre que l’horloge système fonctionne correctement
- C’est un décalage brusque et immédiat de l’heure RTC de 89s dans l’avenir
- À 23:00 visiblement l’heure RTC s’est recalé sur l’heure système mais le serveur NTP a continué sur la mauvaise heure.
- Mon hypothèse de gel de la machine est fausse, on a bien le serveur NTP interrogé toutes les 8s
Questions:
- Pourquoi l’heure RTC se décale comme ça?
- Pourquoi ce décalage s’impose au serveur NTP? Ça n’est pas logique, l’heure fiable c’est l’heure système.
Prochain BUG le 23 Octobre à 9:58 GMT (donc à 11:58 heure Française). Si vous avez des tests à proposer…
Prochain bug
Vue que tu connais l’heure exact de la prochaine occurrence il serait intéressante de mettre une fréquence plus élevée à ce moment là, genre toutes les 0.5s.
Donc si on suis ta pensé c’est l’horloge de la carte mère qui fait défaut. Un test pourrait être fait en enlevant la pile de la CM pour voir si une réinitialisation complète change quelque chose.
Mas si c’est vraiment un problème matériel tu n’a pas de solution hormis changer de matos.
Pour ce qui est du “pourquoi ça s’impose au serveur NTP” il faut voir quelle horloge il privilégie en tant que référence …