SQL Select Statement - Execute dauert sehr lange [Archiv]

View Full Version : SQL Select Statement - Execute dauert sehr lange

Seiten : [1] 2

max40

06-02-15, 10:28

Moin,

ich führe mehrere Statements hintereinander aus.
- Connectionpool getConnection
- connection create statement
- statement execute
- statement close
- connection create statement
- stament execute
- statement close
- connection close
Ab dem 2. Statement braucht er für das execute sehr lange. Wobei da nichts groß gemacht wird. Hin und wieder gehts es auch mal sehr zügig.
Ich habe mal das Log angeschaltet und folgendes kommt raus:

(Die xxxx = as400: ConnectionPool com.ibm.as400.access.AS400JDBCConnectionPool@1f1d1 f1d (522002205) )

Toolbox for Java - Open Source Software, JTOpen 8.1, codebase 5770-SS1 V7R2M0.00 built=20131021 @J5
java.home=/QOpenSys/QIBM/ProdData/JavaVM/jdk60/64bit/jre java.vm.version=2.4 java.version=1.6.0 os.name=OS/400 os.version=V7R1M0
...

Thread[main,5,main] 09:15:04:475 Getting version level.
Thread[main,5,main] 09:15:04:475 Version level: 7
Thread[main,5,main] 09:15:04:475 Bidi layout transformation of SQL meta-data: SELECT FELD1, FELD2, FELD3, FELD4 FROM LIB/DATEI WHERE FELDX = 111111 AND FELDY between 201101 AND 201112 ORDER BY 1
Thread[main,5,main] 09:15:04:475 Bidi layout transformation from 5 to 5 of SQL statement: SELECT FELD1, FELD2, FELD3, FELD4 FROM LIB/DATEI WHERE FELDX = 111111 AND FELDY between 201101 AND 201112 ORDER BY 1
Thread[main,5,main] 09:15:04:476 as400: PreparedStatement STMT0002 (915355279) open. Parent: Connection S4405619 (486612225) .
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Escape processing = "true".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Fetch direction = "1000".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Fetch size = "0".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Max field size = "0".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Max rows = "0".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Query timeout = "0".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Result set concurrency = "1007".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Result set holdability = "1".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Result set type = "1003".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Behavior Override = "0".
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Data to correlate statement with cursor Cursor CRSR0002 (924333848) .
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : isjvm16Synchronizer=false.
Thread[main,5,main] 09:15:04:477 as400: PreparedStatement STMT0002 (915355279) : Preparing [SELECT FELD1, FELD2, FELD3, FELD4 FROM LIB/DATEI WHERE FELDX = 111111 AND FELDY between 201101 AND 201112 ORDER BY 1].
Thread[main,5,main] 09:15:04:477 com.ibm.as400.access.BidiConversionProperties@4810 4810:Setting bidi string type:0
Thread[main,5,main] 09:15:04:477 Converting string to byte array for ccsid: 1141
Thread[main,5,main] 09:15:04:477 Destination byte array for ccsid: 1141
Thread[main,5,main] 09:15:04:477 com.ibm.as400.access.BidiConversionProperties@4ac4 4ac4:Setting bidi string type:0
Thread[main,5,main] 09:15:04:477 Converting string to byte array for ccsid: 1141
Thread[main,5,main] 09:15:04:477 Destination byte array for ccsid: 1141
Thread[main,5,main] 09:15:04:477 send(): send request...
Thread[main,5,main] 09:15:04:477 Data stream sent (connID=1767926112) ...
Thread[main,5,main] 09:15:04:478 com.ibm.as400.access.BidiConversionProperties@4ebb 4ebb:Setting bidi string type:0
Thread[main,5,main] 09:15:04:478 Converting string to byte array for ccsid: 13488
Thread[main,5,main] 09:15:04:479 Destination byte array for ccsid: 13488
Thread[main,5,main] 09:15:04:479 send and receive(): ...
Thread[main,5,main] 09:15:04:479 send(): send request...
Thread[main,5,main] 09:15:04:479 Data stream sent (connID=1767926112) ...
Thread[main,5,main] 09:15:04:480 AS400Server.receive
Thread[main,5,main] 09:15:04:480 receive(): Reply not found. Waiting...
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:15:04:670 Data stream data received (connID=1767926112) ...
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:15:04:670 Data stream data received (connID=1767926112) ...
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:15:04:671 run(): Adding reply: 7
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:15:04:671 run(): Notifying threads.
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:15:04:671 run(): Threads notified.
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:15:04:671 run(): Waiting for reply...
Thread[main,5,main] 09:15:04:672 receive(): Valid reply found: 7
Thread[main,5,main] 09:15:04:674 decompressRLE() sourceLength: 1003
Thread[main,5,main] 09:15:04:674 decompressRLE() destinationLength: 1330
Thread[main,5,main] 09:15:04:675 Received empty parameter marker format.
Thread[main,5,main] 09:15:04:687 as400: PreparedStatement STMT0002 (915355279) : Prepared STMT0002*, SQL Statement -->[SELECT FELD1, FELD2, FELD3, FELD4 FROM LIB/DATEI WHERE FELDX = 111111 AND FELDY between 201101 AND 201112 ORDER BY 1].
Thread[main,5,main] 09:15:04:690 send and receive(): ...
Thread[main,5,main] 09:15:04:690 send(): send request...
Thread[main,5,main] 09:15:04:690 Data stream sent (connID=1767926112) ...
Thread[main,5,main] 09:15:04:690 AS400Server.receive
Thread[main,5,main] 09:15:04:690 receive(): Reply not found. Waiting...

