Hi all,
Database :Oracle 11g database Standard edition 11.2.0.1
Application : Oracle forms 6i client/sever (sqlplus version 6.0.8)
OS : Windows 2008 server with sp1
When i tried to connect to database using sqlplus (6.0.8) it is very slow. At the same time when itried connecting from 11g sql client it connects faster.
We tried installing Oracle 11.2.0.1 EE database on a Win 7 Pc and tried connecting to it, it connects in a flash in both 11g and 6.0.8 clients.
I traced it and found there is a significant delay in below area,
2012-10-17 22:17:12.644127 : snlpcss:Spawn Oracle completed oracle (LOCAL=NO) orcl.
2012-10-17 22:17:12.644233 : snlpcss:exit
*2012-10-17 22:17:12.644337 : sntpcall:Attempting to open pipe \\.\PIPE\ORANTP874.1878*
*2012-10-17 22:17:12.653334 : sntpcall:Successfully established pipe 808 to child with 0 retries.*
2012-10-17 22:17:12.653373 : sntpcall:Attempting to open pipe \\.\PIPE\ORANTP874.1878.w
2012-10-17 22:17:12.653437 : sntpcall:Successfully established pipe 920 to child with 0 retries.
2012-10-17 22:17:12.653475 : sntpcall:exit
2012-10-17 22:17:12.635186 : nsevfnt:cxd: 0x5e60760 stage 0: NT events set:
CONNECTION REQUEST
2012-10-17 22:17:12.635211 : nsevfnt:cxd: 0x5e60760 stage 0: NS events set:
INCOMING CALL
2012-10-17 22:17:12.635235 : nsevrec:event is 0x1, on 3
2012-10-17 22:17:12.635254 : nsevwait:1 posted event(s)
2012-10-17 22:17:12.635272 : nsevwait:exit (0)
2012-10-17 22:17:12.635316 : nsglhe:entry
2012-10-17 22:17:12.635337 : nsglhe:Event on cxd 0x5e60760.
2012-10-17 22:17:12.635366 : nsglhc:Allocating cxd 0x62da3c0
2012-10-17 22:17:12.635386 : nsanswer:entry
2012-10-17 22:17:12.635405 : nsopen:entry
2012-10-17 22:17:12.635429 : nsmal:entry
2012-10-17 22:17:12.635450 : nsmal:1496 bytes at 0x5f2e7f0
2012-10-17 22:17:12.635466 : nsmal:normal exit
2012-10-17 22:17:12.635486 : nsopenmplx:entry
2012-10-17 22:17:12.635675 : nsmal:entry
2012-10-17 22:17:12.635709 : nsmal:2944 bytes at 0x6022e80
2012-10-17 22:17:12.635726 : nsmal:normal exit
2012-10-17 22:17:12.635743 : nsiorini:entry
2012-10-17 22:17:12.635762 : nsbal:entry
2012-10-17 22:17:12.635778 : nsbgetfl:entry
2012-10-17 22:17:12.635796 : nsbgetfl:normal exit
2012-10-17 22:17:12.635814 : nsbal:normal exit
2012-10-17 22:17:12.635830 : nsiorini:exit (0)
2012-10-17 22:17:12.635848 : nscpxget:entry
2012-10-17 22:17:12.635864 : nscpxget:normal exit
2012-10-17 22:17:12.635884 : nsopenalloc_nsntx:nlhthput on mplx_ht_nsgbu:ctx=5f2e7f0, nsntx=6022e80
2012-10-17 22:17:12.635906 : nsopenmplx:normal exit
2012-10-17 22:17:12.635927 : nstoSetupTimeout:entry
2012-10-17 22:17:12.635947 : nstoSetupTimeout:ATO enabled for ctx=0x0000000005F2E7F0, val=60000(millisecs)
2012-10-17 22:17:12.635966 : nstoUpdateActive:entry
2012-10-17 22:17:12.635984 : nstoUpdateActive:Active timeout is 0 (see nstotyp)
2012-10-17 22:17:12.636002 : nsopen:opening transport...
2012-10-17 22:17:12.636023 : nttcon:entry
2012-10-17 22:17:12.636039 : nttcon:toc = 3
2012-10-17 22:17:12.636063 : nttcnp:entry
2012-10-17 22:17:12.636106 : nttcnp:getting sockname
2012-10-17 22:17:12.636131 : nttcnp:getting peername
2012-10-17 22:17:12.636149 : nttcnp:exit
2012-10-17 22:17:12.636166 : nttcnr:entry
2012-10-17 22:17:12.636182 : nttcnr:waiting to accept a connection.
2012-10-17 22:17:12.636322 : nttcnr:getting sockname
2012-10-17 22:17:12.636352 : snlinGetNameInfo:entry
2012-10-17 22:17:12.636380 : snlinGetNameInfo:exit
2012-10-17 22:17:12.636398 : nttcnr:connected on ipaddr 200.200.210.101
2012-10-17 22:17:12.636416 : nttvlser:entry
2012-10-17 22:17:12.636432 : nttvlser:Accepted Entry
2012-10-17 22:17:12.636448 : nttcnr:exit
2012-10-17 22:17:12.636477 : nttcon:NT layer TCP/IP connection has been established.
2012-10-17 22:17:12.636518 : nttcon:set TCP_NODELAY on 904
2012-10-17 22:17:12.636537 : nttcon:exit
2012-10-17 22:17:12.636556 : nsiorecycle:entry
2012-10-17 22:17:12.636572 : nsiorecycle:exit
2012-10-17 22:17:12.636589 : nsopen:transport is open
2012-10-17 22:17:12.636607 : nstoPostNTConn:entry
2012-10-17 22:17:12.636624 : nstoArmEventATO:entry
2012-10-17 22:17:12.636642 : nstoArmEventATO:exit (0)
2012-10-17 22:17:12.636659 : nstoPostNTConn:exit (0)
2012-10-17 22:17:12.636676 : nsnainit:entry
2012-10-17 22:17:12.636694 : nsnainit:answer
2012-10-17 22:17:12.636710 : nsnadct:entry
2012-10-17 22:17:12.636726 : nsnadct:normal exit
2012-10-17 22:17:12.636741 : nsnasvnainfo:entry
2012-10-17 22:17:12.636758 : nsnasvnainfo:NA disabled for this connection
2012-10-17 22:17:12.636774 : nsnasvnainfo:normal exit
2012-10-17 22:17:12.636794 : nainit:entry
2012-10-17 22:17:12.636814 : nagblini:entry
2012-10-17 22:17:12.636839 : nau_gin:entry
2012-10-17 22:17:12.636858 : nau_gparams:entry
2012-10-17 22:17:12.636877 : nam_gbp:Reading parameter "sqlnet.authentication_required" from parameter file
2012-10-17 22:17:12.636897 : nam_gbp:Parameter not found
2012-10-17 22:17:12.636914 : nau_gparams:Using default value "FALSE"
2012-10-17 22:17:12.636931 : nau_gslf:entry
2012-10-17 22:17:12.636947 : nam_gic:entry
2012-10-17 22:17:12.636965 : nam_gic:Counting # of items in "sqlnet.authentication_services" parameter
2012-10-17 22:17:12.636984 : nam_gic:Parameter not found
2012-10-17 22:17:12.637001 : nam_gic:Found 0 items
2012-10-17 22:17:12.637016 : nam_gic:exit
2012-10-17 22:17:12.637033 : nau_gslf:Using default value "all available adapters"
2012-10-17 22:17:12.637050 : nauss_set_state:entry
2012-10-17 22:17:12.637065 : nauss_set_state:exit
2012-10-17 22:17:12.637081 : nau_gslf:exit
2012-10-17 22:17:12.637096 : nau_gparams:exit
2012-10-17 22:17:12.637112 : nau_gin:exit
2012-10-17 22:17:12.637126 : nagblini:exit
2012-10-17 22:17:12.637144 : na_saveprot:entry
2012-10-17 22:17:12.637165 : na_saveprot:exit
2012-10-17 22:17:12.637182 : nacomin:entry
2012-10-17 22:17:12.637200 : nas_init:entry
2012-10-17 22:17:12.637217 : nas_init:exit
2012-10-17 22:17:12.637233 : nau_ini:entry
2012-10-17 22:17:12.637252 : naugcp_get_connect_parameters:entry
2012-10-17 22:17:12.637268 : nauss_set_state:entry
2012-10-17 22:17:12.637283 : nauss_set_state:exit
2012-10-17 22:17:12.637299 : naugcp_get_connect_parameters:exit
2012-10-17 22:17:12.637315 : nau_gettab:entry
2012-10-17 22:17:12.637333 : nau_gettab:using authentication adapter table "nautab"
2012-10-17 22:17:12.637350 : nau_gettab:nautab contains the following services:
2012-10-17 22:17:12.637366 : nau_gettab: KERBEROS5
2012-10-17 22:17:12.637381 : nau_gettab: NTS
2012-10-17 22:17:12.637395 : nau_gettab: RADIUS
2012-10-17 22:17:12.637410 : nau_gettab:exit
2012-10-17 22:17:12.637426 : nau_sini:entry
2012-10-17 22:17:12.637441 : nau_sini:exit
2012-10-17 22:17:12.637456 : nau_ini:connection type: "standard"
2012-10-17 22:17:12.637473 : nau_ini:exit
2012-10-17 22:17:12.637489 : naeeinit:entry
2012-10-17 22:17:12.637507 : nam_gbp:Reading parameter "SQLNET.FIPS_140" from parameter file
2012-10-17 22:17:12.637526 : nam_gbp:Parameter not found
2012-10-17 22:17:12.637544 : nam_gnsp:Reading parameter "SQLNET.ENCRYPTION_SERVER" from parameter file
2012-10-17 22:17:12.637564 : nam_gnsp:Parameter not found
2012-10-17 22:17:12.637581 : naequad:Using default value "ACCEPTED"
2012-10-17 22:17:12.637596 : nam_gic:entry
2012-10-17 22:17:12.637613 : nam_gic:Counting # of items in "SQLNET.ENCRYPTION_TYPES_SERVER" parameter
2012-10-17 22:17:12.637631 : nam_gic:Parameter not found
2012-10-17 22:17:12.637646 : nam_gic:exit
2012-10-17 22:17:12.637662 : naesno:Using default value "all available algorithms"
2012-10-17 22:17:12.637684 : naeshow:entry
2012-10-17 22:17:12.637706 : naeshow:These are the encryption algorithms that the server will accept, in decreasing order of
preference:
2012-10-17 22:17:12.637726 : naeshow:Choice 0: no algorithm; encryption inactive
2012-10-17 22:17:12.637741 : naeshow:exit
2012-10-17 22:17:12.637756 : naeeinit:exit
2012-10-17 22:17:12.637773 : naecinit:entry
2012-10-17 22:17:12.637790 : nam_gnsp:Reading parameter "SQLNET.CRYPTO_CHECKSUM_SERVER" from parameter file
2012-10-17 22:17:12.637808 : nam_gnsp:Parameter not found
2012-10-17 22:17:12.637824 : naequad:Using default value "ACCEPTED"
2012-10-17 22:17:12.637840 : nam_gic:entry
2012-10-17 22:17:12.637856 : nam_gic:Counting # of items in "SQLNET.CRYPTO_CHECKSUM_TYPES_SERVER" parameter
2012-10-17 22:17:12.637874 : nam_gic:Parameter not found
2012-10-17 22:17:12.637889 : nam_gic:exit
2012-10-17 22:17:12.637905 : naesno:Using default value "all available algorithms"
2012-10-17 22:17:12.637920 : naeshow:entry
2012-10-17 22:17:12.637937 : naeshow:These are the checksumming algorithms that the server will accept, in decreasing order
of preference:
2012-10-17 22:17:12.637956 : naeshow:Choice 0: no algorithm; checksumming inactive
2012-10-17 22:17:12.637972 : naeshow:exit
2012-10-17 22:17:12.637986 : naecinit:exit
2012-10-17 22:17:12.638003 : nainit:native services disabled - disconnecting
2012-10-17 22:17:12.638020 : nadisc:entry
2012-10-17 22:17:12.638036 : nacomtm:entry
2012-10-17 22:17:12.638052 : nacompd:entry
2012-10-17 22:17:12.638067 : nacompd:exit
2012-10-17 22:17:12.638081 : nacompd:entry
2012-10-17 22:17:12.638096 : nacompd:exit
2012-10-17 22:17:12.638110 : nacomtm:exit
2012-10-17 22:17:12.638126 : nas_dis:entry
2012-10-17 22:17:12.638142 : nas_dis:exit
2012-10-17 22:17:12.638158 : nau_dis:entry
2012-10-17 22:17:12.638175 : nau_dis:exit
2012-10-17 22:17:12.638190 : naeetrm:entry
2012-10-17 22:17:12.638205 : naeetrm:exit
2012-10-17 22:17:12.638221 : naectrm:entry
2012-10-17 22:17:12.638237 : naectrm:exit
2012-10-17 22:17:12.638253 : nagbltrm:entry
2012-10-17 22:17:12.638269 : nau_gtm:entry
2012-10-17 22:17:12.638285 : nau_gtm:exit
2012-10-17 22:17:12.638300 : nagbltrm:exit
2012-10-17 22:17:12.638318 : nadisc:exit
2012-10-17 22:17:12.638338 : nainit:exit
2012-10-17 22:17:12.638357 : nsnainit:NS Connection version: 314
2012-10-17 22:17:12.638377 : nsnainit:inf->nsinfflg[0]: 0xd inf->nsinfflg[1]: 0xd
2012-10-17 22:17:12.638400 : nsnainit:"or" info flags: 0xd Translations follow:
native service(s) is (are) wanted
NA disabled remotely for this connection
NA services unavailable on both processes - negotiation not needed
2012-10-17 22:17:12.638426 : nsnainit:"or" info flags: 0xd Translations follow:
native service(s) is (are) wanted
NA disabled remotely for this connection
NA services unavailable on both processes - negotiation not needed
"and" info flags: 0xd Translations follow:
native service(s) is (are) wanted
NA disabled remotely for this connection
NA services unavailable on both processes - negotiation not needed
2012-10-17 22:17:12.638454 : nsnainit:normal exit
2012-10-17 22:17:12.638473 : nsopen:global context check-in (to slot 5) complete
2012-10-17 22:17:12.638497 : nsopen:lcl[0]=0xf4ffefff, lcl[1]=0x12003, gbl[0]=0x7abf, gbl[1]=0x2001, tdu=32767, sdu=8192
2012-10-17 22:17:12.638517 : nsfull_opn:entry
2012-10-17 22:17:12.638535 : nsfull_opn:cid=5, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x0
2012-10-17 22:17:12.638553 : nsfull_opn:nsctx: state=7, flg=0x4000, mvd=0
2012-10-17 22:17:12.638570 : nsbal:entry
2012-10-17 22:17:12.638584 : nsbgetfl:entry
2012-10-17 22:17:12.638600 : nsbgetfl:normal exit
2012-10-17 22:17:12.638615 : nsbal:normal exit
2012-10-17 22:17:12.638630 : nsbal:entry
2012-10-17 22:17:12.638644 : nsbgetfl:entry
2012-10-17 22:17:12.638660 : nsbgetfl:normal exit
2012-10-17 22:17:12.638674 : nsbal:normal exit
2012-10-17 22:17:12.638690 : nsfull_opn:normal exit
2012-10-17 22:17:12.638706 : nsopen:normal exit
2012-10-17 22:17:12.638724 : nsanswer:deferring connect attempt; at stage 5
2012-10-17 22:17:12.638741 : nsanswer:normal exit
2012-10-17 22:17:12.638758 : nsevreg:entry
2012-10-17 22:17:12.638777 : nsevreg:begin registration process for 5
2012-10-17 22:17:12.638795 : nsevregPrePost:entry
2012-10-17 22:17:12.638811 : nsevregPrePost:normal exit
2012-10-17 22:17:12.638828 : nsevreg:sgt=0, evn=4, evt[2]=0x0
2012-10-17 22:17:12.638846 : nsevreg:begin notification process for 5
2012-10-17 22:17:12.638863 : nsevregAffectNotif:entry
2012-10-17 22:17:12.638880 : nsrah:entry
2012-10-17 22:17:12.638897 : nsrah:setting transport read mode (2)
2012-10-17 22:17:12.638916 : nttctl:entry
2012-10-17 22:17:12.638933 : nttctl:Clearing non-blocking mode
2012-10-17 22:17:12.638953 : nttctl:entry
2012-10-17 22:17:12.638971 : nttctl:Setting connection into async mode
2012-10-17 22:17:12.638991 : nsrah:normal exit
2012-10-17 22:17:12.639007 : nsevregAffectNotif:exit (0)
2012-10-17 22:17:12.639026 : nsevreg:rdm=2, sgt=0, evt[0]=0x20, [1]=0x20, [2]=0x0, nrg=0
2012-10-17 22:17:12.639043 : nsevreg:registering for 0x20
2012-10-17 22:17:12.639069 : nsiorasy:entry
2012-10-17 22:17:12.639087 : nsiorecv:entry
2012-10-17 22:17:12.639104 : nttmrd:entry
2012-10-17 22:17:12.639120 : nttrd:entry
2012-10-17 22:17:12.639154 : snttcallback:entry
2012-10-17 22:17:12.639174 : snttcallback:exit
2012-10-17 22:17:12.639195 : nttrd:socket 904 had bytes read=210
2012-10-17 22:17:12.639211 : nttrd:exit
2012-10-17 22:17:12.639228 : nsiorecv:exit (0)
2012-10-17 22:17:12.639244 : nsiorasy:exit (0)
2012-10-17 22:17:12.639260 : nsiooverflow:entry
2012-10-17 22:17:12.639276 : nsiooverflow:exit (1)
2012-10-17 22:17:12.639294 : nsevreg:normal exit
2012-10-17 22:17:12.639311 : nsglhe:exit
2012-10-17 22:17:12.639330 : nsevwait:entry
2012-10-17 22:17:12.639346 : nsevwait:4 registered connection(s)
2012-10-17 22:17:12.639364 : nsevwait:1 pre-posted event(s)
2012-10-17 22:17:12.639381 : nsevwait:waiting for transport event (1 thru 5)...
2012-10-17 22:17:12.639400 : nsevwait:0 newly-posted event(s)
2012-10-17 22:17:12.639418 : nsevwait:1 pre-posted event(s)
2012-10-17 22:17:12.639436 : nsevdansw:entry
2012-10-17 22:17:12.639453 : nsevdansw:at STAGE 5
2012-10-17 22:17:12.639471 : nsdo:entry
2012-10-17 22:17:12.639492 : nsdo:cid=5, opcode=68, *bl=2040, *what=8, uflgs=0x0, cflgs=0x3
2012-10-17 22:17:12.639512 : nsdo:rank=64, nsctxrnk=0
2012-10-17 22:17:12.639531 : nsdo:nsctx: state=14, flg=0x20004004, mvd=0
2012-10-17 22:17:12.639550 : nsdo:gtn=10, gtc=10, ptn=10, ptc=8191
2012-10-17 22:17:12.639567 : nscon:entry
2012-10-17 22:17:12.639584 : nscon:doing connect handshake...
2012-10-17 22:17:12.639601 : nscon:recving a packet
2012-10-17 22:17:12.639617 : nsiooverflow:entry
2012-10-17 22:17:12.639632 : nsiooverflow:exit (1)
2012-10-17 22:17:12.639649 : nsprecv:entry
2012-10-17 22:17:12.639666 : nsprecv:210 bytes from leftover
2012-10-17 22:17:12.639686 : nsprecv:tlen=210, plen=210, type=1
2012-10-17 22:17:12.639703 : nsprecv:packet dump
2012-10-17 22:17:12.639724 : nsprecv:00 D2 00 00 01 00 00 00 |........|
2012-10-17 22:17:12.639744 : nsprecv:01 34 01 2C 0C 01 08 00 |.4.,....|
2012-10-17 22:17:12.639763 : nsprecv:7F FF 4F 98 00 00 00 01 |..O.....|
2012-10-17 22:17:12.639782 : nsprecv:00 B0 00 22 00 00 00 00 |..."....|
2012-10-17 22:17:12.639800 : nsprecv:01 01 28 44 45 53 43 52 |..(DESCR|
2012-10-17 22:17:12.639818 : nsprecv:49 50 54 49 4F 4E 3D 28 |IPTION=(|
2012-10-17 22:17:12.639837 : nsprecv:41 44 44 52 45 53 53 5F |ADDRESS_|
2012-10-17 22:17:12.639856 : nsprecv:4C 49 53 54 3D 28 41 44 |LIST=(AD|
2012-10-17 22:17:12.639874 : nsprecv:44 52 45 53 53 3D 28 50 |DRESS=(P|
2012-10-17 22:17:12.639892 : nsprecv:52 4F 54 4F 43 4F 4C 3D |ROTOCOL=|
2012-10-17 22:17:12.639911 : nsprecv:54 43 50 29 28 48 4F 53 |TCP)(HOS|
2012-10-17 22:17:12.639930 : nsprecv:54 3D 4F 52 49 4F 4E 31 |T=ORION1|
2012-10-17 22:17:12.639948 : nsprecv:30 36 2E 69 6E 74 65 72 |06.inter|
2012-10-17 22:17:12.639967 : nsprecv:63 61 72 65 2E 63 6F 2E |care.co.|
2012-10-17 22:17:12.639985 : nsprecv:61 65 29 28 50 4F 52 54 |ae)(PORT|
2012-10-17 22:17:12.640004 : nsprecv:3D 31 35 32 31 29 29 29 |=1521)))|
2012-10-17 22:17:12.640022 : nsprecv:28 43 4F 4E 4E 45 43 54 |(CONNECT|
2012-10-17 22:17:12.640040 : nsprecv:5F 44 41 54 41 3D 28 43 |_DATA=(C|
2012-10-17 22:17:12.640059 : nsprecv:49 44 3D 28 50 52 4F 47 |ID=(PROG|
2012-10-17 22:17:12.640077 : nsprecv:52 41 4D 3D 29 28 48 4F |RAM=)(HO|
2012-10-17 22:17:12.640096 : nsprecv:53 54 3D 5F 5F 6A 64 62 |ST=__jdb|
2012-10-17 22:17:12.640114 : nsprecv:63 5F 5F 29 28 55 53 45 |c__)(USE|
2012-10-17 22:17:12.640133 : nsprecv:52 3D 4F 52 49 4F 4E 31 |R=ORION1|
2012-10-17 22:17:12.640151 : nsprecv:30 36 24 29 29 28 53 45 |06$))(SE|
2012-10-17 22:17:12.640170 : nsprecv:52 56 49 43 45 5F 4E 41 |RVICE_NA|
2012-10-17 22:17:12.640188 : nsprecv:4D 45 3D 6F 72 63 6C 29 |ME=orcl)|
2012-10-17 22:17:12.640207 : nsprecv:29 29 |)) |
2012-10-17 22:17:12.640224 : nsprecv:normal exit
2012-10-17 22:17:12.640241 : nscon:got NSPTCN packet
2012-10-17 22:17:12.640258 : nsconneg:entry
2012-10-17 22:17:12.640276 : nsconneg:vsn=308, lov=300, opt=0xc01, sdu=2048, tdu=32767, ntc=0x4f98
2012-10-17 22:17:12.640297 : nsconneg:vsn=308, gbl=0x801, sdu=2048, tdu=32767
2012-10-17 22:17:12.640313 : nsconneg:normal exit
2012-10-17 22:17:12.640330 : nscpxget:entry
2012-10-17 22:17:12.640345 : nscpxget:normal exit
2012-10-17 22:17:12.640363 : nscon:got 176 bytes connect data
2012-10-17 22:17:12.640380 : nscon:exit (0)
2012-10-17 22:17:12.640396 : nsdo:nsctxrnk=0
2012-10-17 22:17:12.640412 : nsdo:normal exit
2012-10-17 22:17:12.640429 : nsevdrcvreq:entry
2012-10-17 22:17:12.640451 : nsevdansw:exit
2012-10-17 22:17:12.640468 : nsevrec:event is 0x20, on 5
2012-10-17 22:17:12.640487 : nstoToqWalk:entry
2012-10-17 22:17:12.640503 : nstoToqWalk:exit (0)
2012-10-17 22:17:12.640519 : nsevwait:1 posted event(s)
2012-10-17 22:17:12.640534 : nsevwait:exit (0)
2012-10-17 22:17:12.640561 : nsglhe:entry
2012-10-17 22:17:12.640578 : nsglhe:Event on cxd 0x62da3c0.
2012-10-17 22:17:12.640615 : nsglfc:Assume establishing a connection...
2012-10-17 22:17:12.640633 : nsglfc:command = establish
2012-10-17 22:17:12.640650 : nsglauthorized:entry
2012-10-17 22:17:12.640669 : nsglauthorized:Determining auth method...
2012-10-17 22:17:12.640689 : nsglauthorized:No authorization needed.
2012-10-17 22:17:12.640706 : nsglecmd:entry
2012-10-17 22:17:12.640723 : nscontrol:entry
2012-10-17 22:17:12.640740 : nstoControlATO:entry
2012-10-17 22:17:12.640757 : nstoClearTimeout:entry
2012-10-17 22:17:12.640775 : nstoClearTimeout:ATO disabled for ctx=0x0000000005F2E7F0
2012-10-17 22:17:12.640791 : nstoUpdateActive:entry
2012-10-17 22:17:12.640807 : nstoUpdateActive:Active timeout is -1 (see nstotyp)
2012-10-17 22:17:12.640827 : nstoControlATO:ATO disabled for ctx=0x0000000005F2E7F0
2012-10-17 22:17:12.640843 : nstoControlATO:exit (0)
2012-10-17 22:17:12.640859 : nscontrol:cmd=26, lcl=0x0
2012-10-17 22:17:12.640875 : nscontrol:normal exit
2012-10-17 22:17:12.640907 : nttaddr2bnd:entry
2012-10-17 22:17:12.640924 : snlinGetNameInfo:entry
2012-10-17 22:17:12.640946 : snlinGetNameInfo:exit
2012-10-17 22:17:12.640964 : nttaddr2bnd:Resolved to 200.200.210.101
2012-10-17 22:17:12.640985 : nttaddr2bnd:exit
2012-10-17 22:17:12.641012 : nsglbgetRSPidx:entry
2012-10-17 22:17:12.641048 : nsglbgetRSPidx:returning ecode=0
2012-10-17 22:17:12.641065 : nsglbgetRSPidx:exit
2012-10-17 22:17:12.641082 : nsgettrans_bycxdwattr:entry
2012-10-17 22:17:12.641100 : ntgettrans:entry
2012-10-17 22:17:12.641116 : ntgettrans:exit
2012-10-17 22:17:12.641132 : nsgettrans_bycxdwattr:exit
2012-10-17 22:17:12.641149 : nsglbgetSdPidx:secondary protocol=4
2012-10-17 22:17:12.641166 : nsglb:entry
2012-10-17 22:17:12.641185 : nsglb:exit
2012-10-17 22:17:12.641202 : nsbequeath:entry
2012-10-17 22:17:12.641218 : nsc2addr:entry
2012-10-17 22:17:12.641236 :
nsc2addr:(ADDRESS=(PROTOCOL=beq)(PROGRAM=oracle)(ENVS='ORACLE_HOME=D:\Ora11gdb\dbhome_1,ORACLE_SID=orcl')(ARGV0=oracleorcl)(A
RGS='(LOCAL=NO)'))
2012-10-17 22:17:12.641271 : nlpcaini:entry
2012-10-17 22:17:12.641338 : nlpcaini:prg = oracle
2012-10-17 22:17:12.641357 : nlpcaini:arg[0] = oracleorcl
2012-10-17 22:17:12.641373 : nlpcaini:arg[1] = (LOCAL=NO)
2012-10-17 22:17:12.641390 : nlpcaini:env[0] = ALLUSERSPROFILE=C:\ProgramData
2012-10-17 22:17:12.641407 : nlpcaini:exit
2012-10-17 22:17:12.641424 : nsc2addr:normal exit
2012-10-17 22:17:12.641440 : nsbeqaddr:entry
2012-10-17 22:17:12.641456 : nsbeqaddr:connecting...
2012-10-17 22:17:12.641472 : nsopen:entry
2012-10-17 22:17:12.641487 : nsmal:entry
2012-10-17 22:17:12.641506 : nsmal:1496 bytes at 0x6025010
2012-10-17 22:17:12.641521 : nsmal:normal exit
2012-10-17 22:17:12.641537 : nsopenmplx:entry
2012-10-17 22:17:12.641552 : nsmal:entry
2012-10-17 22:17:12.641570 : nsmal:2944 bytes at 0x60255f0
2012-10-17 22:17:12.641585 : nsmal:normal exit
2012-10-17 22:17:12.641600 : nsiorini:entry
2012-10-17 22:17:12.641616 : nsbal:entry
2012-10-17 22:17:12.641631 : nsbgetfl:entry
2012-10-17 22:17:12.641646 : nsbgetfl:normal exit
2012-10-17 22:17:12.641661 : nsbal:normal exit
2012-10-17 22:17:12.641677 : nsiorini:exit (0)
2012-10-17 22:17:12.641693 : nscpxget:entry
2012-10-17 22:17:12.641707 : nscpxget:normal exit
2012-10-17 22:17:12.641724 : nsopenalloc_nsntx:nlhthput on mplx_ht_nsgbu:ctx=6025010, nsntx=60255f0
2012-10-17 22:17:12.641742 : nsopenmplx:normal exit
2012-10-17 22:17:12.641760 : ntpcon:entry
2012-10-17 22:17:12.641775 : ntpcon:toc = 6
2012-10-17 22:17:12.641790 : ntpcon:exit
2012-10-17 22:17:12.641806 : nsopen:opening transport...
2012-10-17 22:17:12.641823 : ntpcon:entry
2012-10-17 22:17:12.641837 : ntpcon:toc = 1
2012-10-17 22:17:12.641857 : sntpcall:entry
2012-10-17 22:17:12.641874 : snlpcss:entry
2012-10-17 22:17:12.644127 : snlpcss:Spawn Oracle completed oracle (LOCAL=NO) orcl.
2012-10-17 22:17:12.644233 : snlpcss:exit
2012-10-17 22:17:12.644337 : sntpcall:Attempting to open pipe \\.\PIPE\ORANTP874.1878
2012-10-17 22:17:12.653334 : sntpcall:Successfully established pipe 808 to child with 0 retries.
2012-10-17 22:17:12.653373 : sntpcall:Attempting to open pipe \\.\PIPE\ORANTP874.1878.w
2012-10-17 22:17:12.653437 : sntpcall:Successfully established pipe 920 to child with 0 retries.
2012-10-17 22:17:12.653475 : sntpcall:exit
2012-10-17 22:17:12.653500 : ntpcon:NT layer IPC connection has been established.
2012-10-17 22:17:12.653519 : ntpcon:exit
2012-10-17 22:17:12.653538 : nsopen:transport is open
2012-10-17 22:17:12.653558 : nsoptions:entry
2012-10-17 22:17:12.653579 : nsoptions:lcl[0]=0x0, lcl[1]=0x2006, gbl[0]=0x0, gbl[1]=0x0, cha=0x0
2012-10-17 22:17:12.653601 : nsoptions:Vectored IO not supported.
2012-10-17 22:17:12.653623 : nsoptions:lcl[0]=0xf4ffe9ff, lcl[1]=0x6016, gbl[0]=0xe881, gbl[1]=0x0
2012-10-17 22:17:12.653642 : nsoptions:normal exit
2012-10-17 22:17:12.653659 : nsnainit:entry
2012-10-17 22:17:12.653678 : nsnainit:normal exit
2012-10-17 22:17:12.653698 : nsopen:global context check-in (to slot 6) complete
2012-10-17 22:17:12.653722 : nsopen:lcl[0]=0xf4ffe9ff, lcl[1]=0x6016, gbl[0]=0xe881, gbl[1]=0x0, tdu=4096, sdu=8192
2012-10-17 22:17:12.653742 : nsfull_opn:entry
2012-10-17 22:17:12.653762 : nsfull_opn:cid=6, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x0
2012-10-17 22:17:12.653782 : nsfull_opn:nsctx: state=7, flg=0x4001, mvd=0
2012-10-17 22:17:12.653801 : nsfull_opn:normal exit
2012-10-17 22:17:12.653818 : nsopen:normal exit
2012-10-17 22:17:12.653914 : nttaddr2bnd:entry
2012-10-17 22:17:12.653942 : snlinGetNameInfo:entry
2012-10-17 22:17:12.653969 : snlinGetNameInfo:exit
2012-10-17 22:17:12.653988 : nttaddr2bnd:Resolved to 200.200.210.101
2012-10-17 22:17:12.654010 : nttaddr2bnd:exit
2012-10-17 22:17:12.654032 : nsbequeath_stg2:doing connect handshake...
2012-10-17 22:17:12.654053 : nsbequeath:doing connect handshake...
2012-10-17 22:17:12.654071 : ntpwr:entry
2012-10-17 22:17:12.654089 : sntpwrite:entry
2012-10-17 22:17:12.654109 : sntpwrite:Attempting to write 4 bytes to handle 808
2012-10-17 22:17:12.654138 : sntpwrite:WriteFile returned 4 bytes
2012-10-17 22:17:12.654157 : sntpwrite:exit
2012-10-17 22:17:12.654175 : ntpwr:exit
2012-10-17 22:17:12.654191 : ntpwr:entry
2012-10-17 22:17:12.654208 : sntpwrite:entry
2012-10-17 22:17:12.654226 : sntpwrite:Attempting to write 66 bytes to handle 808
2012-10-17 22:17:12.654253 : sntpwrite:WriteFile returned 66 bytes
2012-10-17 22:17:12.654271 : sntpwrite:exit
2012-10-17 22:17:12.654287 : ntpwr:exit
2012-10-17 22:17:12.654304 : ntpwr:entry
2012-10-17 22:17:12.654320 : sntpwrite:entry
2012-10-17 22:17:12.654338 : sntpwrite:Attempting to write 8 bytes to handle 808
2012-10-17 22:17:12.654362 : sntpwrite:WriteFile returned 8 bytes
2012-10-17 22:17:12.654381 : sntpwrite:exit
2012-10-17 22:17:12.654396 : ntpwr:exit
2012-10-17 22:17:12.654414 : ntprd:entry
2012-10-17 22:17:12.654432 : sntpread:entry
2012-10-17 22:17:12.654450 : sntpread:Attempting to read 4 bytes from handle 920
2012-10-17 22:17:12.655026 : sntpread:ReadFile returned 4 bytes
2012-10-17 22:17:12.655049 : sntpread:rc = 0, ntresnt[0] = 0
2012-10-17 22:17:12.655067 : sntpread:exit
2012-10-17 22:17:12.655084 : ntprd:exit
2012-10-17 22:17:12.655101 : ntprd:entry
2012-10-17 22:17:12.655117 : sntpread:entry
2012-10-17 22:17:12.655136 : sntpread:Attempting to read 4 bytes from handle 920
2012-10-17 22:17:12.655314 : sntpread:ReadFile returned 4 bytes
2012-10-17 22:17:12.655337 : sntpread:rc = 0, ntresnt[0] = 0
2012-10-17 22:17:12.655354 : sntpread:exit
2012-10-17 22:17:12.655370 : ntprd:exit
2012-10-17 22:17:12.655388 : nsbequeath:NSE=12586
2012-10-17 22:17:12.655407 : nsbequeath:error reading REDIR/NSE msg
2012-10-17 22:17:12.655427 : nserror:entry
2012-10-17 22:17:12.655451 : nserror:nsres: id=5, op=72, ns=12586, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0,
ora[2]=0
2012-10-17 22:17:12.655472 : nsdo:entry
2012-10-17 22:17:12.655491 : nsdo:cid=5, opcode=67, *bl=0, *what=13, uflgs=0x0, cflgs=0x3
2012-10-17 22:17:12.655511 : nsdo:rank=64, nsctxrnk=0
2012-10-17 22:17:12.655530 : nsdo:nsctx: state=2, flg=0x20004004, mvd=0
2012-10-17 22:17:12.655556 : nsdo:gtn=210, gtc=210, ptn=10, ptc=2047
2012-10-17 22:17:12.655578 : nscon:entry
2012-10-17 22:17:12.655597 : nscon:sending NSPTRS packet
2012-10-17 22:17:12.655618 : nspsend:entry
2012-10-17 22:17:12.655641 : nspsend:plen=8, type=11
:
:
{code}
Thanks,
Anand.