Неделю спустя. Прихожу после выходных -- проблема повторяется.

Сначала пытаюсь установить соединение с опубликованным CORBA-объектом по sess_iiop://, клиент зависает.

Затем пытаюсь установить соединение из SQLPlus, с той же удалённой машины:

$ sqlplus /nolog
SQL> CONNECT SYS/change_on_install@ORCL AS SYSDBA;

Клиент зависает. В то же время listener живой, соединение с портами 1521 и 2481 устанавливается. Лог для последнего соединения с клиентской стороны (включённый через sqlnet.ora):

=========== skipped ===========
[09-АВГ-2004 10:27:24:770] nioqsn: entry
[09-АВГ-2004 10:27:24:770] nioqsn: exit
[09-АВГ-2004 10:27:24:770] nioqrc: entry
[09-АВГ-2004 10:27:24:771] nsdo: cid=0, opcode=84, *bl=0, *what=1, uflgs=0x20, c
[09-АВГ-2004 10:27:24:771] nsdo: rank=64, nsctxrnk=0
[09-АВГ-2004 10:27:24:771] nsdo: nsctx: state=8, flg=0x400d, mvd=0
[09-АВГ-2004 10:27:24:771] nsdo: gtn=127, gtc=127, ptn=10, ptc=2011
[09-АВГ-2004 10:27:24:771] nsdofls: DATA flags: 0x0
[09-АВГ-2004 10:27:24:771] nsdofls: sending NSPTDA packet
[09-АВГ-2004 10:27:24:771] nspsend: plen=770, type=6
[09-АВГ-2004 10:27:24:771] nttwr: entry
[09-АВГ-2004 10:27:24:771] nttwr: socket 12 had bytes written=770
[09-АВГ-2004 10:27:24:771] nttwr: exit
[09-АВГ-2004 10:27:24:771] nspsend: 770 bytes to transport
[09-АВГ-2004 10:27:24:772] nsdo: nsctxrnk=0
[09-АВГ-2004 10:27:24:772] nsdo: cid=0, opcode=85, *bl=0, *what=0, uflgs=0x0, cf
[09-АВГ-2004 10:27:24:772] nsdo: rank=64, nsctxrnk=0
[09-АВГ-2004 10:27:24:772] nsdo: nsctx: state=8, flg=0x400d, mvd=0
[09-АВГ-2004 10:27:24:772] nsdo: gtn=127, gtc=127, ptn=10, ptc=2011
[09-АВГ-2004 10:27:24:772] nsdo: switching to application buffer
[09-АВГ-2004 10:27:24:772] nsrdr: recving a packet
[09-АВГ-2004 10:27:24:772] nsprecv: reading from transport...
[09-АВГ-2004 10:27:24:772] nttrd: entry

Ну, то, что "reading from transport" -- это и так понятно. Логинюсь на сервер по ssh, пытаюсь зайти локально:

$ sqlplus /nolog
SQL> CONNECT / AS SYSDBA;

-- тот же отрицательный результат. Решаю посмотреть серверные логи. В ${ORACLE_BASE}/admin/ORCL за последние два дня ничего интересного. Т. е. последняя запись -- два дня назад. Серверный лог (через sqlnet.ora) для последнего соединения, того самого, которое "reading from transport":

========== skipped ===================
nttrd: socket 20 had bytes read=181
nttrd: exit
nsprecv: 181 bytes from transport
nsprecv: tlen=181, plen=181, type=6
nsrdr: got NSPTDA packet
nsrdr: NSPTDA flags: 0x0
nsdo: *what=1, *bl=2009
nsdo: nsctxrnk=0
nioqrc: exit
nioqsn: entry
nioqrc: entry
nsdo: cid=0, opcode=84, *bl=0, *what=1, uflgs=0x20, cflgs=0x3
nsdo: rank=64, nsctxrnk=0
nsdo: nsctx: state=8, flg=0x420c, mvd=0
nsdo: gtn=156, gtc=156, ptn=10, ptc=2019
nsdofls: DATA flags: 0x0
nsdofls: sending NSPTDA packet
nspsend: plen=93, type=6
nttwr: entry
nttwr: socket 20 had bytes written=93
nttwr: exit
nspsend: 93 bytes to transport
nsdo: nsctxrnk=0
nsdo: cid=0, opcode=85, *bl=0, *what=0, uflgs=0x0, cflgs=0x3
nsdo: rank=64, nsctxrnk=0
nsdo: nsctx: state=8, flg=0x420c, mvd=0
nsdo: gtn=156, gtc=156, ptn=10, ptc=2019
nsdo: switching to application buffer
nsrdr: recving a packet
nsprecv: reading from transport...
nttrd: entry
nttrd: socket 20 had bytes read=770
nttrd: exit
nsprecv: 770 bytes from transport
nsprecv: tlen=770, plen=770, type=6
nsrdr: got NSPTDA packet
nsrdr: NSPTDA flags: 0x0
nsdo: *what=1, *bl=2009
nsdo: nsctxrnk=0
nioqrc: exit

