Re: SQLPlus Hangs

On Dec 26, 5:38 am, raghu <raghu_v..._at_yahoo.com> wrote:
> When I enter the credentials in SQL Plus, it hangs. This  happens both
> in the server machine (Oracle 10.2.0) and the clients. But I am able
> to login using the command prompt in the server. Tnsping works
> correctly. Nothing is logged in the alert log for the login attempt.
> Any ideas?
>
> Here is an excerpt of the alert log:
>
> Starting background process EMN0
> EMN0 started with pid=134, OS id=3648
> Wed Dec 26 11:56:33 2007
> Shutting down instance: further logons disabled
> Wed Dec 26 11:56:33 2007
> Stopping background process QMNC
> Wed Dec 26 11:56:34 2007
> Stopping background process CJQ0
> Wed Dec 26 11:56:34 2007
> Background process QMNC not dead after 150 seconds
> Wed Dec 26 11:56:34 2007
> Killing background process QMNC
> Wed Dec 26 11:56:34 2007
> Stopping background process MMNL
> Wed Dec 26 11:56:36 2007
> Background process MMNL not dead after 10 seconds
> Wed Dec 26 11:56:36 2007
> Killing background process MMNL
> Wed Dec 26 11:56:36 2007
> Stopping background process MMON
> Wed Dec 26 11:56:37 2007
> Background process MMON not dead after 30 seconds
> Wed Dec 26 11:56:37 2007
> Killing background process MMON
> Wed Dec 26 11:56:37 2007
> Shutting down instance (immediate)
> License high water mark = 5
> Wed Dec 26 11:56:37 2007
> Stopping Job queue slave processes
> Wed Dec 26 11:56:37 2007
> Job queue slave processes stopped
> All dispatchers and shared servers shutdown
> Wed Dec 26 11:56:44 2007
> ALTER DATABASE CLOSE NORMAL
> Wed Dec 26 11:56:44 2007
> SMON: disabling tx recovery
> SMON: disabling cache recovery
> Wed Dec 26 11:56:44 2007
> SUCCESS: diskgroup ORAREDO was dismounted
> Shutting down archive processes
> Archiving is disabled
> Wed Dec 26 11:56:49 2007
> ARCH shutting down
> ARC1: Archival stopped
> Wed Dec 26 11:56:54 2007
> ARCH shutting down
> ARC0: Archival stopped
> Wed Dec 26 11:56:55 2007
> Thread 1 closed at log sequence 15521
> Successful close of redo thread 1
> Wed Dec 26 11:56:59 2007
> Completed: ALTER DATABASE CLOSE NORMAL
> Wed Dec 26 11:56:59 2007
> ALTER DATABASE DISMOUNT
> Wed Dec 26 11:56:59 2007
> SUCCESS: diskgroup ORADATA was dismounted
> SUCCESS: diskgroup ORABACKUP was dismounted
> Wed Dec 26 11:56:59 2007
> Completed: ALTER DATABASE DISMOUNT
> ARCH: Archival disabled due to shutdown: 1089
> Shutting down archive processes
> Archiving is disabled
> Archive process shutdown avoided: 0 active
> ARCH: Archival disabled due to shutdown: 1089
> Shutting down archive processes
> Archiving is disabled
> Archive process shutdown avoided: 0 active
> Wed Dec 26 11:57:05 2007
> freeing rdom 0
> Wed Dec 26 11:58:31 2007
> Starting ORACLE instance (normal)
> LICENSE_MAX_SESSION = 0
> LICENSE_SESSIONS_WARNING = 0
> Interface type 1 Private 192.168.70.0 configured from OCR for use as a
> cluster interconnect
> Interface type 1 Public 10.45.5.0 configured from OCR for use as  a
> public interface
> Picked latch-free SCN scheme 3
> Autotune of undo retention is turned on.
> LICENSE_MAX_USERS = 0
> SYS auditing is disabled
> ksdpec: called for event 13740 prior to event group initialization
> Starting up ORACLE RDBMS Version: 10.2.0.2.0.
> System parameters with non-default values:
>   processes                = 500
>   sessions                 = 555
>   __shared_pool_size       = 1711276032
>   __large_pool_size        = 0
>   __java_pool_size         = 16777216
>   __streams_pool_size      = 0
>   trace_enabled            = FALSE
>   nls_language             = AMERICAN
>   nls_territory            = UNITED KINGDOM
>   sga_target               = 12884901888
>   control_files            = +ORADATA/edwprd/controlfile/current.
> 256.620240201, +ORABACKUP/edwprd/controlfile/current.256.620240201
>   db_block_size            = 16384
>   __db_cache_size          = 11140071424
>   db_writer_processes      = 8
>   compatible               = 10.2.0.2.0
>   log_archive_dest_1       = LOCATION=+ORABACKUP/EDWPRD/
>   log_archive_format       = ARC%S_%R.%T
>   db_file_multiblock_read_count= 16
>   cluster_database         = TRUE
>   cluster_database_instances= 2
>   db_create_file_dest      = +ORADATA
>   db_recovery_file_dest    = +ORABACKUP
>   db_recovery_file_dest_size= 10737418240
>   thread                   = 1
>   instance_number          = 1
>   undo_management          = AUTO
>   undo_tablespace          = UNDOTBS1
>   remote_login_passwordfile= EXCLUSIVE
>   db_domain                =
>   dispatchers              = (PROTOCOL=TCP) (SERVICE=EDWPRDXDB)
>   remote_listener          = LISTENERS_EDWPRD
>   job_queue_processes      = 10
>   audit_file_dest          = D:\ORACLE\PRODUCT\10.2.0\ADMIN\EDWPRD
> \ADUMP
>   background_dump_dest     = D:\ORACLE\PRODUCT\10.2.0\ADMIN\EDWPRD
> \BDUMP
>   user_dump_dest           = D:\ORACLE\PRODUCT\10.2.0\ADMIN\EDWPRD
> \UDUMP
>   max_dump_file_size       = 1024
>   core_dump_dest           = D:\ORACLE\PRODUCT\10.2.0\ADMIN\EDWPRD
> \CDUMP
>   db_name                  = EDWPRD
>   open_cursors             = 300
>   optimizer_mode           = choose
>   pga_aggregate_target     = 1707081728
> Cluster communication is configured to use the following interface(s)
> for this instance
>   192.168.70.11
> Wed Dec 26 11:58:37 2007
> cluster interconnect IPC version:Oracle 9i Winsock2 TCP/IP IPC
> IPC Vendor 0 proto 0
>   Version 0.0
> PMON started with pid=2, OS id=7116
> DIAG started with pid=6, OS id=6880
> PSP0 started with pid=10, OS id=6476
> LMON started with pid=14, OS id=6856
> Wed Dec 26 11:58:39 2007
> ORA-00130: invalid listener address '(ADDRESS=(PROTOCOL=TCP)
> (HOST=BRNORA62-vip)(PORT=1521))'
>
> LMD0 started with pid=18, OS id=7016
> LMS0 started with pid=22, OS id=6728
> LMS1 started with pid=26, OS id=4036
> MMAN started with pid=30, OS id=6204
> DBW0 started with pid=34, OS id=448
> DBW1 started with pid=38, OS id=5492
> DBW2 started with pid=42, OS id=4436
> DBW3 started with pid=46, OS id=5960
> DBW4 started with pid=50, OS id=6324
> DBW5 started with pid=54, OS id=5700
> DBW6 started with pid=58, OS id=2828
> DBW7 started with pid=62, OS id=4612
> LGWR started with pid=66, OS id=3952
> CKPT started with pid=70, OS id=1572
> SMON started with pid=74, OS id=6288
> RECO started with pid=78, OS id=5860
> CJQ0 started with pid=82, OS id=6672
> MMON started with pid=86, OS id=5288
> MMNL started with pid=90, OS id=6976
> Wed Dec 26 11:58:39 2007
> starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)
> (PROTOCOL=TCP))'...
> starting up 1 shared server(s) ...
> Wed Dec 26 11:58:39 2007
> lmon registered with NM - instance id 1 (internal mem no 0)
> Wed Dec 26 11:58:41 2007
> Reconfiguration started (old inc 0, new inc 2)
> List of nodes:
>  0
>  Global Resource Directory frozen
> * allocate domain 0, invalid = TRUE
>  Communication channels reestablished
>  Master broadcasted resource hash value bitmaps
>  Non-local Process blocks cleaned out
> Wed Dec 26 11:58:41 2007
>  LMS 1: 0 GCS shadows cancelled, 0 closed
> Wed Dec 26 11:58:42 2007
>  LMS 0: 0 GCS shadows cancelled, 0 closed
>  Set master node info
>  Submitted all remote-enqueue requests
>  Dwn-cvts replayed, VALBLKs dubious
>  All grantable enqueues granted
>  Post SMON to start 1st pass IR
> Wed Dec 26 11:58:42 2007
>  LMS 0: 0 GCS shadows traversed, 0 replayed
> Wed Dec 26 11:58:42 2007
>  LMS 1: 0 GCS shadows traversed, 0 replayed
> Wed Dec 26 11:58:42 2007
>  Submitted all GCS remote-cache requests
>  Post SMON to start 1st pass IR
>  Fix write in gcs resources
> Reconfiguration complete
> LCK0 started with pid=102, OS id=1876
> Wed Dec 26 11:58:43 2007
> ALTER DATABASE   MOUNT
> Wed Dec 26 11:58:43 2007
> This instance was first to mount
> Wed Dec 26 11:58:43 2007
> Starting background process ASMB
> ASMB started with pid=110, OS id=5428
> Starting background process RBAL
> RBAL started with pid=114, OS id=4344
> Wed Dec 26 11:58:48 2007
> SUCCESS: diskgroup ORADATA was mounted
> SUCCESS: diskgroup ORABACKUP was mounted
> Wed Dec 26 11:58:52 2007
> Setting recovery target incarnation to 1
> Wed Dec 26 11:58:52 2007
> Successful mount of redo thread 1, with mount id 606843251
> Wed Dec 26 11:58:52 2007
> Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE)
> Completed: ALTER DATABASE   MOUNT
> Wed Dec 26 11:58:52 2007
> ALTER DATABASE OPEN
> This instance was first to open
> Picked broadcast on commit scheme to generate SCNs
> Wed Dec 26 11:58:53 2007
> LGWR: STARTING ARCH PROCESSES
> ARC0 started with pid=134, OS id=4724
> Wed Dec 26 11:58:53 2007
> ARC0: Archival started
> ARC1 started with pid=138, OS id=4700
> Wed Dec 26 11:58:53 2007
> ARC1: Archival started
> LGWR: STARTING ARCH PROCESSES COMPLETE
> SUCCESS: diskgroup ORAREDO was mounted
> Thread 1 opened at log sequence 15521
>   Current log# 6 seq# 15521 mem# 0: +ORAREDO/edwprd/onlinelog/
> group_6.257.630862051
>   Current log# 6 seq# 15521 mem# 1: +ORAREDO/edwprd/onlinelog/
> group_6.256.630862053
> Successful open of redo thread 1
> Wed Dec 26 11:58:53 2007
> MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
> Wed Dec 26 11:58:53 2007
> ARC1: STARTING ARCH PROCESSES
> Wed Dec 26 11:58:53 2007
> ARC0: Becoming the 'no FAL' ARCH
> ARC0: Becoming the 'no SRL' ARCH
> Wed Dec 26 11:58:53 2007
> ARC2: Archival started
> ARC2 started with pid=142, OS id=4256
> Wed Dec 26 11:58:53 2007
> SMON: enabling cache recovery
> Wed Dec 26 11:58:53 2007
> ARC1: STARTING ARCH PROCESSES COMPLETE
> ARC1: Becoming the heartbeat ARCH
> Wed Dec 26 11:58:54 2007
> Successfully onlined Undo Tablespace 1.
> Wed Dec 26 11:58:54 2007
> SMON: enabling tx recovery
> Wed Dec 26 11:58:54 2007
> Database Characterset is WE8MSWIN1252
> Wed Dec 26 11:58:54 2007
> Instance recovery: looking for dead threads
> Instance recovery: lock domain invalid but no dead threads
> Wed Dec 26 11:58:54 2007
> replication_dependency_tracking turned off (no async multimaster
> replication found)
> Starting background process QMNC
> QMNC started with pid=146, OS id=4912
> Wed Dec 26 11:58:58 2007
> Completed: ALTER DATABASE OPEN
> Wed Dec 26 11:58:58 2007
> db_recovery_file_dest_size of 10240 MB is 0.21% used. This is a
> user-specified limit on the amount of space that will be used by this
> database for recovery-related files, and does not reflect the amount
> of
> space available in the underlying filesystem or ASM diskgroup.
> Wed Dec 26 11:59:53 2007
> Shutting down archive processes
> Wed Dec 26 11:59:58 2007
> ARCH shutting down
> ARC2: Archival stopped

The alert log won't usually help you troubleshoot connection issues; sqlnet tracing/logging and the listener.log might. I'd look at the listener.log and see if tracing the connection attempt through sqlnet can pinpoint the problem.

David Fitzjarrell Received on Wed Dec 26 2007 - 08:31:56 CST