ScheduledExecutorService проскальзывает в течение 10 минут в расписании на 1 минуту (ошибка systemd - journald)

Question

У меня есть служба-исполнитель, которая должна каждую минуту записывать некоторые вещи на диск.

Запланировано так:

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

Задача использует общий список, который заполняется основным потоком, поэтому он синхронизируется в этом списке:

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(); 
      } 
     } 
    } 

Мой список объявлен как таковой:

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

Основная нить получает данные по пакету, поэтому каждую секунду или около того она получает 30 р которые он кэширует в списке. В остальное время он ждет сокета.

То, что я не понимаю, что из журналов, моя запланированная задача часто срабатывает с образом более, что 1 минута в возрасте:

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.

Посмотрите на это:

• sept. 16 09:59:43 Запланированная запись на диск. У нас есть 27 записей для сохранения.
• перегородка. 16 10:04:43 Запланированная запись на диск. У нас есть 27 записей для сохранения.

=> 5 минут

Или даже:

• Sept. 16 09:46:43 Запланированная запись дампа на диск. У нас есть 27 записей для сохранения.
• перегородка. 16 09:55:43 Запланированная запись дампа на диск. У нас есть 27 записей для сохранения.

=> 9 минут

Мой журнал в synchronized() объеме, так что я не знаю, если задача на самом деле запланировано на время и ждет 10 минут на замке, или, если это просто реальная задача планирования. Я вытащу его из него, но, как правило, я не могу понять, как нить может оставаться заблокированной в течение 10 минут на блокировке, которая выпускается примерно каждую секунду.

Как я могу это расследовать?

Для информации: машина, на которой он работает, является машиной KVM, может ли это быть фактором?

Answer 1

Ой ..

Это не была ошибка в Java вообще. Это была ошибка системы.

Мой процесс выполняется как служба systemd, поэтому журналы, которые я вытаскиваю, поступают из systemd-journald. И угадайте, что есть ограничение скорости в systemd.И мой демон ударит его, когда планировщик был вызван, так что я получил МНОГО линии, как это:

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

Так .. да, я удалил дросселирование на journald и у меня есть мои следы каждую минуту в настоящее время.

Решение было:

• редактировать /etc/systemd/journald.conf
• добавить строки: RateLimitInterval=0 в конце
• выполнить systemctl restart systemd-journald
• выполнить systemctl restart myservice

Теперь я все идет гладко.

Я обновлю название для использования в будущем :)