Diese Geschichte handelt von einem Ereignis, das wir kürzlich bei der Migration von WSO2 ESB 4.8.0 auf WSO2 Enterprise Integrator 6.5.0 erlebt haben. In Zusammenarbeit mit unserem Kunden haben wir eine unternehmensfähige Serviceplattform entwickelt, die eine große Anzahl seiner Backend-Anwendungen verbindet und integriert. Über die Plattform werden Geschäftsintegrationsprozesse sicher, zeitnah und vollständig abgewickelt. Die Produktionsplattform wird seit mehreren Jahren erfolgreich auf einer Einzelknoten-Installation betrieben. Allerdings kam es gelegentlich zu Lastspitzen auf der Plattform, was sich manchmal als Herausforderung erwies, die Plattform ohne Unterbrechungen am Laufen zu halten.
Da die Plattform wuchs, wurde erkannt, dass ein Upgrade sowohl auf Anwendungs- als auch auf Infrastrukturebene erforderlich war. So wurde ein Projekt initiiert, um von einem Einzelknoten WSO2 ESB 4.8.0 mit WSO2 Data Services Server (DSS) 3.2.2 auf eine hochverfügbare und ausfallsichere Infrastruktur auf Basis von WSO2 Enterprise Integrator 6.5 aufzurüsten. Die Hochskalierung würde uns mehrere Vorteile bringen. Zum Beispiel können wir Wartungsarbeiten an der Plattform ohne Ausfälle durchführen und Spitzenlasten besser bewältigen, da wir nun Auto-Healing-Funktionen auf der Plattform konfigurieren können.
Das Ergebnis war ein Multi-Node-Setup auf RHEL 7 OS, das von einem Linux-HA Load Balancer und Reverse Proxy mit WSO2 Enterprise Integrator 6.5, Apache ActiveMQ und einer Datenbank als Backend in einer hochverfügbaren Konfiguration betrieben wurde.
Die Diensteplattform bestand aus:
- Einige benutzerdefinierte OSGi-Module.
- 3 custom Axis2-Dienste.
- 61 CARs mit 119 Dienste.
- 2 unterstützende Spring-boot-Dienste.
Damit das alles funktioniert, haben wir:
- Konnektivität mit ActiveMQ für garantierte Nachrichtenzustellung.
- Alle Datenbankdatenquellen werden mit MS SQL verbunden. (Datenbankprodukt nach Wahl des Kunden)
- Benutzerdefinierte Profile für ausgehenden HTTP-Verkehr.
- VFS-Adapter konfiguriert.
- Konnektivität mit 20 Backend-Anwendungen.
Sie sehen, das ist eine ziemlich umfangreiche Einrichtung. Anfänglich hatten wir eine angemessene Startzeit von 240 Sekunden für WSO2 Enterprise Integrator, um die Plattform zum Laufen zu bringen. Doch nach einer Weile stieg die Startzeit plötzlich auf mehr als 1.200 Sekunden an! Außerdem dauerte das Durchsuchen der Registry mit der Carbon-Konsole sehr lange. Bei jedem Klick dauerte es etwa 10 bis 20 Sekunden, um zum nächsten Schritt in der Registrierungsstruktur zu gelangen.
Dieser Blog beschreibt, wie wir das Problem des langsamen Starts schließlich gefunden und gelöst haben, um zu den ursprünglichen 240 Sekunden zurückzukehren.
Beobachtung
Zuerst haben wir die WSO2-Richtlinien zur Leistungsoptimierung überprüft, um sicherzustellen, dass alles berücksichtigt wurde. Es wurden alle Einstellungen übernommen, und wir konnten dieses Problem beseitigen. Auch die von WSO2 vorgeschlagenen Anforderungen an die Maschinenressourcen haben wir perfekt erfüllt. Bei allen Knoten im Cluster konnten wir feststellen, dass die CPU-Last und die Speichernutzung normal waren. Zweitens erlebten wir auch schnellere Startzeiten zu verschiedenen unregelmäßigen Zeitpunkten während der Tests in der Nacht oder am späten Nachmittag, wenn das Geschäft die Plattform nicht so stark belastete.
Wir haben begonnen, die JVM- und WSO2-Ressourcen über JMX zu beobachten. Wir haben auf unserem Server Jolokia installiert, um den internen Zustand des Servers zu überwachen, und so war es einfach, die MBeans für Datenbankdatenquellen zu beobachten. Die MBeans zeigten Unterschiede zwischen langsamen und schnellen Starts. Bei langsamen Starts benötigte die Registry-Datenquelle über 56.000 Fremdverbindungen, während es bei normalen Starts nicht mehr als 76 waren. Das gab uns den Hinweis, die Konfiguration der Datenquelle zu optimieren, so dass genügend Verbindungen im Pool der Datenbankverbindungen zur Verfügung stehen, um alle Start- und Bereitstellungsroutinen zu unterstützen.
Nach dem Tuning der Datenquelle und einem neuen Startvorgang hatten wir eine hervorragende Startzeit von 210 Sekunden. Wir dachten, damit sei das Problem gelöst. Bis die Langsamkeit nach einem halben Tag zurückkehrte.
Die Suche geht weiter
Bei einem langsamen Start erscheinen diese Arten von Protokollen immer am Anfang:
[EI] 2020-02-12 03:27:03,971 WARN [Timer-4] {org.wso2.carbon.application.deployer.internal.AppDeployerServiceComponent} - Waiting for required OSGi services: org.wso2.carbon.application.deployer.synapse.service.SynapseAppDeployerService,org.wso2.carbon.mediation.initializer.services.SynapseEnvironmentService,[EI] 2020-02-12 03:27:04,368 WARN [Timer-5] {org.wso2.carbon.core.internal.StartupFinalizerServiceComponent} - Waiting for required OSGi services: org.wso2.carbon.application.deployer.service.CappDeploymentService,org.wso2.carbon.server.admin.common.IServerAdmin,org.wso2.carbon.throttling.agent.ThrottlingAgent,[EI] 2020-02-12 03:28:03,970 WARN [Timer-4] {org.wso2.carbon.application.deployer.internal.AppDeployerServiceComponent} - Waiting for required OSGi services: org.wso2.carbon.application.deployer.synapse.service.SynapseAppDeployerService,org.wso2.carbon.mediation.initializer.services.SynapseEnvironmentService,[EI] 2020-02-12 03:28:04,368 WARN [Timer-5] {org.wso2.carbon.core.internal.StartupFinalizerServiceComponent} - Waiting for required OSGi services: org.wso2.carbon.application.deployer.service.CappDeploymentService,org.wso2.carbon.server.admin.common.IServerAdmin,org.wso2.carbon.throttling.agent.ThrottlingAgent,[EI] 2020-02-12 03:28:23,650 INFO [localhost-startStop-1] {org.wso2.carbon.mediation.initializer.ServiceBusInitializer} - Starting ESB...Der Grund dafür, dass ein OSGi-Modul auf seine Bereitstellung wartet, ist, dass es darauf wartet, dass andere abhängige OSGi-Module bereitgestellt werden und verfügbar sind. Nach der Einstellung der Registry-Datenquelle hatten wir keine Ahnung, was genau das Problem war.
Wir haben einige Szenarien durchgespielt, um herauszufinden, wo sich die Geschwindigkeit verlangsamt hat:
| WSO2 Enterprise Integrator-Einrichtung | Ergebnis |
| Leere Installation | Superschneller Start in weniger als 30 Sekunden |
| Mit Konfiguration, aber ohne den Teil registry.xml | Weiterhin ein schneller Start |
| Mit Konfiguration + registry.xml Teil | Langsamer Start mit OSGi WARN-Meldungen. |
| Vollständige Einrichtung (Konfiguration und Dienste), wobei die registry.xml weggelassen wird. | Schneller Startup um die 60 Sekunden! |
| Vollständiges Setup (Konfiguration und Dienste) und registry.xml enthalten. | Langsamer Start |
Aufgrund der Cluster-Konfiguration haben wir ursprünglich die registry.xml geändert, um die Cluster-Konfiguration zu berücksichtigen. Wir beschlossen, die Registry von der Datenbank zu trennen und zur H2-Datenbank zurückzukehren, die in den WSO2-Produkten als Standard konfiguriert ist.
Das Ergebnis war, dass beim Umschalten der Datenquellen von der Registry auf die MS SQL-Datenbank (die auf einem Windows 2012-Server läuft) der Startvorgang langsam war. Dies veranlasste uns, die Datenbank selbst zu untersuchen und nicht die WSO2-Konfiguration.
Eingrenzen des Problembereichs
Um herauszufinden, was mit der WSO2-Registrierungsdatenquelle passiert, mussten wir Spy-Logs mit einem Tool namens log4jdbc DriverSpy einrichten. Dieser Prozess sitzt zwischen der Datenquelle und der Datenbankverbindung und kann einige sehr nützliche Anwendungsprotokolle bezüglich der Abfrageleistung veröffentlichen.
Dies sind die Schritte, die wir zum Einrichten von DriverSpy unternommen haben:
1. Laden Sie den log4jdbc-Treiber herunter und fügen Sie ihn dem Ordner <EI_HOME>/lib hinzu.
2. Fügen Sie die folgenden Modifikationen in der Datei <EI_HOME>/conf/datasources/master-datasources.xml hinzu.
2a. Ändern Sie die URLs der Datenquellen wie folgt, indem Sie das Präfix „log4jdbc“ hinzufügen <url>jdbc:log4jdbc:sqlserver://hostname:1433;databaseName=REG_DB;applicationIntent=ReadWrite</url>
Im vorliegenden Fall basiert die obige Prozedur auf einer Verbindung zu MS SQL, aber Sie können die gleiche Art von Prozedur für jede Art von Datenbankverbindung ausführen.
2b. Modify the ‚driverClassName‘ parameter value as below<driverClassName>net.sf.log4jdbc.DriverSpy</driverClassName>
2c. Fügen Sie die folgenden Eigenschaften in die Datei <EI_HOME>/conf/log4j.properties ein. file.log4j.logger.jdbc.sqlonly=INFOlog4j.logger.jdbc.sqltiming=INFOlog4j.logger.jdbc.audit=OFFlog4j.logger.jdbc.resultset=ERRORlog4j.logger.jdbc.connection=ERROR
3. Starten Sie den Server neu
Während des Neustarts können wir feststellen, wie viel Zeit für die Ausführung der Datenbankanweisungen benötigt wird. In der Ausgabe werden die Protokolle wie unten dargestellt, und wir können sehen, dass die folgende Abfrage in 1 Millisekunde ausgeführt wurde.
>[2020-02-14 12:43:12,437] [EI-Core] INFO - sqltiming SELECT REG_MEDIA_TYPE, REG_CREATOR, REG_CREATED_TIME, REG_LAST_UPDATOR, REG_LAST_UPDATED_TIME, REG_VERSION, REG_DESCRIPTION, REG_CONTENT_ID, REG_UUID FROM REG_RESOURCE WHERE REG_PATH_ID=45 AND REG_NAME = 'edit.gif' AND REG_TENANT_ID=-1234 {executed in 1 msec}
In den Blog-Beiträgen „How to Enable JDBC Spy Logs for WSO2 Servers“ und „How to use log4jdbc with WSO2 products to log JDBC calls“ werden die oben genannten Punkte näher erläutert.
Nach dem Zählen aller Abfrageaufrufe während des Starts kamen wir zu folgenden Ergebnissen:
Normaler Start:
Zeit für DB-Aufrufe: 14.490s
Zeit für die Bereitstellung von Autoanwendungen: 2m 44s
Gesamt-Startzeit: 353s (5m 53s)
Langsamer Start:
Zeit für DB-Aufrufe: 168,696s (2m 49s)
Zeit für die Bereitstellung von Autoanwendungen: 15m 36s
Startzeit insgesamt: 1244s (20m 44s)
Das Ergebnis der Analysephase zeigt, dass während des langsamen Starts viel Zeit für DB-Aufrufe und CAR-Bereitstellungen aufgewendet wurde. Der Zeitaufwand für die CAR-Bereitstellung nimmt den größten Anteil an der gesamten Startzeit ein.
Jetzt war klar, dass die Datenbank das Problem war, auch wegen des unregelmäßigen Verhaltens in Zeiten, in denen niemand im Büro arbeitet. An einem Samstagabend mussten wir uns an das DBA-Team wenden, um zu prüfen, was mit der Datenbank los ist.
Schwerpunkt Windows
Wir hatten uns bereits während unserer Untersuchung an den DBA gewandt und ihn gebeten, in der Datenbank nach Indikatoren zu suchen. Er hatte lediglich nach Abfragen gesucht, die länger als normal in der Warteschlange standen, und das war nicht der Fall. Nach unserer letzten Feststellung waren wir überzeugt, dass die Datenbank der Übeltäter war, und baten das DBA-Team und das Operations-Team, die Untersuchung auf ihrer Seite fortzusetzen. Das Operations-Team entdeckte, dass auf dem Datenbankserver (Windows 2012 Server, mit 2 vCPUs) eine CPU die ganze Zeit voll ausgelastet war und die andere im Durchschnitt zu über 80%, bis hin zu 100%!
Für diesen Overhead ist ein Prozess verantwortlich. „svchost.exe“ mit den Parametern -k netsvc, der ständig 50% der CPU nutzt. Dieser Prozess wird von vielen Windows-Diensten verwendet. Ein anderer Prozess, der zusammen mit svchost.exe regelmäßig 50 % der CPU verbraucht, ist tiworker.exe, der für die Durchführung von Windows-Betriebssystem-Updates verwendet wird. Dieser Service kann nicht angehalten werden (oder der Prozess hängt). Wir gehen davon aus, dass er beim Anhalten nach einer Weile automatisch neu gestartet wird. Wenn Sie im Internet nach „tiworker.exe“ suchen, werden Sie eine Menge häufiger Probleme mit der Leistung von Windows 2012 finden.
Das Operations-Team hat beschlossen, den Windows-Update-Cache zu leeren und den Update-Prozess neu zu starten, was dazu führte, dass er ordnungsgemäß beendet wurde und die Datenbank wieder Zugriff auf die Ressourcen hatte.
Nachdem wir die Leistung überwacht hatten, während der Dienst tiworker.exe nicht ausgeführt wurde, konnten wir eine erhebliche Verbesserung der Startzeit feststellen. 276 Sekunden. (Vorher lag die Startzeit bei über 1.300 Sekunden).
Zusammenfassung
Unser Kunde, der eine große Service-Plattform betreibt, hat einen plötzlichen Einbruch der Startleistung seiner neu installierten und konfigurierten WSO2 Enterprise Integration v6-Installation festgestellt. Im ersten Moment startete sie in einem akzeptablen Zeitrahmen, dann verlangsamte sie sich um mehr als 500%. Wir haben verschiedene Teile der WSO2-Installation untersucht und unsere Bemühungen schließlich auf unseren Datenbankserver und insbesondere die Windows-Update-Dienste gelenkt.
In diesem Blog beschreiben wir, wie wir an das Problem herangegangen sind und welche Tools und Schritte wir unternommen haben, um die Schichten des Problems abzuschälen und schließlich wieder zu einem akzeptablen WSO2-Start zu kommen.
