Зависание запроса через jdbc, использующего dblink

fabler
Дата: 20.03.2011 18:59:03
Добрый день!

используются следующая схема: БД на Oracle 10 на Solaris x86 (типа агрегатор), она имеет связь через dblink с другими БД (Oracle 10 на Solaris SPARC), архитектура которых абсолютно идентична.
Программы, написанные на java, крутятся на сервере Solaris x86 и все запросы до других БД идут через dblink'и БД-агрегатора.
запросы несложные, нигде не связываются таблицы/НД с разных ДБ.

Вдруг, почему-то перестало работать несколько запросов вида:
select t1.col1, t2.col1
from table1@db_1 t1
inner join table2@db_1 t2 on (t1.id = t2.id) where t2.col3 = 1
order by ...;

что значит не работает: запрос должен вернуть около 70000 записей, но происходит следующее:
ResultSet благополучно открывается, записи в цикле начинают забираться и сохраняться в массив, но после записи № 49470 метод rset.next() виснет. Может провисеть хоть 12 часов без генерации исключений и пр.
пример java кода:
            rset = stmt.executeQuery(query);
            System.out.println("Забрал");
            progBar=0;
            while (rset.next()){
                progBar++;
                if (progBar == 49468) {
                    System.out.print("+"); //для дебага
                }
                /*операции обработки записи и сохранения в массив*/
            }
            System.out.println("\n");
            System.out.println("Положил в массив " + arr.size());
            System.out.print("Закрываю ResultSet... ");
            rset.close();
            System.out.print(" Закрыл...\n");

при этом на сервере db_1 в логе sqlnet.log пишется:

Tracing not turned on.
Tns error struct:
ns main err code: 12535
TNS-12535: TNS:operation timed out
ns secondary err code: 12560
nt main err code: 505
TNS-00505: Operation timed out
nt secondary err code: 145
nt OS err code: 0
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=W.X.Y.Z)(PORT=54606))

непонятно почему, недавно еще все работало (как всегда)...

подозрение пало на dblink'и, т.к. переделанная программа, в которой jdbc соединение устанавливается напрямую c db_1, отрабатывает корректно. хотя запрос с использованием dblink в sqlplus также возвращает полный набор записей...



есть ли мнение, куда копать, что смотреть, чтобы выяснить и устранить причину этого странного поведения?

Буду благодарен за любую помощь по теме!
Андрей Панфилов
Дата: 20.03.2011 19:03:11
fabler
есть ли мнение, куда копать, что смотреть, чтобы выяснить и устранить причину этого странного поведения?
пока у вас нет треддампа в предполагаемый момент зависания, говорить не о чем.
//http://expertodev.wordpress.com/2009/05/30/how-to-take-java-thread-dump/
fabler
Дата: 20.03.2011 19:21:23
Андрей Панфилов,

благодарю за полезную информацию!

ниже дамп после зависания.
но насколько я посмотрел, его вид не отличается от момента, когда программа еще работает.
меня смутили только выделенные locked

или я не туда смотрю?



2011-03-20 19:12:58
Full thread dump Java HotSpot(TM) Server VM (17.1-b03 mixed mode):

"Low Memory Detector" daemon prio=3 tid=0x0815f800 nid=0xd runnable [0x00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=3 tid=0x0815d000 nid=0xc waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=3 tid=0x0815b000 nid=0xb waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=3 tid=0x08159800 nid=0xa waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=3 tid=0x08148000 nid=0x9 in Object.wait() [0xb6713000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0xbaee1130> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0xbaee1130> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=3 tid=0x08143800 nid=0x8 in Object.wait() [0xb6764000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0xbaee1200> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0xbaee1200> (a java.lang.ref.Reference$Lock)

"main" prio=3 tid=0x0806fc00 nid=0x2 runnable [0xfe35e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.DataPacket.receive(Unknown Source)
at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1099)
at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1070)
at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:478)
at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:207)
at oracle.jdbc.driver.T4CStatement.fetch(T4CStatement.java:1205)
at oracle.jdbc.driver.OracleResultSetImpl.close_or_fetch_from_next(OracleResultSetImpl.java:373)
- locked <0xbaf00ad0> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.OracleResultSetImpl.next(OracleResultSetImpl.java:284)
- locked <0xe6065ef8> (a oracle.jdbc.driver.OracleResultSetImpl)
at db.dbConnection.getIncorrectC(dbConnection.java:711)
at confManagers.Dmanager.getHtmlCReport(RASmanager.java:92)
at confmanager.Main.main(Main.java:45)

