ScheduledExecutorService glisse pendant 10 minutes sur un programme de 1 minute (systemd - journald fault)

Question

J'ai un service d'exécuteur qui est censé écrire des choses sur le disque chaque minute.

Il est prévu comme ceci:

scheduledCacheDump = new ScheduledThreadPoolExecutor(1); 
    scheduledCacheDump.scheduleAtFixedRate(this::saveCachedRecords, 
              60, 
              60, 
              TimeUnit.SECONDS 
    ); 

La tâche utilise une liste commune qui est rempli par le thread principal, il est synchronisé sur cette liste:

private void saveCachedRecords() { 
     LOG.info(String.format("Scheduled record dump to disk. We have %d records to save.", recordCache.size())); 
     synchronized (recordCache) { 
      Iterator<Record> iterator = recordCache.iterator(); 
      while (iterator.hasNext()) { 
       // save record to disk 
       iterator.remove(); 
      } 
     } 
    } 

Ma liste est déclarée en tant que tel:

private final List<Record> recordCache = new ArrayList<>(); 

Le thread principal reçoit des données par lot, de sorte que chaque seconde, il reçoit 30 r les accords qu'il met en cache dans la liste. Le reste du temps, il attend sur une socket.

Ce que je ne comprends pas, est que des journaux, ma tâche planifiée est souvent déclenchée avec la manière plus que 1 minute entre:

sept. 16 09:30:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:31:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:32:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:33:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:34:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:35:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:42:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:43:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:44:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:45:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:46:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:55:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:56:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:57:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:58:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 09:59:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 10:04:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 10:05:43 Scheduled record dump to disk. We have 27 records to save. sept. 16 10:06:43 Scheduled record dump to disk. We have 27 records to save.

Regardez ceci:

• sept. 16 09:59:43 Vidage d'enregistrement planifié sur le disque. Nous avons 27 enregistrements à enregistrer.
• sept. 16 10:04:43 Sauvegarde d'un enregistrement planifié sur le disque. Nous avons 27 enregistrements à enregistrer.

=> 5 minutes

Ou même:

• SEPT. 16 09:46:43 Sauvegarde d'enregistrement planifiée sur le disque. Nous avons 27 enregistrements à enregistrer.
• sept. 16 09:55:43 Sauvegarde d'enregistrement planifiée sur le disque. Nous avons 27 enregistrements à enregistrer.

=> 9 minutes

Mon journal se trouve dans le champ synchronized(), donc je ne sais pas si la tâche est effectivement prévue à l'heure et attend 10 minutes sur la serrure, ou si elle est juste un vrai problème de planification. Je vais le sortir de là, mais en général, je ne peux pas comprendre comment un fil pourrait rester bloqué pendant 10 minutes sur une serrure qui est relâchée toutes les secondes.

Comment puis-je étudier cela?

Pour information: la machine sur laquelle il tourne est une machine KVM, cela pourrait-il être un facteur?

Answer 1

Oh my ..

Ce ne fut pas la faute de Java du tout. C'était la faute de systemd.

Mon processus s'exécute en tant que service systemd, donc les logs que je tire proviennent de systemd-journald. Et devinez quoi, il y a une limite de débit dans systemd.Et mon démon frapperait quand le planificateur a été déclenchée, alors je me suis ABONDANCE de lignes comme ceci:

Suppressed 570 messages from /system.slice/xxx.service Suppressed 769 messages from /system.slice/xxx.service Suppressed 745 messages from /system.slice/xxx.service Suppressed 729 messages from /system.slice/xxx.service Suppressed 717 messages from /system.slice/xxx.service Suppressed 95 messages from /system.slice/xxx.service Suppressed 543 messages from /system.slice/xxx.service

Alors .. oui, je l'ai enlevé l'étranglement sur journald et j'ai mes traces maintenant chaque minute.

La solution était:

• modifier /etc/systemd/journald.conf
• ligne ajouter: RateLimitInterval=0 à la fin
• execute systemctl restart systemd-journald
• execute systemctl restart myservice

Maintenant, j'ai toutes choses qui se passent en douceur.

Je mettrai à jour le titre pour référence future :)