Call Stack Dump/Log

[ChrisX]

Hallo,

ich habe ein kleines Probelm, welches ich am besten kurz erläutere damit es besser verstanden werden kann ;-D


Ich administriere eine 825 mit V5R2M0, ca. 10GB, 1TB HD storage, 2 Prozessoren, CPW 3600/6600. Ca. 800 User im Schnitt.

Die Hauptapplikation auf der Machine ist in der Grundform BPCS, welches allerdings sehr stark von Programmiererteams modifiziert wurde.

Nun zum eigtl. Problem ;-D

Seit geraumer Zeit beschweren sich manche Anwender, dass Transaktionen (Order Entry zum Beispiel) sehr lange dauern. D.h. sie geben zum Beispiel etwas ein und warten dann ca. 5-6 Min. bis zur nächsten Maske (Kann stark variieren). Wenn ich mir den Job zum Beispiel anschaue, sehe ich dass der Job status RUN ist, also kein LCKW oder dergleichen vorliegt. Ergo schliesse ich daraus, dass das Programm irgendetwas arbeitet ^^ Nun wäre es Klasse wenn mir jemand sagen könnte wie ich den Call Stack eines Jobs mitprotokollieren kann, damit ich auswerten kann welches PGM im Zugriff war und welche Statements evtl. Probleme machen.

Das System ist hardwareseitig eigtl. nicht voll ausgelastet in meinen Augen, daher sehe ich das problem eher bei einem Programmierfehler oder dergleichen.

Würde mich über jegliche Hilfe oder Ansatzpunkte freuen.

Danke und Gruss
Chris

[Fuerchau]

Wenn das Programm aktiv ist, dann hilft ggf. der Callstack überhaupt nicht weiter.
Du musst ggf. die Anzahl Dateizugriffe beobachten (DSPJOB->Auswahl 14).
Ich habe es schon erlebt, dass Programme zigtausende Sätze verarbeiten müssen um irgendeine Prüfung durchzuführen.
Bei kleineren Systemen kann dies schon mal einige Zeit in Anspruch nehmen.

Ist die Anwendung in SQL geschrieben ?

Dann könnten die SQL's ggf. nicht sehr performant laufen (fehlende Zugriffswege).

API's helfen da auch nicht immer weiter.
Zumal du ja das API zum Sammeln der Daten auch mehrfach aufrufen musst.

Sicherlich gibts auch Tools dafür.

Aber beobachte einfach mal in einer solchen Situation den Job (Auswahl 14) und die Anzahl Dateizugriffe (F5).

[ChrisX]

Erstmal vielen Dank für die Info.

Ich habe den aktuellen Job eines Anwenders bei dem häufig diese Probleme auftreten mal angeschaut mit der Auswahl 14. Bei Open data paths stand dort 676. Ich werde aber sobald das problem erneut auftritt nochmals nachschauen. Leider weiss ich nicht ob dies eine kritisch hohe Zahl ist oder nicht.

Die Anwendung ist in SQL geschrieben und ich habe auch schon den database monitor laufen lassen. Die Auswertung wurde auch bereits an das applikations team geschickt. Dort wurde die Erstellung von einigen Zugriffspfaden empfohlen. Soweit ich aber weiss müsste ich dann bei dem entsprechenden Job auch sehen dass er einen index aufbaut, dies war jedoch nicht der Fall, oder irre ich hier?

Zum auslesen des Call stacks gibt es shareware tools, ich wollte jedoch vom Einsatz solcher programme absehen ^^

Mein Problem ist letzenendes, dass ich nicht genau weiss was in den 5-6 Minuten während der Anwender auf den nächsten Bildschirm warten muss passiert. Ich suche nun nach einem Weg relativ genau herauszufinden was sich während dieser Zeit abspielt, da das Applikationsteam behauptet es wäre kein Fehler ihrer Seite.

Danke nochmal für weitere Tips und Anregungen.

Gruss
Chris

[Fuerchau]

676 geöffnete Dateien sind ja doch schlicht der Hammer.

Wenn SQL im Spiel ist, dann kannst du eine QAQQINI erstellen und die Joblog-nachrichten analysieren.

Control queries dynamically with the query options file QAQQINI

Das Attribut MESSAGES_DEBUG schreibt dann entsprechende Nachrichten.

Indizees werden nicht immer aufgebaut oder verwendet, wenn z.B. eine Join-Beziehung keinen Index erlaubt (z.B. Typänderungen).

Da hilft nur tatsächlich eine Anpassung der Anwendung.

Ggf. hilft mal ein PRTSQLINF des jeweiligen Programmes.

