Ik kreeg een telefoontje van iemand dat ze TNS-12519-fouten kregen in hun applicatie. En ja hoor, die berichten stonden ook in het listener.log-bestand.
TNS-12519: TNS:no appropriate service handler found
Voor degenen die niet bekend zijn met deze fout, betekent dit meestal een van de twee dingen. De servicenaam is niet geregistreerd bij de listener of de database heeft het maximale aantal processen bereikt. Wat het laatste betreft, wat er gebeurt, is dat de luisteraar weet dat de database geen nieuwe processen kan accepteren, dus de servicenaam wordt als het ware buiten dienst gesteld. Een snelle "lsnrctl-status" laat me zien dat de servicenaam correct is geregistreerd. Het moet dus het laatste zijn. Ik stel dan de volgende vraag en bevestig mijn vermoedens.
SQL> select resource_name,current_utilization,max_utilization 2 from v$resource_limit where resource_name='processes';
RESOURCE_NAME CURRENT_UTILIZATION MAX_UTILIZATION --------------- ------------------- --------------- processes 299 300
Zowaar. Ik heb het maximale aantal processen bereikt, dat in mijn SPFILE is gedefinieerd als 300. Ik heb de parameter verhoogd naar 600 en de instantie teruggestuurd. We hebben opnieuw de fout gemaakt met het dubbele aantal processen. Ik moet hier natuurlijk verder op ingaan.
Voor wat achtergrondinformatie, en voor iets dat later belangrijk zal zijn, is het belangrijk om te weten dat deze database onze geautomatiseerde testinspanningen ondersteunt. We hebben een testharnas dat onze primaire productietoepassing uitoefent. Deze testsuite start de applicatie, maakt verbinding met de database, drukt op een paar knoppen en selecteert een paar menu-items en verbreekt vervolgens de verbinding.
Ik onderzocht het bestand listener.log om te zien waar de verbindingsverzoeken vandaan kwamen. Deze verzoeken kwamen van een malafide applicatieserver, niet van onze testsuite. Ik wist dat er iets mis was omdat we nog niet met de testsuite waren begonnen en we de fouten kregen. We hebben de applicatieserver gerepareerd en ik zag de fouten niet terugkeren. We hebben toen de testsuite gestart en enige tijd later kwamen de TNS-12519-fouten terug. Hmmm... ik dacht dat ik de boosdoener had gevonden. Maar laten we eens kijken naar ons procesgebruik.
SQL> select resource_name,current_utilization,max_utilization 2 from v$resource_limit where resource_name='processes';
RESOURCE_NAME CURRENT_UTILIZATION MAX_UTILIZATION --------------- ------------------- --------------- processes 89 157
Dus ik zie momenteel 89 processen met een maximaal gebruik van 157. Ik ben lang niet in de buurt van mijn nieuwe limiet van 600. Dus wat geeft het? Het duurde even voordat ik doorhad wat het probleem was. De servicenaam is correct geregistreerd en ik ben lang niet in de buurt van mijn limiet. MOS OPMERKING 552765.1 vertelt hoe de luisteraar bij de TNS-12519-fout komt. Voorheen zag ik de meest voorkomende oorzaak. Max PROCESSEN was bereikt. Maar deze keer niet. Dus wat geeft het?
Na onderzoek vond ik mijn antwoord in het logboek van de luisteraar. Maar het was niet duidelijk als een grote foutmelding. Het eerste optreden van de TNS-12519-fout was om 9.38 uur. Ik zocht naar "service_update" in het luisteraarlogboek en zag deze vermeldingen.
25-JUN-2015 09:17:08 * service_update * orcl * 0 25-JUN-2015 09:17:26 * service_update * orcl * 0 25-JUN-2015 09:17:29 * service_update * orcl * 0 25-JUN-2015 09:17:44 * service_update * orcl * 0 25-JUN-2015 09:17:50 * service_update * orcl * 0 25-JUN-2015 09:17:53 * service_update * orcl * 0 25-JUN-2015 09:18:56 * service_update * orcl * 0 25-JUN-2015 09:18:59 * service_update * orcl * 0 25-JUN-2015 09:19:50 * service_update * orcl * 0 25-JUN-2015 09:20:11 * service_update * orcl * 0 25-JUN-2015 09:21:27 * service_update * orcl * 0 25-JUN-2015 09:22:09 * service_update * orcl * 0 25-JUN-2015 09:24:05 * service_update * orcl * 0 25-JUN-2015 09:27:53 * service_update * orcl * 0 25-JUN-2015 09:29:32 * service_update * orcl * 0 25-JUN-2015 09:34:07 * service_update * orcl * 0 25-JUN-2015 09:41:45 * service_update * orcl * 0
Merk op dat deze service-update regelmatig om 9:17 en 9:18 plaatsvindt, maar dat de tijd tussen de service-updates steeds langer duurt. Merk op dat er aan het einde 8 minuten en 38 seconden waren tussen service-updates (9:34 tot 9:41). Waarom is dit belangrijk?
Dit is een Oracle 11.2.0.4-database. Voor 11.2 en eerder is PMON verantwoordelijk voor het opschonen na processen en voor het doorgeven van informatie aan de luisteraar. Bij het opstarten van de database probeert PMON de services te registreren bij de luisteraar. Een ander ding dat PMON doet, is de luisteraar vertellen hoeveel max-processen kunnen worden bediend. In dit geval vertelt PMON de luisteraar dat het maximaal 600 processen kan hebben. PMON doet meer, maar voor deze discussie is dat genoeg.
Een belangrijk stuk om te weten is dat de luisteraar nooit weet hoeveel processen er momenteel verbonden zijn. Het weet alleen hoeveel verbindingsverzoeken het de makelaar heeft geholpen. De luisteraar weet nooit of processen de verbinding met de database verbreken. De service_update hierboven is waar PMON de luisteraar vertelt hoeveel processen daadwerkelijk worden gebruikt. Dus om 9:34:07 vertelt de PMON-service-update de luisteraar dat er 145 processen in gebruik zijn. De Luisteraar is nu up-to-date. Wanneer een nieuw verbindingsverzoek binnenkomt, verhoogt de luisteraar dit tot 146 processen. Tussen de service-updates is de luisteraar zich er totaal niet van bewust dat 1 of meer processen mogelijk zijn beëindigd, normaal of abnormaal. Het blijft het aantal processen verhogen tot de volgende service-update wanneer de luisteraar een nauwkeurig overzicht krijgt van hoeveel processen er zijn voortgebracht.
Dus we hebben die 8,5 minuut tussen service-updates. Waarom duurde het zo lang voordat PMON terugging naar de luisteraar? De aanwijzing daarvoor staat ook in de listener.log. Ik heb alles uit het logboek verwijderd vóór de service_update van 9:34 en na de service-update van 9:41. Van daaruit was het gemakkelijk om naar "(CONNECT_DATA=" te zoeken in wat er over was en door te pijpen naar "wc -l" om een telling van regels te krijgen.
Tijdens dit interval van 8,5 minuten had ik meer dan 450 nieuwe verbindingsverzoeken! Maar de meeste van die nieuwe verbindingen zijn beëindigd, zoals blijkt uit V$RESOURCE_LIMIT die me liet zien dat ik er maximaal 150 had. PMON was zo druk bezig met het opschonen van de applicatie die de databaseverbindingen verliet dat het een grote vertraging had voordat het de listener bijwerkte. Wat de luisteraar betreft, betekende de 150 huidige verbindingen plus de 450 nieuwe verbindingen dat het de limiet van 600 bereikte.
Het kan tot 10 minuten duren voordat PMON teruggaat naar de luisteraar met de volgende service-update. Opschonen nadat sessies de instantie hebben verlaten, heeft een hogere prioriteit dan service-updates voor de luisteraar. Na 10 minuten geeft PMON de service-update de hoogste prioriteit als de service-update niet eerder in dat tijdsinterval was uitgevoerd.
Onthoud dat dit een database is om geautomatiseerd testen te ondersteunen. We moeten leven met zoveel verbindings- en ontkoppelingshandelingen omdat we een geautomatiseerde robot hebben die onze applicatie razendsnel test. We willen niet veranderen hoe de applicatie werkt, omdat deze heel goed werkt wanneer deze door een enkele gebruiker wordt uitgevoerd. Onze geautomatiseerde testsuite voert de applicatie anders uit dan waarvoor deze is ontworpen. Maar we willen de applicatie gebruiken zoals deze is geschreven om mogelijk bugs bloot te leggen voordat de codewijzigingen in productie gaan.
Voor nu heb ik de parameter PROCESSES verhoogd tot een waarde die we nooit zullen bereiken. Dit alles zodat de luisteraar de limiet in zijn interne teller niet kan raken. Hoe meer PROCESSEN, hoe meer geheugen er in de SGA nodig is om dat hogere aantal te ondersteunen. Maar deze database kan het aan.
Als iemand een manier weet om de service-update binnen 5 minuten te laten plaatsvinden, laat het me dan weten. Er zijn geen gedocumenteerde parameters om dit gedrag te controleren en ik heb ook geen ongedocumenteerde kunnen vinden.
Ten slotte bevindt dit probleem zich in een van mijn 11.2.0.4-databases. Oracle 12c verandert de architectuur een beetje. Het nieuwe achtergrondproces Luisteraarsregistratie (LREG) handelt het werk af dat PMON vroeger deed. Ik heb nog geen systeem om te testen, maar ik wed dat de LREG niet hetzelfde probleem zal hebben in 12c dat PMON hier vertoont in 11g, aangezien de LREG geen opruimtaken hoeft uit te voeren die PMON doet. MOS Note 1592184.1 laat zien dat LREG de service-updates zal doen.
Update:sinds ik dit artikel schreef, had ik de kans om de database te upgraden naar 12c met zijn nieuwe LREG-proces. Toen de LREG de service-updates van de luisteraar afhandelde, zagen we het probleem verdwijnen. Zelfs in tijden van zware sessie-activiteit, met name het verbinden en loskoppelen, maakte LREG regelmatig service-updates die PMON niet zo vaak had kunnen uitvoeren.