"VM Thread" prio=3 tid=0x08141000 nid=0x7 runnable

"GC task thread#0 (ParallelGC)" prio=3 tid=0x08076800 nid=0x3 runnable

"GC task thread#1 (ParallelGC)" prio=3 tid=0x08077c00 nid=0x4 runnable

"GC task thread#2 (ParallelGC)" prio=3 tid=0x08079000 nid=0x5 runnable

"GC task thread#3 (ParallelGC)" prio=3 tid=0x0807a400 nid=0x6 runnable

"VM Periodic Task Thread" prio=3 tid=0x08162000 nid=0xe waiting on condition

JNI global references: 1477

Heap
PSYoungGen total 71424K, used 21423K [0xe5a00000, 0xed000000, 0xfb000000)
eden space 66176K, 24% used [0xe5a00000,0xe69cdc40,0xe9aa0000)
from space 5248K, 99% used [0xe9aa0000,0xe9fbe310,0xe9fc0000)
to space 6912K, 0% used [0xec940000,0xec940000,0xed000000)
PSOldGen total 45056K, used 6089K [0xbae00000, 0xbda00000, 0xe5a00000)
object space 45056K, 13% used [0xbae00000,0xbb3f2410,0xbda00000)
PSPermGen total 16384K, used 8759K [0xb6e00000, 0xb7e00000, 0xbae00000)
object space 16384K, 53% used [0xb6e00000,0xb768dcb0,0xb7e00000)



Андрей Панфилов
Дата: 20.03.2011 20:06:06
fabler
но насколько я посмотрел, его вид не отличается от момента, когда программа еще работает.
меня смутили только выделенные locked
то что locked - не обращайте внимание (по крайней мере в вашем случае так и должно быть). судя по стеку с жавой ничего подозрительного нет, кроме заполненности пространства from (from space 5248K, 99% used [0xe9aa0000,0xe9fbe310,0xe9fc0000)). Можно попытаться либо увеличить конкретный сегмент либо весь хип (насколько я понял, у вас жава запускается без каких-либо параметров, задающих размер хипа, и/или он у вас 128m) - попробуйте выставить -Xms256m -Xmx512m, если никак положительно не повиляет, то начинайте указывать номера версий (оракла, жавы, драйверов jdbc)
fabler
Дата: 20.03.2011 20:34:48
Андрей Панфилов,

99% видел, но эта величина не постоянная, эта область расширяется по мере необходимости, как я понял.
запускал действительно без каких-либо дополнительных настроек.

но дело не в яве, я думаю. Ведь эта же программа нормально работает, если не использовать dblink, а выкачивать 70000 записей напрямую из другой БД. ну и в принципе программа работала до определенного момента (понять бы, до какого...)

если запускать программу с предложенными параметрами, то, к сожалению, ничего не меняется
java -jar -Xms256m -Xmx512m <полное имя jar файла>


дамп:


2011-03-20 20:20:04
Full thread dump Java HotSpot(TM) Server VM (17.1-b03 mixed mode):

"Low Memory Detector" daemon prio=3 tid=0x0815f800 nid=0xd runnable [0x00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=3 tid=0x0815d000 nid=0xc waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=3 tid=0x0815b000 nid=0xb waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=3 tid=0x08159800 nid=0xa waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=3 tid=0x08148000 nid=0x9 in Object.wait() [0xd68c3000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0xf44803b0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0xf44803b0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=3 tid=0x08143800 nid=0x8 in Object.wait() [0xd6914000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0xf448c0e0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0xf448c0e0> (a java.lang.ref.Reference$Lock)

"main" prio=3 tid=0x0806fc00 nid=0x2 runnable [0xfe35e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Unknown Source)
at oracle.net.ns.DataPacket.receive(Unknown Source)
at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.net.ns.NetInputStream.read(Unknown Source)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1099)
at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1070)
at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:478)
at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:207)
at oracle.jdbc.driver.T4CStatement.fetch(T4CStatement.java:1205)
at oracle.jdbc.driver.OracleResultSetImpl.close_or_fetch_from_next(OracleResultSetImpl.java:373)
- locked <0xf4597148> (a oracle.jdbc.driver.T4CConnection)
at oracle.jdbc.driver.OracleResultSetImpl.next(OracleResultSetImpl.java:284)
- locked <0xf2e716c8> (a oracle.jdbc.driver.OracleResultSetImpl)
at db.dbConnection.getIncorrectNBR(dbConnection.java:711)
at NEconfManagers.RASmanager.getHtmlNBRReport(RASmanager.java:92)
at wsmconfmanager.Main.main(Main.java:45)

