Scheduler und Datenbank

[Alexander Winterstein]

Hallo zusammen,

wir hatten zuletzt immer mal ein paar kleine Schwierigkeiten mit unserem Datenbank-Cluster (3 Galera Cluster Nodes, MariaDB). Aus bislang unbekannten Gründen kommt das in letzter Zeit immer mal ins Stocken. Es sieht so aus, als landen zigtausende Anfragen (Fehlermeldungen) im Log von einer Node. Und die schaffen es, daß anscheinend das komplette Cluster blockiert wird, so daß nach und nach alle Anwendungen ebenfalls ins Straucheln geraten. Abhilfe schafft dann nur noch, die betreffende Node neuzustarten, wodurch die MySQL-Prozesse terminiert werden.

Soweit, sogut.

Unser Datenbank-Admin meinte, daß insbesondere von KIX enorm viele Log-Einträge aufploppen, wenn es da zu Fehlern kommt. Und dann auch gleich mehrere in derselben Sekunde. Hier ein Auszug:

Code Auswählen Erweitern

2022-09-07 12:01:51 0 [Note] InnoDB: WSREP: BF lock wait long for trx:95750178 query: UPDATE scheduler_task SET lock_key = '10012126170', lock_time =
        '2022-09-07 11:35:10'
    , lock_update_time =
        '2022-09-07 11:35:10'
     WHERE lock_key = 0 AND id = '3936294'ï¿œec
2022-09-07 12:01:51 0 [Note] InnoDB: WSREP: BF lock wait long for trx:95750179 query: UPDATE scheduler_task SET lock_key = '10012126171', lock_time =
        '2022-09-07 11:35:10'
    , lock_update_time =
        '2022-09-07 11:35:10'
     WHERE lock_key = 0 AND id = '3936297'ï¿œec
2022-09-07 12:01:52 0 [Note] InnoDB: WSREP: BF lock wait long for trx:95750178 query: UPDATE scheduler_task SET lock_key = '10012126170', lock_time =
        '2022-09-07 11:35:10'
    , lock_update_time =
        '2022-09-07 11:35:10'
     WHERE lock_key = 0 AND id = '3936294'ï¿œec
2022-09-07 12:01:52 0 [Note] InnoDB: WSREP: BF lock wait long for trx:95750179 query: UPDATE scheduler_task SET lock_key = '10012126171', lock_time =
        '2022-09-07 11:35:10'
    , lock_update_time =
        '2022-09-07 11:35:10'
     WHERE lock_key = 0 AND id = '3936297'ï¿œec
2022-09-07 12:01:53 0 [Note] InnoDB: WSREP: BF lock wait long for trx:95750178 query: UPDATE scheduler_task SET lock_key = '10012126170', lock_time =
        '2022-09-07 11:35:10'
    , lock_update_time =
        '2022-09-07 11:35:10'
     WHERE lock_key = 0 AND id = '3936294'ï¿œec
2022-09-07 12:01:53 0 [Note] InnoDB: WSREP: BF lock wait long for trx:95750179 query: UPDATE scheduler_task SET lock_key = '10012126171', lock_time =
        '2022-09-07 11:35:10'
    , lock_update_time =
        '2022-09-07 11:35:10'
     WHERE lock_key = 0 AND id = '3936297'ï¿œec

Hier nun meine Fragen:
Anscheinend ist der Scheduler generell äußerst aktiv. Mich wundert es hier konkret, daß die Tabelle scheduler_task aktualisiert wird, die aber beim Blick in die DB eigentlich immer leer ist. Es gibt noch zwei weitere scheduler-Tabellen (recurrent und future).

Wie arbeitet KIX da im Hintergrund?

Läßt es sich irgendwie beeinflussen, wie frequentiert der Scheduler Anfragen auslöst?


Viele Grüße
Alex

[Benedikt Geißler]

Hallo Alexander,

es gibt einen KIX-Konsolenbefehl, mit man sich einen Überblick zum Daemon verschaffen kann:

Code Auswählen Erweitern

kix.Console.pl Maint::Daemon::Summary