--- Was passiert hier ? ? ? ? ---

Thread[ACPM,5,main] 09:20:04:368 as400: xxxx : ConnectionPool cleanup....
Thread[ACPM,5,main] 09:20:04:368 as400: xxxx : MaxLifeTime: 86400000.
Thread[ACPM,5,main] 09:20:04:368 as400: xxxx : MaxUseTime: -1.
Thread[ACPM,5,main] 09:20:04:368 as400: xxxx : MaxInactivity: 3600000.
Thread[ACPM,5,main] 09:20:04:368 as400: xxxx : PretestConnections: false.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : Idle Connections: 0.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : Active Connections: 1.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : Dead Connections: 0.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : com.ibm.as400.access.AS400JDBCPooledConnection@1d0 11d01.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : ConnectionPool cleanup finished..
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : Idle Connections: 0.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : Active Connections: 1.
Thread[ACPM,5,main] 09:20:04:369 as400: xxxx : Dead Connections: 0.
Thread[ACPM,5,main] 09:25:04:403 as400: xxxx : ConnectionPool cleanup....
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : MaxLifeTime: 86400000.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : MaxUseTime: -1.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : MaxInactivity: 3600000.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : PretestConnections: false.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : Idle Connections: 0.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : Active Connections: 1.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : Dead Connections: 0.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : com.ibm.as400.access.AS400JDBCPooledConnection@1d0 11d01.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : ConnectionPool cleanup finished..
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : Idle Connections: 0.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : Active Connections: 1.
Thread[ACPM,5,main] 09:25:04:404 as400: xxxx : Dead Connections: 0.
Thread[ACPM,5,main] 09:30:04:437 as400: xxxx : ConnectionPool cleanup....
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx : MaxLifeTime: 86400000.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx : MaxUseTime: -1.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx : MaxInactivity: 3600000.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx : PretestConnections: false.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx : Idle Connections: 0.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:30:04:439 as400: xxxx: com.ibm.as400.access.AS400JDBCPooledConnection@1d0 11d01.
Thread[ACPM,5,main] 09:30:04:440 as400: xxxx: ConnectionPool cleanup finished..
Thread[ACPM,5,main] 09:30:04:440 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:30:04:440 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:30:04:440 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:35:04:474 as400: xxxx: ConnectionPool cleanup....
Thread[ACPM,5,main] 09:35:04:474 as400: xxxx: MaxLifeTime: 86400000.
Thread[ACPM,5,main] 09:35:04:474 as400: xxxx: MaxUseTime: -1.
Thread[ACPM,5,main] 09:35:04:474 as400: xxxx: MaxInactivity: 3600000.
Thread[ACPM,5,main] 09:35:04:474 as400: xxxx: PretestConnections: false.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: com.ibm.as400.access.AS400JDBCPooledConnection@1d0 11d01.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: ConnectionPool cleanup finished..
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:35:04:475 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:40:04:508 as400: xxxx: ConnectionPool cleanup....
Thread[ACPM,5,main] 09:40:04:508 as400: xxxx: MaxLifeTime: 86400000.
Thread[ACPM,5,main] 09:40:04:508 as400: xxxx: MaxUseTime: -1.
Thread[ACPM,5,main] 09:40:04:508 as400: xxxx: MaxInactivity: 3600000.
Thread[ACPM,5,main] 09:40:04:508 as400: xxxx: PretestConnections: false.
Thread[ACPM,5,main] 09:40:04:508 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: com.ibm.as400.access.AS400JDBCPooledConnection@1d0 11d01.
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: ConnectionPool cleanup finished..
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:40:04:509 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:45:04:544 as400: xxxx: ConnectionPool cleanup....
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: MaxLifeTime: 86400000.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: MaxUseTime: -1.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: MaxInactivity: 3600000.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: PretestConnections: false.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: Dead Connections: 0.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: com.ibm.as400.access.AS400JDBCPooledConnection@1d0 11d01.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: ConnectionPool cleanup finished..
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: Idle Connections: 0.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: Active Connections: 1.
Thread[ACPM,5,main] 09:45:04:545 as400: xxxx: Dead Connections: 0.
Thread[AS400 Read Daemon [system:localhos;job:173298/QUSER/QZDASOINIT],5,main] 09:46:25:183 Data stream data received (connID=1767926112) ...
Thread[AS400 Read Daemon [system:localhost;job:173298/QUSER/QZDASOINIT],5,main] 09:46:25:183 Data stream data received (connID=1767926112) ...

