This discussion is archived
4 Replies Latest reply: Jan 31, 2013 4:31 PM by SMEC_Matt RSS

Managed Server stuck in starting

SMEC_Matt Newbie
Currently Being Moderated
Hi every, thank you for reading.
We have a Oracle SOA domain running on WLS 10.3.6. The OS is windows server 2003.
Adminserver and soa_server1 are on vmmachine1.
proxy server and soa_server2 are on vmmachine2.
soa_server1 and soa_server2 are in a cluster.

This domain has been working normally for serveral months. Managed server is controlled by nodemanager.

Yesterday, we increased the memory of vmmachine1 and vmmachine2 from 8g to 16g.
After that, soa_server2 cannot be started while other managed server of the domain starts normally.

I looked into the soa_server2.log and found that the log stucks at "<Notice> <Log Management> <BEA-170019> <The server log file C:\Oracle\Middleware\user_projects\domains\ctst_soa_domain\servers\soa_server2\logs\soa_server2.log is opened. All server side log events will be written to this file.> " forever.

The task manager shows that the memory of java.exe process of the stucked managed server is about 350m and at an increase rate of about 4k.
The cpu consumption of the process is 0 percent.

Below is part of JRockit Mission Control fly record event of the stucked JVM:

1,359,447,962,480,625,883     4,453,053,500     weblogic.timers.TimerThread     Java Wait
1,359,447,962,480,688,068     4,453,037,334     [ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'     Java Wait
1,359,447,962,558,579,199     109,474,384     VDE Transaction Processor Thread     Java Wait
1,359,447,962,564,083,662     869,606,634     RMI TCP Connection(26)-192.9.200.148     Socket Read
1,359,447,962,668,068,530     109,075,316     VDE Transaction Processor Thread     Java Wait
1,359,447,962,777,159,184     109,367,902     VDE Transaction Processor Thread     Java Wait
1,359,447,962,886,542,218     109,638,015     VDE Transaction Processor Thread     Java Wait
1,359,447,962,996,257,842     109,285,831     VDE Transaction Processor Thread     Java Wait
1,359,447,963,105,558,278     109,143,508     VDE Transaction Processor Thread     Java Wait
1,359,447,963,214,709,536     109,312,043     VDE Transaction Processor Thread     Java Wait
1,359,447,963,324,052,457     109,455,297     VDE Transaction Processor Thread     Java Wait
1,359,447,963,433,516,028     109,259,502     VDE Transaction Processor Thread     Java Wait
1,359,447,963,433,924,695     93,414,304     RMI TCP Connection(26)-192.9.200.148     Socket Read
1,359,447,963,527,635,047     2,515,422,874     RMI TCP Connection(26)-192.9.200.148     Socket Read
1,359,447,963,542,789,729     152,068,282     VDE Transaction Processor Thread     Java Wait
1,359,447,963,694,879,147     113,581,233     VDE Transaction Processor Thread     Java Wait
1,359,447,963,697,060,581     1,002,528,122     RMI TCP Connection(idle)     Socket Read
1,359,447,963,808,488,263     109,555,192     VDE Transaction Processor Thread     Java Wait
1,359,447,963,918,076,105     109,076,613     VDE Transaction Processor Thread     Java Wait
1,359,447,964,027,167,650     109,358,282     VDE Transaction Processor Thread     Java Wait
1,359,447,964,136,541,541     109,442,748     VDE Transaction Processor Thread     Java Wait
1,359,447,964,245,999,192     109,830,184     VDE Transaction Processor Thread     Java Wait
1,359,447,964,324,342,462     2,015,390,696     Timer-1     Java Wait
1,359,447,964,355,844,714     108,827,865     VDE Transaction Processor Thread     Java Wait
1,359,447,964,464,687,365     109,297,368     VDE Transaction Processor Thread     Java Wait
1,359,447,964,574,003,355     109,396,656     VDE Transaction Processor Thread     Java Wait
1,359,447,964,683,418,068     109,366,571     VDE Transaction Processor Thread     Java Wait
1,359,447,964,705,600,116     743,862,091     RMI TCP Connection(idle)     Socket Read
1,359,447,964,792,799,741     109,347,456     VDE Transaction Processor Thread     Java Wait
1,359,447,964,902,156,236     109,395,625     VDE Transaction Processor Thread     Java Wait
1,359,447,965,011,567,244     109,331,778     VDE Transaction Processor Thread     Java Wait
1,359,447,965,120,914,342     109,367,906     VDE Transaction Processor Thread     Java Wait
1,359,447,965,230,297,996     109,602,297     VDE Transaction Processor Thread     Java Wait
1,359,447,965,339,915,098     109,369,203     VDE Transaction Processor Thread     Java Wait
1,359,447,965,449,297,323     109,126,121     VDE Transaction Processor Thread     Java Wait
1,359,447,965,449,946,395     265,099,402     RMI TCP Connection(idle)     Socket Read
1,359,447,965,558,468,725     109,441,305     VDE Transaction Processor Thread     Java Wait
1,359,447,965,667,925,444     109,229,624     VDE Transaction Processor Thread     Java Wait
1,359,447,965,720,533,365     322,363,229     RMI TCP Connection(idle)     Socket Read
1,359,447,965,777,169,428     109,580,914     VDE Transaction Processor Thread     Java Wait
1,359,447,965,886,766,019     109,140,868     VDE Transaction Processor Thread     Java Wait

Any help is welcome.
  • 1. Re: Managed Server stuck in starting
    729470 Newbie
    Currently Being Moderated
    Thread Dump:

    "Main Thread" id=1 idx=0x4 tid=1728 prio=5 alive, waiting, native_blocked
    -- Waiting for notification on: weblogic/t3/srvr/SubsystemRequest@0x00000001
    82879510[fat lock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at weblogic/t3/srvr/SubsystemRequest.rendezvouz(SubsystemRequest.java:100)
    ^-- Lock released while waiting: weblogic/t3/srvr/SubsystemRequest@0x0000000
    182879510[fat lock]
    at weblogic/t3/srvr/SubsystemRequest.action(SubsystemRequest.java:81)
    at weblogic/t3/srvr/SubsystemRequest.start(SubsystemRequest.java:51)
    at weblogic/t3/srvr/ServerServicesManager.startService(ServerServicesManager
    .java:459)
    at weblogic/t3/srvr/ServerServicesManager.startInStandbyState(ServerServices
    Manager.java:166)
    ^-- Holding lock: java/lang/Class@0x0000000182852658[biased lock]
    at weblogic/t3/srvr/T3Srvr.initializeStandby(T3Srvr.java:881)
    at weblogic/t3/srvr/T3Srvr.startup(T3Srvr.java:568)
    at weblogic/t3/srvr/T3Srvr.run(T3Srvr.java:469)
    at weblogic/Server.main(Server.java:71)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "(Signal Handler)" id=2 idx=0x8 tid=4040 prio=5 alive, daemon

    "(OC Main Thread)" id=3 idx=0xc tid=2300 prio=5 alive, native_waiting, daemon

    "(GC Worker Thread 1)" id=? idx=0x10 tid=220 prio=5 alive, daemon

    "(GC Worker Thread 2)" id=? idx=0x14 tid=2056 prio=5 alive, daemon

    "(GC Worker Thread 3)" id=? idx=0x18 tid=1096 prio=5 alive, daemon

    "(GC Worker Thread 4)" id=? idx=0x1c tid=2580 prio=5 alive, daemon

    "(Code Generation Thread 1)" id=4 idx=0x20 tid=3404 prio=5 alive, native_waiting
    , daemon

    "(Code Optimization Thread 1)" id=5 idx=0x24 tid=3228 prio=5 alive, native_waiti
    ng, daemon

    "(VM Periodic Task)" id=6 idx=0x28 tid=1564 prio=10 alive, native_blocked, daemo
    n

    "(Attach Listener)" id=7 idx=0x2c tid=640 prio=5 alive, native_blocked, daemon

    "Finalizer" id=8 idx=0x30 tid=248 prio=8 alive, native_waiting, daemon
    at jrockit/memory/Finalizer.waitForFinalizees(J[Ljava/lang/Object;)I(Native
    Method)
    at jrockit/memory/Finalizer.access$700(Finalizer.java:12)
    at jrockit/memory/Finalizer$4.run(Finalizer.java:183)
    at java/lang/Thread.run(Thread.java:662)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "Reference Handler" id=9 idx=0x34 tid=2092 prio=10 alive, native_waiting, daemon

    at java/lang/ref/Reference.waitForActivatedQueue(J)Ljava/lang/ref/Reference;
    (Native Method)
    at java/lang/ref/Reference.access$100(Reference.java:11)
    at java/lang/ref/Reference$ReferenceHandler.run(Reference.java:82)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "(Sensor Event Thread)" id=10 idx=0x38 tid=3548 prio=5 alive, native_blocked, da
    emon

    "VM JFR Buffer Thread" id=11 idx=0x3c tid=3768 prio=5 alive, in native, daemon

    "Timer-0" id=14 idx=0x40 tid=3800 prio=5 alive, waiting, native_blocked, daemon
    -- Waiting for notification on: java/util/TaskQueue@0x000000018238DF88[fat l
    ock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at java/lang/Object.wait(Object.java:485)
    at java/util/TimerThread.mainLoop(Timer.java:483)
    ^-- Lock released while waiting: java/util/TaskQueue@0x000000018238DF88[fat
    lock]
    at java/util/TimerThread.run(Timer.java:462)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "Timer-1" id=15 idx=0x44 tid=1572 prio=5 alive, waiting, native_blocked, daemon
    -- Waiting for notification on: java/util/TaskQueue@0x0000000185AC9490[fat l
    ock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at java/util/TimerThread.mainLoop(Timer.java:509)
    ^-- Lock released while waiting: java/util/TaskQueue@0x0000000185AC9490[fat
    lock]
    at java/util/TimerThread.run(Timer.java:462)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'"
    id=16 idx=0x48 tid=3360 prio=5 alive, waiting, native_blocked, daemon
    -- Waiting for notification on: com/octetstring/vde/backend/standard/Transac
    tionProcessor@0x000000018A83F800[fat lock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at java/lang/Object.wait(Object.java:485)
    at com/octetstring/vde/backend/standard/TransactionProcessor.waitTransaction
    sCompleted(TransactionProcessor.java:353)
    ^-- Lock released while waiting: com/octetstring/vde/backend/standard/Transa
    ctionProcessor@0x000000018A83F800[fat lock]
    at com/octetstring/vde/backend/standard/BackendStandard.<init>(BackendStanda
    rd.java:275)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    at jrockit/vm/Reflect.invokeMethod(Ljava/lang/Object;Ljava/lang/Object;[Ljav
    a/lang/Object;)Ljava/lang/Object;(Native Method)
    at sun/reflect/NativeConstructorAccessorImpl.newInstance0(Ljava/lang/reflect
    /Constructor;[Ljava/lang/Object;)Ljava/lang/Object;(Native Method)
        at sun/reflect/NativeConstructorAccessorImpl.newInstance(NativeConstructorAc
    cessorImpl.java:39)
        at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConst
    ructorAccessorImpl.java:27)
        at java/lang/reflect/Constructor.newInstance(Constructor.java:513)
        at com/octetstring/vde/backend/BackendHandler.<init>(BackendHandler.java:248
    )
        at com/octetstring/vde/backend/BackendHandler.getInstance(BackendHandler.jav
    a:344)
        at weblogic/ldap/EmbeddedLDAP.start(EmbeddedLDAP.java:299)
        at weblogic/t3/srvr/SubsystemRequest.run(SubsystemRequest.java:64)
        at weblogic/work/ExecuteThread.execute(ExecuteThread.java:256)
        at weblogic/work/ExecuteThread.run(ExecuteThread.java:221)
        at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
        -- end of trace

    "JFR request timer" id=17 idx=0x4c tid=2260 prio=5 alive, waiting, native_blocke
    d, daemon
        -- Waiting for notification on: java/util/TaskQueue@0x0000000185B49530[fat l
    ock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at java/lang/Object.wait(Object.java:485)
    at java/util/TimerThread.mainLoop(Timer.java:483)
    ^-- Lock released while waiting: java/util/TaskQueue@0x0000000185B49530[fat
    lock]
    at java/util/TimerThread.run(Timer.java:462)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "weblogic.time.TimeEventGenerator" id=19 idx=0x50 tid=600 prio=9 alive, waiting,
    native_blocked, daemon
    -- Waiting for notification on: weblogic/time/common/internal/TimeTable@0x00
    0000018C653048[fat lock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at weblogic/time/common/internal/TimeTable.snooze(TimeTable.java:286)
    ^-- Lock released while waiting: weblogic/time/common/internal/TimeTable@0x0
    00000018C653048[fat lock]
    at weblogic/time/common/internal/TimeEventGenerator.run(TimeEventGenerator.j
    ava:117)
    at java/lang/Thread.run(Thread.java:662)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "JMAPI event thread" id=20 idx=0x54 tid=2916 prio=5 alive, in native, daemon

    "weblogic.timers.TimerThread" id=21 idx=0x58 tid=3288 prio=9 alive, waiting, nat
    ive_blocked, daemon
    -- Waiting for notification on: weblogic/timers/internal/TimerThread@0x00000
    0018C6ABCA0[fat lock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at weblogic/timers/internal/TimerThread$Thread.run(TimerThread.java:262)
    ^-- Lock released while waiting: weblogic/timers/internal/TimerThread@0x0000
    00018C6ABCA0[fat lock]
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'
    " id=22 idx=0x5c tid=1368 prio=5 alive, waiting, native_blocked, daemon
    -- Waiting for notification on: weblogic/work/ExecuteThread@0x000000018C2A1C
    00[fat lock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at java/lang/Object.wait(Object.java:485)
    at weblogic/work/ExecuteThread.waitForRequest(ExecuteThread.java:205)
    ^-- Lock released while waiting: weblogic/work/ExecuteThread@0x000000018C2A1
    C00[fat lock]
    at weblogic/work/ExecuteThread.run(ExecuteThread.java:226)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=25 idx=0x60 tid=1484
    prio=5 alive, in native, daemon
    at weblogic/socket/NTSocketMuxer.getIoCompletionResult(Lweblogic/socket/NTSo
    cketMuxer$IoCompletionData;)Z(Native Method)
    at weblogic/socket/NTSocketMuxer.processSockets(NTSocketMuxer.java:81)
    at weblogic/socket/SocketReaderRequest.run(SocketReaderRequest.java:29)
    at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:42)
    at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:145)
    at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:117)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=26 idx=0x64 tid=2540
    prio=5 alive, in native, daemon
    at weblogic/socket/NTSocketMuxer.getIoCompletionResult(Lweblogic/socket/NTSo
    cketMuxer$IoCompletionData;)Z(Native Method)
    at weblogic/socket/NTSocketMuxer.processSockets(NTSocketMuxer.java:81)
    at weblogic/socket/SocketReaderRequest.run(SocketReaderRequest.java:29)
    at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:42)
    at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:145)
    at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:117)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" id=27 idx=0x68 tid=3640
    prio=5 alive, in native, daemon
    at weblogic/socket/NTSocketMuxer.getIoCompletionResult(Lweblogic/socket/NTSo
    cketMuxer$IoCompletionData;)Z(Native Method)
    at weblogic/socket/NTSocketMuxer.processSockets(NTSocketMuxer.java:81)
    at weblogic/socket/SocketReaderRequest.run(SocketReaderRequest.java:29)
    at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:42)
    at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:145)
    at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:117)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "ExecuteThread: '3' for queue: 'weblogic.socket.Muxer'" id=28 idx=0x6c tid=1904
    prio=5 alive, in native, daemon
    at weblogic/socket/NTSocketMuxer.getIoCompletionResult(Lweblogic/socket/NTSo
    cketMuxer$IoCompletionData;)Z(Native Method)
    at weblogic/socket/NTSocketMuxer.processSockets(NTSocketMuxer.java:81)
    at weblogic/socket/SocketReaderRequest.run(SocketReaderRequest.java:29)
    at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:42)
    at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:145)
    at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:117)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    "VDE Transaction Processor Thread" id=31 idx=0x70 tid=1520 prio=2 alive, waiting
    , native_blocked, daemon
    -- Waiting for notification on: com/octetstring/vde/backend/standard/Transac
    tionProcessor@0x000000018A83F800[fat lock]
    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Metho
    d)
    at java/lang/Object.wait(J)V(Native Method)
    at com/octetstring/vde/backend/standard/TransactionProcessor.waitwrite(Trans
    actionProcessor.java:378)
    ^-- Lock released while waiting: com/octetstring/vde/backend/standard/Transa
    ctionProcessor@0x000000018A83F800[fat lock]
    at com/octetstring/vde/backend/standard/TransactionProcessor.run(Transaction
    Processor.java:228)
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    -- end of trace

    ===== END OF THREAD DUMP ===============
  • 2. Re: Managed Server stuck in starting
    Kishore Rout Journeyer
    Currently Being Moderated
    Hi Matt,
    Can you completely shutdown, and then restart the entire cluster. Because the coherence cache is shared by all members of the cluster, all need to be restarted.

    If this helps please mark.
    Regards,
    Kishore
  • 3. Re: Managed Server stuck in starting
    RenévanWijk Oracle ACE
    Currently Being Moderated
    Could you test, if you can create JVM's with a size of 16G on your machine.
    (a nice example of how to do that is provided here: http://stackoverflow.com/questions/987219/max-amount-of-memory-per-java-process-in-windows).

    When it is possible, what you can try to monitor is the swapping, could the process is running on disk instead of RAM.
  • 4. Re: Managed Server stuck in starting
    SMEC_Matt Newbie
    Currently Being Moderated
    Thank you guys. This problem is solved.

    It turns out that some of the files in servers/soa_server2 directory is corrupted due to improperly shutdown.
    We think it was the ldap files of the managed server that were corrupted since normally the next thing a server will do after "<Notice> <Log Management> <BEA-170019> <The server log file C:\Oracle\Middleware\user_projects\domains\ctst_soa_domain\servers\soa_server2\logs\soa_server2.log is opened. All server side log events will be written to this file.> " is LDAP related.

    I deleted cache,tmp,data,log directories under servers/soa_server2 and the server restarts normally.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points