Dann sieht man die SQL's und kann sie mal per STRSQL im Debug-Modus ausprobieren.

[holgerscherer]

D.h. sie geben zum Beispiel etwas ein und warten dann ca. 5-6 Min. bis zur nächsten Maske (Kann stark variieren). Wenn ich mir den Job zum Beispiel anschaue, sehe ich dass der Job status RUN ist, also kein LCKW oder dergleichen vorliegt.

Hallo Chris,

ist das Verhalten nur bei einzelnen Jobs bei speziellem Anwendungsbereich sichtbar, oder auch bei mehreren / anderen?

Wenn Du 5722PT1 installiert hast, probiere den Befehl WRKSYSACT (alternativ gibt es WRKSYSAC2 als Shareware/Free demo). Da sieht man mit mehrmaligem F11 und Auswahl 6 halbwegs brauchbare Angaben zur I/O-Last und Speicherbelegung.

Eventuell steht auch was beim QSYSOPR, dass die (bei Euch limitierte) Interaktivkapazität am bitteren Ende ist.

-h

[jo400]

Hallo Chris,

kann es sein, dass der Job gelockt ist?

Ich würde - wenn das Problem das nächste Mal auftritt - zuerst in den Joblog schauen (WRKJOB - Auswahl 10, dann F10 - F5 - F18) ggfs. steht da ja ein Hinweis auf das Problem.

Zusätzlich würde ich noch kontrollieren, ob der Job überhaupt noch CPU-Zeit verwendet (WRKJOB - Auswahl 3) und mit F5 kontrollieren, ob sich die "benutzte CPU-Zeit" weiter erhöht.

Außerdem sollte man mit WRKACTJOB und F16 auf CPU die CPU-Auslastung beobachten.

Viel Erfolg.

Jo

[ChrisX]

So, erstmal wieder Vielen Dank für die Informationen!

@Fuerchau: Das mit der QAQQINI hört sich interessant an, werde versuchen dies mal umzusetzen. Wenn ich mir andere Jobs anschaue sehe ich eigtl. im Schnitt meist 500-600 open data paths. Eher selten, dass die zahl hier bei 100 oder weniger liegt. Das Problem ist, dass ich nicht genau weiss welches Programm die "Verzögerung" produziert, daher weiss ich auch nicht auf welches Programm ich ein PRTSQLINF machen sollte. Mein Gedanke war ja hier dass ich den Callstack auslese/dumpe um dies herauszufinden.

@holgerscherer: Das Verhalten ist nur in bestimmten Anwendungsbereichen sichtbar. Bei dem betroffenen Anwenderpool betrifft es beispielsweise nur den Order Entry. Alle anderen Funktionen/Abfragen laufen laut Anwender performant. Nur bei der Auftragseingabe kommt es sporadisch zu "unakzeptablen" Verzögerungen. Man kann leider auch nicht sagen dass es ein dauerhaftes problem ist. Es gibt auch zeiten (unregelmäßig) zu denen es akzeptabel läuft.

WRKSYSACT habe ich auch schon öfter mitlaufen lassen. Es besteht zwar häufig eine hohe CPU Last, jedoch meist auch durch BATCH Jobs und nicht INTeraktiv. Es ist mir auch noch nicht aufgefallen dass die CFINT0X jobs versuchen Kapazität zu sperren. Auch im QSYSOPR Log gibt/gab es bisher keine Einträge darüber dass die Interaktive Leistung überschritten wurde. Generell bin ich auch der Meinung, dass eigtl. fast jeder Anwender Performance Probleme haben müsste, wenn das System am Limit mit seinen Resourcen wäre. Es betrifft aber wirklich nur Mitarbeiter welche mit Order Entry beschäftigt sind. Zumindest haben sich bisher noch keine Anwender in anderen Bereichen mit den gleichen Problemen gemeldet.

@jo400: Wenn diese probleme auftreten rufen mich die Anwender meist direkt an. Ich beobachte dann generell den job status. Es kam zwar vereinzelt mal vor, dass der Job ein kurzes Object Lock hatte (LCKW) aber dies war entweder kein Dauerzustand über die ganzen 5-6 Minuten noch habe ich das gefühl, dass mit den "kurz" auftretenden Lockwaits ein wirkiches problem besteht. Normalerweise hat der Job den Status RUN. Wenn ich in das Joblog schaue, sehe ich zum aktuellen Zeitpunkt (also wenn der Job hängt) meist nur den folgenden letzten Eintrag:

Open of member XXX was changed to SEQONLY(*NO).

Das ist meist der einzige Eintrag den ich sehen kann.