Was macht er da? Muss ich noch irgendwelche Einstellungen setzen? PTFs?

Danke+Gruß
Max

Fuerchau

06-02-15, 13:45

Das hängt nun ganz von der AS/400 ab.
Wie viele Daten enthält die Datei?
Gibt es einen Index?
Bei solchen Problemen hilft eher selten ein lokaler Trace sondern ein STRDBG im AS/400-Job.
Dieser wird durch eine Trace-Angabe in der Java-Connection gestartet.
Anschließend kannst du per "WRKOBJLCK USER *USRPRF" (User = dein Anmeldeuser) den QZDASOINIT-Job feststellen und die dortigen Nachrichte bzgl. des langsamen SQL's untersuchen und ggf. darauf reagieren.
Dies ist die 1. Variante.

Nun bin ich nicht tief genug in Java um zu wissen, ob es hier die Differenz zwischen Client- und Servercursor gibt.
Ggf. wird beim Execute ein Resultset gebildet, dass alle Daten des Selects beinhaltet. D.h., dass der Execute erst zurückkommt, wenn alles geladen ist.
Auch dies sieht man ggf. im AS/400-Job, da durch blocken dort immer steht "XXX Zeilen von Cursor abgerufen" (o.ä.).
Dies kann natürlich auch dauern.

max40

06-02-15, 15:31

Es werden ca. 15 Statements ausgeführt, die jeweils max 20 Datensätze mit max 20 Feldern zurückliefern.

Habe jetzt mal ein -Dcom.ibm.as400.access.ServerTrace.JDBC=126 hinzugefügt.
Der QZDASOINIT steht auf QDBGETMQO und Jobprotokoll steht:
Der Zugriffsplan der Abfrage wurde erneut erstellt.
****: Debug-Nachrichten für Abfrage werden beendet.
ODP erstellt.
Blockung für Abfrage.
Cursor CRSR0002 eröffnet.

Und das Java-Programm wie bisher.

BenderD

06-02-15, 17:36

... die Infos sind ein wenig rudimentär, aber alles was länger als millisekunden pro Satz dauert sind fehlende Zugriffspfade oder Ressourcenengpässe. Im Joblog des Database Servers müssen unter Debug noch mehr Infos zu finden sein. Generell noch ein paar Hinweise:
- wenn extended dynamic in den Driver Properties aktiviert ist, package löschen und deaktivieren
- andere Treiberversion probieren
- ich würde auch einen ordentlichen ConnectionPool nehmen und nicht diesen Dollschachtel Kram
- log4j einsetzen, das ist flexibller und bei SQL unumgänglich
- alle warnings und SQLCode mit level warning o.ä. protokollieren

D*B

D*B

Robi

17-02-15, 15:41

Fuerchau

17-02-15, 16:03

Ich würde da schon auf ein massives Indexproblem tippen.
QDBGETMQO deutet auf eine MaterializedQuery-Table hin.
M.a.W., ier wird ein Tablescan durchgeführt der eine temporäre MQ-Table erstellt. Diese sind nach IPL meist wieder weg.
Außerdem ist es immer wieder faszinierend, wie SQL ganz anders bei STRSQL optimiert als bei embedded oder ODBC/JDBC. Alle QAQQINI-Einstellungen haben bei mir noch nie zu einer gleichartigen Optimierung geführt.

Deshalb (bei Java kenne ich die Option nicht) nochmal:
Du musst mal die DEBUG-Nachrichten aktivieren und die Joblog-Nachrichten prüfen.

Zur Not kannst du die SQL's auch mal per Opsnav ausführen.
Hier kannst du dir, nach Einschalten, die Diagnosenachrichten direkt ansehen.
Wenn das nicht klappt, versuche es mal mit Excel und Import via ODBC-Quelle.
Hier kannst du den Debugmodus in ODBC konfigurieren.

Beim Debugmodus sollte mehr als "Der Zugriffsplan wurde neu erstellt" stehen.

BenderD

17-02-15, 21:38