Аналогичный локальный клиентский лог (видимо, для работающего на той же машине oracle enterprise manager'а) весит 600 Мб и вся вторая половина загажена сообщениями след. вида:

...nsevwait: nsevwait: nsevwait: nsevwait: nsevwait:
nsevwait: nsevwait: nsevwait: nsevwait: nsevwait:
nsevwait: nsevwait: nsevwait: nsevwait: nsevwait: ...

В то же время

ps -e -o "user,pid,pcpu,pmem,rss,vsz,args"

сообщает, что есть штук восемь процессов с "args" oracle_ORCL, из них три отожрали почти всю память (25, 25 и 17%), причём для одного значение "pcpu" колеблется между 97% и 100%, причём эти "почти сто процентов" -- не system time, а user time, что подтверждается: по данным sdtperfmeter (утилита такая в соляре для мониторинга производительности), активность disk/page/swap практически на нуле. Но при этом cpu load -- 100%, system load -- 4. vmstat сообщает то же самое:

cpu
cs  us sy id
287  99 1 0
285 100 0 0
280 100 0 0
272 100 0 0
298  98 2 0
275  99 1 0
267 100 0 0
307  97 3 0
282 100 0 0
270 100 0 0
307  98 2 0
287 100 0 0

Здесь "cs" -- "the number of cpu context switches per second" (кто бы объяснил толком, что это такое);
"us" -- user time процессора; "sy" -- system time процессора.


Ждал три часа, нормально зашатдаунить базу так и не смог, плюнул, перезагрузил машину. Помогло. До след. викенда.
Вопрос: над чем оракл мог так долго думать? На OTN народ сказал, что, скорее всего, это баг, и надо обращаться в metalink. Есть ли какие-л. другие пути? Может ли быть мисконфигурация оракла?

Заранее спасибо.

Здравствуйте, Bass, Вы писали:

B>Неделю спустя. Прихожу после выходных -- проблема повторяется.
B> === skipped ===
B>Ждал три часа, нормально зашатдаунить базу так и не смог, плюнул, перезагрузил машину. Помогло. До след. викенда.

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

на металинке только 8рка фигурирует. выдай точно что за ось и сильно рекомендую апгрейд до 9.2.0.5
посмотри top, покажи какие процессы, наверху.


Doc ID: Note:68059.1
Subject: ALERT: Oracle 8 SQL*Plus connections from Solaris 2.6 to HP/UX & SNI hang
Type: ALERT
Status: PUBLISHED

Content Type: TEXT/PLAIN
Creation Date: 14-JAN-1999
Last Revision Date: 10-MAY-2002

Oracle 8 sqlplus client connections from Solaris 2.6 to HP/UX and SNI systems

can hang.

This problem has been described in a number of Oracle bugs: bug:601571,

bug:752562, bug:757577, bug:761106, bug:805590.

There has been much confusion over the issue, and suggestions that it's caused

(or resolved) by Solaris patch 105786-05, and that using a Net 8 listener, or

MTS on the server is a workaround. None of this has been proved to be true.

The ONLY RELIABLE WORKAROUND that has been identified is to set:

DISABLE_OOB=ON

In the client's "sqlnet.ora" file (disabling Oracle's use of urgent data

messages).

The problem is actually due to incorrect behaviour by either the Sun or

HP/Pyramid TCP stack when dealing with un-ack'd urgent data messages. The

problem is currently the subject of discussion between Sun & HP.

It causes the client and server processes to get out of sync, by affecting

SQL*Net's (default) out-of-band break/reset mechanism.

This break/reset mechanism is implemented by the client sending a single-byte

urgent data message (the TCP MSB_OOB flag is set), followed by an 11-byte

normal data packet (NSPTMK).

The reason this only affects Solaris to HP/UX & SNI is that these platforms

have a different method for handling simultaneous urgent messages on the same

socket. On HP & SNI the first byte of the 11-byte data packet is lost, causing

a 12569: header checksum error.

Note: This problem does NOT affect Server Manager's connection attempt, as