(bei KIX18 gibt es den auch, da über den Adminbereich → KIX → System → Konsole)

Die Ausgabe beinhaltet dann mehrere Abschnitte, die jeweils eine Kurzform des Inhalts der Datenbanktabellen darstellen:

• "Tasks to be executed in future" → scheduler_future_task, für die zukünftigen Aufgaben – tritt auf, wenn ein Webservice-Task fehlschlägt und nochmal erneut eingeplant wird
• "Recurrent cron tasks" → scheduler_recurrent_task, für die wiederkehrenden Aufgaben, mit Information, wann die Ausführung zuletzt und wann sie als Nächstes stattfindet
• "Recurrent generic agent tasks" → generic_agent_jobs, für zeitgesteuerte, gültige GenericAgents
• "Unhandled Worker Tasks" → scheduler_tasks, für die wiederkehrenden Aufgaben, die noch zur Ausführung vorgemerkt sind
• "Handled Worker Tasks" → scheduler_tasks, für die wiederkehrenden Aufgaben, die gerade laufen

Sobald ein Job aus scheduler_task fertig ist, wird der entsprechende Eintrag in scheduler_recurrent_task aktualisiert.

Einstellen, ob und in welchen Intervallen die Aufgaben durchgeführt werden sollen, lässt sich in der SysConfig in der Untergruppe Daemon::SchedulerCronTaskManager::Task. Dabei wird jeweils im Unterschlüssel Schedule das Intervall in Cron-Notation vermerkt. Ein hilfreiches Tool, um herauszufinden, was ein solcher Eintrag bedeutet, ist die Webseite https://crontab.guru. GenericAgents werden natürlich im Adminbereich bei GenericAgent und das Intervall für die FutureTasks beim Sysconfig-Schlüssel Daemon::SchedulerGenericInterfaceTaskManager::FutureTaskTimeDiff eingestellt.

Viele Grüße
Benedikt

[Alexander Winterstein]

Besten Dank für die ausführliche Erklärung. Dann schauen wir, ob wir damit etwas bei uns herausfinden können.

Viele Grüße
Alexander

[Alexander Winterstein]

Falls es jemanden interessiert, reiche ich noch kurz unsere Erkenntnisse nach.


In der Übersicht sind bei uns diese Einträge auffällig gewesen:

Code Auswählen Erweitern

Tasks to be executed in future:
      NAME                                     TYPE                 TO EXECUTE AT                                                                                                             
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:51:52
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:49:29
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:50:51
      PluginAsynchronous::ConcurrentUser       AsynchronousExec...  2022-09-07 11:42:26
Es hat den Anschein, als könnten die tatsächlich mit unserem Problem zusammenhängen, denn die Execute-Zeiten liegen alle in der Vergangenheit. Gut denkbar, daß sich da immer mal etwas kritisch behakt hat.Mit etwas Glück konnten wir damit unser Problem nun beheben. Schauen wir mal, was die Logfiles in Zukunft zu berichten wissen. Danke nochmal für den Hinweis.


Drei Fragen habe ich noch:
- Was genau macht der Tast "ConcurrentUser"?
- Was könnte die Ursache dafür gewesen sein?
- Gibt es eine Möglichkeit, solche hängenden Tasks "korrekt" zu bereinigen, um nicht die Tabelle scheduler_future_tasks direkt in der DB leeren zu müssen?


Viele Grüße
Alex

[Benedikt Geißler]

Hallo Alex,

der Task ConcurrentUser berechnet die Anzahl an gleichzeitig angemeldeten Agenten und Kunden und wird jedes Mal ausgeführt, wenn sich ein Agent oder ein Kunde anmeldet. Im Nachhinein ist es allerdings schwer zu sagen, woran es gelegen haben könnte, dass sich diese Tasks angehäuft haben. Neben dem Löschen dieser überflüssigen Einträge aus der Datenbanktabelle kann es auch helfen, den Daemon mit "kix.Daemon.pl stop" und "kix.Daemon.pl start" neu zu starten.

Viele Grüße
Benedikt