Recourcenengpässe sind es M.e. nicht denn...
hier nicht erwähnt wurde ...

1.) Wenn ich genau das SQL -Statement aus dem LOG kopiere und in einer grünen Sitzung ausführe,
habe ich (je Statement) nach maximal 9 Sekunden mein Ergebnis

2.) Die Laufzeit scheint vom Wetter / Tagesform / ... ab zu hängen. Es gibt Tage, da ist die gesamte Statistik nach 1,5-2 Minuten durch, andere Tage (Heute!) läuft das mehrere Stunden!
Die Auslastung der AS400 ist immer gleich, da gibt es keine Lastspitzen durch irgendwelche großen Läufe. CPU immer so bei 35-39 %

@DB kannst du das bitte übersetzen :o

Danke
Robi (der gerade wieder testet, da nun alle PTF eingespielt sind)

... der grüne macht meist optimize for 1 row (oder wenige), das kann bei optimize for all anders aussehen (da werden full table scans eher favorisiert).

Die wechselnden Zugriffszeiten sind geradezu typisch für einen schlechten Connection Pool. Wenn das statemet und temp. indexe in einer Connection gecached sind, dann funzt es, fängt er bei nix an, dann dauert es. (Dollschachtel wie Toolbox) Bessere Pools machen prepared statements und geben Dir diesselbe Connection, wenn es geht, für dasselbe Statement.

Den Debug kannst Du per Connection Property setzen.

Dennoch bleibt es dabei, dass hier was am Index Design krumm ist. Auf einem anderen Blatt steht, ob man durch ziehen von Extrakten, bzw. mit mehr Redundanz im Datenbankdesign hier was machen kann/muss - das ist aber alles eh Kaffeesatz, wenn die Infos nur homöopatisch verabreicht werden.

D*B

Robi

18-02-15, 09:31

Ganz ehrlich?
Ich raff es nicht!
Die Kiste fährt jede Nacht runter!
Wir haben eben den Debug wieder eingeschaltet (ging vorher nie, da die Berechtigung für strtrc fehlte)
Aufgerufen, 21,22,23 fertig (so wie's sein soll)
Den QZDASOINIT Job hab ich beim 2 versuch grad noch so erwischt, aber da steht nix im Joblog, ein Spool hängt da auch nicht dran.
Das Log, das der Java Job geschrieben hat ist riesig, sagt uns aber nix. Ok, heute ist es mal wieder schnell gewesen.
Zu den Daten:
Wir erstellen eine View über 5 Dateien, die Verknüpfung ist immer der unique key, hier meist als indexiertes PF.
Diese View wird mit einer 2. View nach Mandant selektiert (immer 1 Mandant) und nach Monat/Jahr Summiert und ausgegeben 12 Sätze eines SQL's + 3 (Konstante) Kopf Sätze die separat, NICHT aus der View selektiert werden.
Die View's werden nach dem Aufruf des letzten Mandanten gelöscht ( Statistik, wird nur ein mal / Monat gebraucht)

also : select '31.01.2015', '17.02.2015', '31.01.2015' from sysibm/sysdummy1
dann select feld1, feld2, ...from view2 where Mandant = m_Nr and jjmm between 201101 and 201112
dann select feld1, feld2, ...from view2 where Mandant = m_Nr and jjmm between 201201 and 201212
... 2013,14,15

(die between Daten sind variablen, das ist also eine Schleife)
Der Block (andere Felder im select) 3 mal, fertig

Heute morgen: mehrfach aufgerufen, so schnell wie es sein soll,
Gesten nachmittag, quälend langsam (fast 2 Stunden)

Fuerchau

18-02-15, 09:38

Das deutet auf einen IPL am Wochenende hin, so dass temporäre, aber gemerkte Indizes dann wieder weg sind.
Das Löschen eine View ist eigentlich unnötig, sie kostet nichts.
Das Problem sind ggf. nicht die Verknüpfungen sondern die Where-Bedingung.
Hier entscheidet die AS/400 den Indexaufbau bzw. Tablescan.

Um den Debug einzuschalten benötigst du Berechtigung an STRDBG und nicht an STRTRC.
Also muss deine Einstellung für Debug in der Connection noch falsch sein, das deutet auch auf die Menge an Joblog-Einträgen hin.

Robi

18-02-15, 09:54

? IPL am Wochenende?
äh, ja, nicht nur das. Ich schrieb:

Die Kiste fährt jede Nacht runter!

Das sollte bedeuten: jeden Tag IPL:p

Hmm,
unser erster versuch mit Debug brachte im Joblog die Meldung, das die Berechtigung für strtrc fehlt.
Ich frag nochmal in der Java Abteilung
Danke
Robi