Server Manager doesn't perform the same datatype negotiation during connection

establishment, therefore avoiding use of the break/reset mechanism.

This bug can be identified by the following information in level 16 client and

server trace files:

Client trace file:

~~~~~~~~~~~~~~~~~~

...

nsrdr: NSPTDA flags: 0x0

nsrdr: normal exit

nsdo: *what=1, *bl=2038

nsdo: nsctxrnk=0

nsdo: normal exit

nioqrc: exit

nioqsn: entry

nioqbr: entry

nioqbr: state = normal (0)

nioqsm: entry

nioqsm: Sending break packet (1)...

nsdo: entry

nsdo: cid=0, opcode=67, *bl=1, *what=18, uflgs=0x100, cflgs=0x3

nsdo: rank=64, nsctxrnk=0

nsdo: nsctx: state=8, flg=0x420d, mvd=0

nsdo: gtn=127, gtc=127, ptn=10, ptc=2047

nsdo: sending ATTN

nsdo: 127 urgent byte to transport

nsdo: nsctxrnk=0

nsdo: normal exit

nioqbr: exit

nioqrs: entry

nioqrs: state = interrupted (1)

nioqrs: nioqrs: Not in send state ...

nioqsm: entry

nioqsm: Sending reset packet (2)...

nsdo: entry

nsdo: cid=0, opcode=67, *bl=1, *what=17, uflgs=0x0, cflgs=0x3

nsdo: rank=64, nsctxrnk=0

nsdo: nsctx: state=8, flg=0x420d, mvd=0

nsdo: gtn=127, gtc=127, ptn=10, ptc=2047

nsdofls: entry

nsdofls: DATA flags: 0x0

nsdofls: normal exit

nsdo: sending NSPTMK packet

nspsend: entry

nspsend: plen=11, type=12

nttwr: entry

nttwr: socket 11 had bytes written=11

nttwr: exit

nspsend: 11 bytes to transport

nspsend: packet dump

nspsend:00 0B 00 00 0C 00 00 00 |........|

nspsend:01 00 02 00 00 00 00 00 |........|

nspsend: normal exit

nsdoacts: entry

nsdofls: entry

nsdofls: DATA flags: 0x0

nsdofls: normal exit

nsdoacts: flushing transport

nttctl: entry

nsdoacts: normal exit

nsdo: nsctxrnk=0

nsdo: normal exit

nioqrs: nioqrs: sucking for reset marker...

nioqar: entry

nioqar: nioqar: suck pipe til I get a reset...

nscontrol: entry

nscontrol: cmd=1, lcl=0x0

nscontrol: normal exit

nscontrol: entry

nscontrol: cmd=3, lcl=0x2

nscontrol: normal exit

nsdo: entry

nsdo: cid=0, opcode=85, *bl=0, *what=0, uflgs=0x0, cflgs=0x3

nsdo: rank=64, nsctxrnk=0

nsdo: nsctx: state=8, flg=0x420d, mvd=0

nsdo: gtn=127, gtc=127, ptn=10, ptc=2047

nsdo: switching to application buffer

nsrdr: entry

nsrdr: recving a packet

nsprecv: entry

nsprecv: reading from transport...

nttrd: entry

nttrd: socket 11 had bytes read=11

nttrd: exit

nsprecv: 11 bytes from transport

nsprecv: tlen=11, plen=11, type=12

nsprecv: packet dump

nsprecv:00 0B 00 00 0C 00 00 00 |........|

nsprecv:01 00 02 00 00 00 00 00 |........|

nsprecv: normal exit

nsrdr: got NSPTMK packet

nsrdr: normal exit

nsdo: *what=17, *bl=1

nsdo: nsctxrnk=0

nsdo: normal exit

nioqar: exit

nscontrol: entry

nscontrol: cmd=2, lcl=0x0

nscontrol: normal exit

nsnactl: entry

nactl_internal: entry

naeectl: entry

naeectl: exit

naecctl: entry

naecctl: exit

nactl_internal: exit

nsnactl: error exit

nserror: entry

nserror: nsres: id=0, op=77, ns=12630, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0

nioqer: entry

nioqer: incoming err = 0

nioqce: entry

nioqce: exit

nioqer: returning err = 0

nioqer: exit

nioqrs: exit

nioqrc: entry

nsdo: entry

nsdo: cid=0, opcode=85, *bl=0, *what=0, uflgs=0x0, cflgs=0x3

nsdo: rank=64, nsctxrnk=0

nsdo: nsctx: state=8, flg=0x420d, mvd=0

