Dit verhaal gaat over een recente gebeurtenis die we meemaakten toen we van WSO2 ESB 4.8.0 naar WSO2 Enterprise Integrator 6.5.0 migreerden. Samen met onze klant ontwikkelden we een zakelijk servicesplatform waarin een groot aantal van hun backend applicaties geïntegreerd en met elkaar verbonden werden. Het platform vervult bedrijfsintegratieprocessen op een veilige, tijdige en volledige manier. Het productieplatform loopt al een paar jaar succesvol op een installatie met een enkele node, maar af en toe merkten we een piekbelasting op het platform, waardoor het moeilijk was om het platform zonder onderbrekingen te laten draaien.
Naarmate het platform groeide werd duidelijk dat een upgrade op zowel het applicatie- als het infrastructuurniveau noodzakelijk was. Daarom werd een project opgestart om van een enkele node WSO2 ESB 4.8.0 met WSO2 Data Services Server (DSS) 3.2.2 te upgraden naar een infrastructuur met meer beschikbaarheid en failovermogelijkheden, gebaseerd op de WSO2 Enterprise Integrator 6.5. De schaalvergroting zou verschillende voordelen met zich meebrengen. Waarom zaken zoals platformonderhoud zonder storingen en een veerkrachtigere afhandeling van piekbelastingen, omdat we nu zelfhelende mogelijkheden op het platform kunnen configureren.
Het eindresultaat was een multi-node setup op RHEL 7 OS front-end met een Linux-HA load balancer en reverse proxy in combinatie met de WSO2 Enterprise Integrator 6.5, Apache ActiveMQ en een database als backend. Volledig geconfigureerd om een ruime beschikbaarheid te garanderen.
Het servicesplatform bestond uit:
- Enkele aangepaste OSGi modules.
- 3 aangepaste Axis2 services.
- 61 CARs die 119 services bevatten.
- 2 ondersteunende Spring-boot services.
Om alles te laten werken hebben we:
- Connectiviteit met ActiveMQ dat gegarandeerde berichtaflevering biedt.
- Alle database databronnen verbonden met MS SQL. (Keuze van de klant voor een databaseproduct)
- Aangepaste profielen voor uitgaand HTTPs verkeer.
- Geconfigureerde VFS adapters.
- Connectiviteit met 20 backend applicaties.
Zoals je kunt zien is het best een grote setup. Oorspronkelijk hadden we een redelijke opstarttijd van 240 seconden voor de WSO2 Enterprise Integrator om het platform werkend te krijgen. Maar na een poosje veranderde de opstarttijd plotseling naar meer dan 1200 seconden! Het duurde ook afschuwelijk lang om het register door te bladeren met de Carbon console. Elke klik naar de volgende stap in de registerboom duurde ongeveer 10 tot 20 seconden.
In deze blog vertel ik hoe we uiteindelijk het probleem met de langzame opstarttijd ontdekten en opgelost hebben, zodat we het weer terug konden brengen naar de oorspronkelijke 240 seconden.
Observeren
Allereerst controleerden we WSO2’s performance tuning guidelines opnieuw om te garanderen dat alles gerespecteerd was. Alle instellingen waren correct toegepast en zo konden we dit punt uit sluiten. We voldeden ook perfect aan de vereisten met betrekking tot machine resources zoals aanbevolen door WSO2. Op alle nodes in de cluster konden we zien dat de CPU-belasting en het geheugengebruik normaal was. Ten tweede, we ervoeren ook snellere opstarttijden rond verscheidene onregelmatige momenten tijdens tests, zoals ‘s nachts of in de late namiddag als het bedrijf het platform niet te zwaar belastte.
We begonnen de JVM en WSO2 bronnen via JMX te bekijken. We hebben Jolokia op onze servers gezet om de interne staat te volgen en dat maakte het makkelijk om de MBeans te observeren voor database databronnen. De MBeans toonde verschillen tussen de keren dat er langzaam en snel gestart werd. Bij een langzame start had de register databron meer dan 56,000 geleende connecties nodig, maar tijdens een normale start was dat niet meer dan 76. Dit gaf ons de aanwijzing om te kijken of we de databronconfiguratie konden afstemmen, zodat we genoeg connecties in de database connectiepool hadden om alle opstart- en deployment-routines te ondersteunen.
Na het afstemmen van de databron en een nieuwe start hadden we een fantastische opstarttijd van 210 seconden. Hiermee dachten we dat het probleem was opgelost. Tot de vertraging zich na een halve dag opnieuw voordeed.
Verder zoeken
Tijdens een langzame start verschenen er aan het begin altijd dit soort logs:
[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...
Als er een OSGi module wacht om te worden ingezet, is dat omdat het wacht op andere afhankelijke OSGi modules die ingezet moeten worden en opnieuw beschikbaar zijn. Na het afstemmen van de register databron hadden we geen idee meer wat het probleem precies was.
We voerden een paar scenario’s uit om te kijken waar de vertraging begon:
WSO2 Enterprise Integrator Setup | Resultaat |
Lege installatie | Supersnelle start (nog geen 30 seconden) |
Met configuratie, maar zonder het registry.xml deel | Nog steeds een snelle start |
Met configuratie + registry.xml deel | Langzame start met OSGi WARN berichten |
Volledige setup (configuratie en diensten) maar zonder het registry.xml deel | Snelle start (ongeveer 60 seconden!) |
Volledige setup (configuratie en diensten) en inclusief het registry.xml deel | Langzame start |
Aangezien we een gebundelde setup hebben, pasten we eerst de registry.xml aan om de clusterconfiguratie weer te geven. We besloten om het register los te koppelen van de database en terug te gaan naar de H2 database die in WSO2 producten als default geconfigureerd is.
De conclusie was dat de start langzaam gemaakt wordt door het omzetten van databronnen vanuit het register, dat verwijst naar de MS SQL database (dat op een Windows 2012 server werkt). Hierdoor richten we onze onderzoeksinspanningen op de database zelf in plaats van op de WSO2 configuratie.
Het probleemgebied verkleinen
Om te zien wat er gebeurt met de register databron van WSO2 moesten we spy logs opzetten met een hulpmiddel dat log4jdbc DriverSpy heet. Het is een proces dat tussen de databron en de databaseverbinding zit. Je kunt hier erg nuttige applicatielogs over queryprestaties inzichtelijk mee maken.
Dit zijn de stappen om DriverSpy op te zetten:
1. Download het log4jdbc stuurprogramma en voeg het toe aan de <EI_HOME>/lib map.
2. Pas de volgende wijzigingen toe op het <EI_HOME>/conf/datasources/master-datasources.xml bestand.
2a. Verander de URL’s van de databron zoals hieronder, door er een ‘log4jdbc’-prefix aan toe te voegen.<url>jdbc:log4jdbc:sqlserver://hostname:1433;databaseName=REG_DB;applicationIntent=ReadWrite</url>
In ons geval is het bovenstaande gebaseerd op een verbinding met MS SQL, maar je kan dezelfde soort procedure voor elke soort databaseverbinding uitvoeren.
2b. Verander de waarde van de ‘driverClassName’ parameter zoals hieronder.<driverClassName>net.sf.log4jdbc.DriverSpy</driverClassName>
2c. Voeg de volgende eigenschappen toe aan het <EI_HOME>/conf/log4j.properties bestand. file.log4j.logger.jdbc.sqlonly=INFOlog4j.logger.jdbc.sqltiming=INFOlog4j.logger.jdbc.audit=OFFlog4j.logger.jdbc.resultset=ERRORlog4j.logger.jdbc.connection=ERROR
3. Herstart de server
Tijdens de herstart zouden we kunnen zien hoe lang het duurt om database statements af te ronden. De output printte de logs en we kunnen zien dat de onderstaande query in 1 milliseconde uitgevoerd wordt.
>[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}
De blog “How to Enable JDBC Spy Logs for WSO2 Servers” and “How to use log4jdbc with WSO2 products to log JDBC calls” geven een uitgebreidere uitleg van het bovenstaande.
Na het tellen van alle query calls tijdens de start hadden we de volgende resultaten:
Normale Start:
Tijd voor DB calls: 14.490s
Tijd voor het inzetten van car apps: 2m 44s
Totale opstarttijd: 353s (5m 53s)
Langzame Start:
Tijd voor DB calls: 168.696s (2m 49s)
Tijd voor het inzetten van car apps: 15m 36s
Totale opstarttijd: 1244s (20m 44s)
Volgens het resultaat van de analysefase lijkt het dat tijdens een langzame start veel tijd verbruikt wordt door DB calls en de CAR deployments. Het tijdsverbruik van de CAR deployments neemt het grootste deel in beslag van de totale opstarttijd.
Het was nu duidelijk dat de database het probleem was, ook door het onregelmatige gedrag als er niemand op het kantoor aan het werk was. Zelfs op een zaterdagnacht moesten we contact opnemen met het DBA team om te kijken wat er aan de hand was met de database.
Focussen op windows
Tijdens ons onderzoek hadden we al contact opgenomen met de DBA en hem laten zoeken naar aanwijzingen in de database. Hij had alleen gekeken of er queries langer in de rij stonden dan normaal en dat was niet het geval. Na onze laatste vondst waren we overtuigd dat de database de boosdoener was en vroegen we het DBA-team en operationeel team om het onderzoek aan hun kant voort te zetten. Het operationeel team vond uit dat op de database server (Windows 2012 server, met 2 vCPU’s) één CPU altijd volledig in gebruik was en de ander gemiddeld voor 80%, soms zelfs voor de volledige 100%, gebruikt werd!
Er is één proces verantwoordelijk voor deze overhead: “svchost.exe” met de parameters -k netsvc, dat constant 50% CPU gebruikt. Dit is een proces dat gebruikt wordt door veel Windows services. Een ander proces dat samen met svchost.exe regelmatig 50% van de CPU gebruikt is de tiworker.exe. Het wordt gebruikt om Windows OS updates uit te voeren. Het is niet mogelijk om deze service te stoppen (tenzij dit proces is vastgelopen). Als het proces stopt, dan gaan we ervan uit dat het na een poosje automatisch opnieuw opstart. Als je op Internet naar “tiworker.exe“ zoekt, zul je veel zien dat er vaak problemen zijn met Windows 2012 prestaties.
Het operationeel team besloot om de Windows-update cache vrij te maken en het updateproces te herstarten. Dit zorgde ervoor dat het naar behoren afgewerkt werd en de database toegang tot resources terugkreeg.
Na het monitoren van de prestaties, terwijl de tiworker.exe service niet uitgevoerd werd, zagen we een substantiële verbetering in opstarttijd. 276 seconden. (Vanuit een situatie waar de opstarttijd meer dan 1,300 seconden bedroeg).
Samenvatting
Bij onze klant met een groot services-platform, merkten we een plotselinge daling in opstartprestaties van onze recent geïnstalleerde en geconfigureerde WSO2 Enterprise Integration v6 installatie. Soms startte het op in een aanvaardbare tijdsperiode, soms vertraagde het met meer dan 500%. We onderzochten verschillende delen van de WSO2 installatie en uiteindelijk richten we ons op de database-server en in het bijzonder de Windows update services.
In deze blog beschreven we hoe we dit probleem hebben benaderd en welke hulpmiddelen en stappen we namen om de lagen van het probleem af te pellen en uiteindelijk weer uit te komen bij een aanvaardbare WSO2 opstarttijd.