Die CPU Auslastung ist oft sehr schwankend, wobei die meiste CPU Zeit von BATCH Jobs mit PRIO > 20 gebraucht wird.

Meine Idee war, dass ich mit Hilfe des Call Stacks das Programm, welches aktuell "arbeitet" herausfinden kann um dann zu prüfen was dieses Programm genau macht und warum die Zeitverzögerung zustande kommt.

Laut Anwender wurde die performance über Monate hinweg immer schlechter.

Auch die Betreuer der Applikation habe ich schon darauf hingewiesen dass es mit BPCS Performance Probleme geben kann, wenn manche Dateien nicht reorganisiert werden. Aber hier hat eine Bereinigung auch nichts gebracht.

Noch eine kleine Info:
Das System wird monatlich IPLed und halbjährlich wird ein RCLSTG gefahren. Die Performance Analyse (Über die Performance Tools) ergab, dass die Disk Arms stark beansprucht sind. Der Systemwert QPFRADJ steht auf 2. Die Plattenplatzbelegung liegt momentan bei ca. 75%.

Danke schonmal + Gruss
Chris

[BenderD]

Hallo,

Ferndiagnosen sind meist schwierig, aber trotzdem ein paar Anmerkungen zu den zitierten Aspekten:

wenn du den "Klemmer" beobachtest, dann einfach in der Call Stack Anzeige so oft man es schafft refreshen und von dem aktiven Programm Hardcopys machen liefert eine statistische Verteilung der runtime Anteile (was anderes machen die Performance tools letztlich auch nicht. Wenn da einer 90 % hat -> et voila.

open of member was changed to seqonly riecht nach full table scan (ist in den reads nicht auffällig wg. Blockung und könnte Plattenaktivität plausibel erscheinen lassen.

mfg

Dieter Bender

So, erstmal wieder Vielen Dank für die Informationen!

@jo400: Wenn diese probleme auftreten rufen mich die Anwender meist direkt an. Ich beobachte dann generell den job status. Es kam zwar vereinzelt mal vor, dass der Job ein kurzes Object Lock hatte (LCKW) aber dies war entweder kein Dauerzustand über die ganzen 5-6 Minuten noch habe ich das gefühl, dass mit den "kurz" auftretenden Lockwaits ein wirkiches problem besteht. Normalerweise hat der Job den Status RUN. Wenn ich in das Joblog schaue, sehe ich zum aktuellen Zeitpunkt (also wenn der Job hängt) meist nur den folgenden letzten Eintrag:

Open of member XXX was changed to SEQONLY(*NO).

Das ist meist der einzige Eintrag den ich sehen kann.

Die CPU Auslastung ist oft sehr schwankend, wobei die meiste CPU Zeit von BATCH Jobs mit PRIO > 20 gebraucht wird.

Meine Idee war, dass ich mit Hilfe des Call Stacks das Programm, welches aktuell "arbeitet" herausfinden kann um dann zu prüfen was dieses Programm genau macht und warum die Zeitverzögerung zustande kommt.

Laut Anwender wurde die performance über Monate hinweg immer schlechter.

Danke schonmal + Gruss
Chris

[ChrisX]

Hallo,

Ferndiagnosen sind meist schwierig,...

Ich weiss ;-D, daher bin ich ja froh um jede Antwort und jeden Tip ^^

Gruss
Chris

[Fuerchau]

Changed to SEQONLY(*NO) deutet meist darauf hin, dass die Datei mit FRCDATA(1) definiert wurde, d.h., dass jeder Write sofort auf die Platte muss.

Wenn da nicht so viel geschrieben wird, hat das keine nennenswerte Auswirkung.

Ein CPYF kann mit FRCDATA(*NONE) z.B. bis Faktor 100 oder mehr kopieren.

Der Call-Stack muss da eher genau analysiert werden, da die Programm meistens in Q-Programmen (SQL/DB) verschwinden.

Kritisch ist es z.B., wenn da ein QQQ-Programm länger benötigt (Optimizer).

Ich tippe aber eben eher auf sinnlose Abfragen über tausende Sätze an Stelle gezielter Zugriffe.

Wenn Du schon den Ansatz hast, dass der OrderEntry Schuld hat, würde ich mich mal darauf konzentrieren und die Anzahl Zugriffe auf die Dateien beobachten (was bei >500 ODP's zugegegeben etwas schwierig ist).

[holly]

Hallo Chris,
wenn die User 5-6 Minuten warten, brauchst Du den Call Stack nicht mitzuprotokollieren.
Da sollte dspactjob und Auswahl 10 reichen dann F10 drücken (Stapel aktualisieren) um zu sehen in welchem PGM und an welchem Befehl er hängt.

mfG Holger