nsdo: gtn=127, gtc=127, ptn=10, ptc=2047

nsdo: switching to application buffer

nsrdr: entry

nsrdr: recving a packet

nsprecv: entry

nsprecv: reading from transport...

nttrd: entry

The client hangs at this point....

Server trace file:

~~~~~~~~~~~~~~~~~~

...

nsdo: switching to application buffer

nsrdr: entry

nsrdr: recving a packet

nsprecv: entry

nsprecv: reading from transport...

nttrd: entry

nttrd: socket 12 had bytes read=10

nttrd: exit

nsprecv: 10 bytes from transport

-<ERROR>- nsprecv: header checksum error

nsprecv:packet hdr

nsprecv:0B 00 00 0C 00 00 00 00 |........|

nsprecv: error exit

nserror: entry

-<ERROR>- nserror: nsres: id=0, op=68, ns=12569, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0

nsrdr: error exit

nsdo: nsctxrnk=0

nsdo: error exit

osnqrc: interrupt came in while in ns...

osnqhp: entry

osnqhp: handling break in state sent (1)

osnqhp: exit

osnqrc: exit

osnqrs: entry

osnqrs: state = interrupted (1)

osnqrs: osnqrs: sending reset marker...

osnqsm: entry

osnqsm: Sending reset packet (2)...

nsdo: entry

nsdo: cid=0, opcode=67, *bl=1, *what=17, uflgs=0x0, cflgs=0x3

nsdo: rank=64, nsctxrnk=0

nsdo: nsctx: state=8, flg=0x420c, mvd=0

nsdo: gtn=143, gtc=143, ptn=10, ptc=2048

nsdofls: entry

nsdofls: DATA flags: 0x0

nsdofls: normal exit

nsdo: sending NSPTMK packet

nspsend: entry

nspsend: plen=11, type=12

nttwr: entry

nttwr: socket 12 had bytes written=11

nttwr: exit

nspsend: 11 bytes to transport

nspsend:packet dump

nspsend:00 0B 00 00 0C 00 00 00 |........|

nspsend:01 00 02 00 00 00 00 00 |........|

nspsend: normal exit

nsdoacts: entry

nsdofls: entry

nsdofls: DATA flags: 0x0

nsdofls: normal exit

nsdoacts: flushing transport

nttctl: entry

nsdoacts: normal exit

nsdo: nsctxrnk=0

nsdo: normal exit

osnqsm: exit

osnqrs: osnqrs: sucking for reset marker...

osnqar: entry

osnqar: osnqar: suck pipe til I get a reset...

nsdo: entry

nsdo: cid=0, opcode=85, *bl=0, *what=0, uflgs=0x0, cflgs=0x3

nsdo: rank=64, nsctxrnk=0

nsdo: nsctx: state=8, flg=0x420c, mvd=0

nsdo: gtn=143, gtc=143, ptn=10, ptc=2048

nsdo: switching to application buffer

nsrdr: entry

nsrdr: recving a packet

nsprecv: entry

nsprecv: reading from transport...

The server hangs at this point.

Большое спасибо за информацию.

Система -- Sun Ultra 10, 1 UltraSPARC IIi 440Mhz CPU.
Ось -- Solaris 5.9 Maintenance Update 4
Оракл -- 9.0.1 (9i Release 1) без каких-либо патчей/апдейтов.

Вопрос: сейчас на эту версию оракла получить платную поддержку можно? А то я по OTN полазил -- ничего путного не нашёл. Все в сотоянии эйфории от выхода 10g...

B>Система -- Sun Ultra 10, 1 UltraSPARC IIi 440Mhz CPU.
B>Ось -- Solaris 5.9 Maintenance Update 4
B>Оракл -- 9.0.1 (9i Release 1) без каких-либо патчей/апдейтов.

сначала пачить хотя бы до 9.0.1.4 (там 250 мб), если не проканает то до 9.2.0.5. имхо только потом можно смотреть логи.

B>Вопрос: сейчас на эту версию оракла получить платную поддержку можно? А то я по OTN полазил -- ничего путного не нашёл. Все в сотоянии эйфории от выхода 10g...

точно не знаю, но если и можно то через пару месяцев она проэкспирится. а на otn ничего не бывает в принципе — им металик продавать нада ...

Здравствуйте, Аноним, Вы писали:

А>а на otn ничего не бывает в принципе — им металик продавать нада ...
Ну почему же, на форумах достаточно много независимой и толковой публики. Даже наши иногда тусуются, индусов поучают...