"VM Thread" prio=3 tid=0x08141000 nid=0x7 runnable

"GC task thread#0 (ParallelGC)" prio=3 tid=0x08076800 nid=0x3 runnable

"GC task thread#1 (ParallelGC)" prio=3 tid=0x08077c00 nid=0x4 runnable

"GC task thread#2 (ParallelGC)" prio=3 tid=0x08079800 nid=0x5 runnable

"GC task thread#3 (ParallelGC)" prio=3 tid=0x0807ac00 nid=0x6 runnable

"VM Periodic Task Thread" prio=3 tid=0x08162000 nid=0xe waiting on condition

JNI global references: 1471

Heap
PSYoungGen total 77056K, used 62404K [0xf0400000, 0xf9c00000, 0xfb000000)
eden space 66048K, 80% used [0xf0400000,0xf37d6ae8,0xf4480000)
from space 11008K, 84% used [0xf4480000,0xf4d9a860,0xf4f40000)
to space 11008K, 0% used [0xf9140000,0xf9140000,0xf9c00000)
PSOldGen total 176128K, used 0K [0xdae00000, 0xe5a00000, 0xf0400000)
object space 176128K, 0% used [0xdae00000,0xdae00000,0xe5a00000)
PSPermGen total 16384K, used 8759K [0xd6e00000, 0xd7e00000, 0xdae00000)
object space 16384K, 53% used [0xd6e00000,0xd768dcb8,0xd7e00000)


версии софта:


[user@isystem:~] java -version
java version "1.6.0_22"
Java(TM) SE Runtime Environment (build 1.6.0_22-b04)
Java HotSpot(TM) Server VM (build 17.1-b03, mixed mode)
[user@isystem:~] sqlplus -version
SQL*Plus: Release 10.2.0.1.0 - Production - БД-агрегатор
[user@isystem:~]

JDBC драйвер ojdbc14_g, взятый с сайта Оракла, для Release 10.2.0.1.0

[oracle@db_1: /db/oracle] sqlplus -version
SQL*Plus: Release 10.2.0.3.0 - Production - пример удаленного сервера db_1
[oracle@db_1: /db/oracle]
fabler
Дата: 20.03.2011 21:06:31
в режиме debug программы это выглядит, как незавершающийся метод rset.next() в проверке цикла while (rset.next()){....}
т.е. метод вызывается, начинает выполняться, но не завершается
-2-
Дата: 20.03.2011 22:03:48
fabler
непонятно почему, недавно еще все работало (как всегда)...
Возможно сменили настройки файрвола, маршрутизатора, бд, ... Что база думает по поводу зависшей сессии?
Андрей Панфилов
Дата: 20.03.2011 22:20:10
-2-
Возможно сменили настройки файрвола, маршрутизатора, бд, ... Что база думает по поводу зависшей сессии?
как я понял у ТС на локальной БД не воспроизводится и на SQLPlus тоже не воспроизводится (осталось разве что проверить воспроизводимость на thiсk драйвере). А вообще на металинке только это с похожими симптомами (правда там серверный процесс падает)
fabler
Дата: 20.03.2011 22:25:34
-2-
Возможно сменили настройки файрвола, маршрутизатора, бд, ...

ну что сказать по поводу сети и пр...
как-то получить первые 49000 записей удается...
+ все работает при прямом обращении к удаленной БД
-2-
Что база думает по поводу зависшей сессии?

удаленная БД:

Tracing not turned on.
Tns error struct:
ns main err code: 12535
TNS-12535: TNS:operation timed out
ns secondary err code: 12560
nt main err code: 505
TNS-00505: Operation timed out
nt secondary err code: 145
nt OS err code: 0
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=W.X.Y.Z)(PORT=54606))

БД-агрегатор: ничего толком не нашел.
Где/что искать?
fabler
Дата: 21.03.2011 12:53:07
как можно посомтреть на стороне Оракла, БД-агрегатора, может, ему там памяти не хватает?
начал читать про instance_tune.htm , но пока все V$...STAT в голове улягутся... может, есть какие-то устоявшиеся полезные запросы, показывающие критичные места?

явно, что чот-то порисходит между 2мя Ораклами, пока данные идут по dblink.
может, есть ограничения по dblink'ам (длительность сессии и пр)?