5 Replies Latest reply: Aug 16, 2009 6:37 AM by 807567 RSS

    smpatch analyze - five days analyzing?

    807567
      After changing RAM up to 8GB, "smpatch analyze" ran from crontab for the first time that I noticed. Seemed to take lots of CPU cycles (Sun Ultra 20 M2 - x86 running Solaris 10 from MY2006) so I shut off the crontab instance and started one from the command line.

      Five days later, it still seems to be analyzing and consuming all resources of one CPU.

      Any RTFMs (with FM suggestions) or condolences welcome.
      Donald.
        • 1. Re: smpatch analyze - five days analyzing?
          807567
          Which process is consuming the CPU: smpatch, pprosvc or java?

          If it is java try doing a pstack of the java process.

          One possibility is that your switch to 8GB (what was it previously?) is causing the Java server VM to now run by default where in the past it may have been the client VM. Not that the server VM should hang like this, but it may explain the change. If it is the JVM then pstack should give some hint as to where the problem is.

          If the process is not java then you'll need the assistance of the update manager wizards. ;-)

          There's probably some setting you can use to force use of the client VM (by passing -client to the VM invocation) but the update manager wizards will need to advise how to do that.

          Cheers,
          David Holmes
          • 2. Re: smpatch analyze - five days analyzing?
            807567
            Hello, David.

            Thank you for your response. I'm going to have to look at the rest of your suggestions later - I'm commited to a large list of To-Do's today for guests this evening. No sweat; this is not a production machine, it's my home computer.

            Donald.

            Meantime, this is what I found:

            My ps -A -o BlahDeBlah looks like java is the primary consumer - one line in particular:

            PID PPID USER %CPU VSZ ELAPSED TIME SZ %MEM WCHAN LWP NLWP COMMAND
            17911 17902 root 49.3 316536 6-05:49:53 6-04:11:10 79134 1.8 - 1 12 /usr/bin/java -Djava.library.path=/usr/lib/cc-ccr/lib com.sun.patchpro.cli.Patc

            Previously, memory was 3GB

            pstack - most threads are in lwp_cond_wait except #12, which sure looks like the culprit. Now what to do?

            ----------------- lwp# 12 / thread# 12 --------------------
            fef50647 pollsys (0, 0, f9071c60, 0)
            feefa6c2 poll (0, 0, 32) + 52
            fe9328f4 __1cIos_sleep6Fxi_i_ (32, 0, 0) + 124
            fe93271c __1cCosFsleep6FpnGThread_xi_i_ (81901b0, 32, 0, 0) + 1ac
            fea6c4e5 __1cNWatcherThreadDrun6M_v_ (81901b0) + e5
            fecb27f2 __1cG_start6Fpv_0_ (81901b0) + d2
            fef4f92e thrsetup (fe3f2400) + 4e
            fef4fc10 lwpstart (fe3f2400, 0, 0, f9071ff8, fef4fc10, fe3f2400)
            • 3. Re: smpatch analyze - five days analyzing?
              807567
              dhlocker0 wrote:
              pstack - most threads are in lwp_cond_wait except #12, which sure looks like the culprit. Now what to do?

              ----------------- lwp# 12 / thread# 12 --------------------
              fef50647 pollsys (0, 0, f9071c60, 0)
              feefa6c2 poll (0, 0, 32) + 52
              fe9328f4 __1cIos_sleep6Fxi_i_ (32, 0, 0) + 124
              fe93271c __1cCosFsleep6FpnGThread_xi_i_ (81901b0, 32, 0, 0) + 1ac
              fea6c4e5 __1cNWatcherThreadDrun6M_v_ (81901b0) + e5
              fecb27f2 __1cG_start6Fpv_0_ (81901b0) + d2
              fef4f92e thrsetup (fe3f2400) + 4e
              fef4fc10 lwpstart (fe3f2400, 0, 0, f9071ff8, fef4fc10, fe3f2400)
              The WatcherThread is a periodic thread that wakes up every 50ms to do some VM housekeeping work. It spends most of its time sleeping as per the above stacktrace. So this shouldn't be the culprit.

              If pstack didn't show any active threads then it might be necessary to do a series of pstacks to see if any threads are changing their stacks - and thus are active. I'd be interested to see more of the pstack output.

              David Holmes
              • 4. Re: smpatch analyze - five days analyzing?
                807567
                Only the first thread is showing any activity. All the rest (I did several comparisons) seem to be in the cond-wait state. I just ran a once-per-minute pstack. All diffs are in lpw #1/thread #1; here are some extracts: That's all I have room for; hope it's not to onerous. the 17911 is the PID of the processes spawned by /sbin/sh /usr/sbin/pprosvc -l (from the smpatch analyze command.)

                17911:     /usr/bin/java -Djava.library.path=/usr/lib/cc-ccr/lib com.sun.patchpro
                ----------------- lwp# 1 / thread# 1 --------------------
                f9329445 ???????? (0, b93599a0, 0, 0, 9, b4e6af78)
                b4e4b4d8 ???????? ()
                ----------------- lwp# 2 / thread# 2 --------------------
                fef50a17 lwp_cond_wait (80f5218, 80f5200, 0, 0)
                fe92faca __1cHMonitorEwait6Mil_i_ (80f51a8, 1, 0) + 4ba
                fe9114dd __1cNGCTaskManagerIget_task6MI_pnGGCTask__ (80f5168, 0) + 90
                fea57643 __1cMGCTaskThreadDrun6M_v_ (80f5238) + 1a3
                fecb27f2 __1cG_start6Fpv_0_ (80f5238) + d2
                fef4f92e thrsetup (fef92400) + 4e
                fef4fc10 lwpstart (fef92400, 0, 0, fbd7bff8, fef4fc10, fef92400)
                ----------------- lwp# 3 / thread# 3 --------------------
                fef50a17 lwp_cond_wait (80f5218, 80f5200, 0, 0)
                fe92faca __1cHMonitorEwait6Mil_i_ (80f51a8, 1, 0) + 4ba
                fe9114dd __1cNGCTaskManagerIget_task6MI_pnGGCTask__ (80f5168, 1) + 90
                fea57643 __1cMGCTaskThreadDrun6M_v_ (80f5c78) + 1a3
                fecb27f2 __1cG_start6Fpv_0_ (80f5c78) + d2
                fef4f92e thrsetup (fe3f0000) + 4e
                fef4fc10 lwpstart (fe3f0000, 0, 0, fbd39ff8, fef4fc10, fe3f0000)
                ----------------- lwp# 4 / thread# 4 --------------------
                fef50a17 lwp_cond_wait (80739c8, 80739b0, fbcf7b88, 0)
                fef3dc1f lwpcond_timedwait (80739c8, 80739b0, fbcf7bd0) + 35
                fe92faa8 __1cHMonitorEwait6Mil_i_ (8073958, 1, 3e8) + 498
                fea676dd __1cIVMThreadEloop6M_v_ (817bee8) + fd
                fea681c8 __1cIVMThreadDrun6M_v_ (817bee8) + 88
                fecb27f2 __1cG_start6Fpv_0_ (817bee8) + d2
                fef4f92e thrsetup (fe3f0400) + 4e
                fef4fc10 lwpstart (fe3f0400, 0, 0, fbcf7ff8, fef4fc10, fe3f0400)
                ----------------- lwp# 5 / thread# 5 --------------------
                fef50a17 lwp_cond_wait (817e2e0, 817e2c8, 0, 0)
                fe9d73ac __1cCosHSolarisFEventEpark6M_v_ (817e2a0) + 4c
                fe9e52f6 __1cNObjectMonitorEwait6MxipnGThread__v_ (817e4f4, 0, 0, 1, 817dfc0) + 346
                fe9e5a00 __1cSObjectSynchronizerEwait6FnGHandle_xpnGThread__v_ (8125eec, 0, 0, 817dfc0) + 70
                fe9e4db4 JVM_MonitorWait (817e080, fbcb5af0, 0, 0, fbcb5abc, 0) + 234
                f92083ba ???????? (0, f9206319, 0, 0, b90b86a0, fbcb5af4)
                f9202aeb ???????? (b90b86a0, 3, b90b86a0, fbcb5b1c, b4e8e056, fbcb5b58)
                f9202aeb ???????? (0, f4620010, b90b86a0, f4620010, b908e3b0, 1f80)
                f92001af ???????? (fbcb5bb8, fbcb5d5c, a, b4e8e0b0, f9207440, fbcb5cb8)
                fe940b67 __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (fbcb5d58, fbcb5c50, fbcb5cb4, 817dfc0, fbcb5c44, fe940e68) + 187
                fe940e34 __1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_ (fe9409e0, fbcb5d58, fbcb5c50, fbcb5cb4, 817dfc0) + 14
                fe940e68 __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (fbcb5d58, 8125ee8, fbcb5cb4, 817dfc0) + 28
                fe9e7eae __1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_ (fbcb5d58, 8125edc, fee3bf20, fee3bff0, fbcb5cb4, 817dfc0) + be
                fe9f205d __1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_ (fbcb5d58, 8125ed8, 8125edc, fee3bf20, fee3bff0, 817dfc0) + 6d
                fea093b0 __1cMthread_entry6FpnKJavaThread_pnGThread__v_ (817dfc0, 817dfc0) + d0
                fea05ae1 __1cKJavaThreadRthread_main_inner6M_v_ (817dfc0) + 51
                fea05a85 __1cKJavaThreadDrun6M_v_ (817dfc0) + 105
                fecb27f2 __1cG_start6Fpv_0_ (817dfc0) + d2
                fef4f92e thrsetup (fe3f0800) + 4e
                fef4fc10 lwpstart (fe3f0800, 0, 0, fbcb5ff8, fef4fc10, fe3f0800)
                ----------------- lwp# 6 / thread# 6 --------------------
                fef50a17 lwp_cond_wait (817fc28, 817fc10, 0, 0)
                fe9d73ac __1cCosHSolarisFEventEpark6M_v_ (817fbe8) + 4c
                fe9e52f6 __1cNObjectMonitorEwait6MxipnGThread__v_ (817e534, 0, 0, 1, 817f4c0) + 346
                fe9e5a00 __1cSObjectSynchronizerEwait6FnGHandle_xpnGThread__v_ (817f67c, 0, 0, 817f4c0) + 70
                fe9e4db4 JVM_MonitorWait (817f580, f91fdb40, 0, 0, f91fdb0c, 0) + 234
                f92083ba ???????? (0, f9206319, 0, 0, b8f25578, 3)
                f9202aeb ???????? (0, 0, b8f25578, 0, 0, b9022018)
                f9202a14 ???????? (b9022018, f91fdbb0, b4e8e963, f91fdbd8, b4e8ebe0, 0)
                f9202a14 ???????? (f46203d8, b908e410, 1f80, fedd0000, 817f4c0, 1)
                f92001af ???????? (f91fdc38, f91fdddc, a, b4e8e980, f9207440, f91fdd38)
                fe940b67 __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (f91fddd8, f91fdcd0, f91fdd34, 817f4c0, f91fdcc4, fe940e68) + 187
                fe940e34 __1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_ (fe9409e0, f91fddd8, f91fdcd0, f91fdd34, 817f4c0) + 14
                fe940e68 __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (f91fddd8, 817f678, f91fdd34, 817f4c0) + 28
                fe9e7eae __1cJJavaCallsMcall_virtual6FpnJJavaValue_nLKlassHandle_nMsymbolHandle_4pnRJavaCallArguments_pnGThread__v_ (f91fddd8, 817f66c, fee3bf20, fee3bff0, f91fdd34, 817f4c0) + be
                fe9f205d __1cJJavaCallsMcall_virtual6FpnJJavaValue_nGHandle_nLKlassHandle_nMsymbolHandle_5pnGThread__v_ (f91fddd8, 817f668, 817f66c, fee3bf20, fee3bff0, 817f4c0) + 6d
                fea093b0 __1cMthread_entry6FpnKJavaThread_pnGThread__v_ (817f4c0, 817f4c0) + d0
                fea05ae1 __1cKJavaThreadRthread_main_inner6M_v_ (817f4c0) + 51
                fea05a85 __1cKJavaThreadDrun6M_v_ (817f4c0) + 105
                fecb27f2 __1cG_start6Fpv_0_ (817f4c0) + d2
                fef4f92e thrsetup (fe3f0c00) + 4e
                fef4fc10 lwpstart (fe3f0c00, 0, 0, f91fdff8, fef4fc10, fe3f0c00)
                ----------------- lwp# 7 / thread# 7 --------------------
                fef4fc6b lwp_park (0, 0, 0)
                ...

                17911:     /usr/bin/java -Djava.library.path=/usr/lib/cc-ccr/lib com.sun.patchpro
                ----------------- lwp# 1 / thread# 1 --------------------
                f93291d8 ???????? ()
                ----------------- lwp# 2 / thread# 2 --------------------
                ...

                17911:     /usr/bin/java -Djava.library.path=/usr/lib/cc-ccr/lib com.sun.patchpro
                ----------------- lwp# 1 / thread# 1 --------------------
                f93292ff ???????? ()
                ----------------- lwp# 2 / thread# 2 --------------------
                ...

                17911:     /usr/bin/java -Djava.library.path=/usr/lib/cc-ccr/lib com.sun.patchpro
                ----------------- lwp# 1 / thread# 1 --------------------
                f930a0ce ???????? (100, 4800100f, 4800100f, 4800100f, 4800100f, 4800100f)
                b4e00a70 ???????? ()
                ----------------- lwp# 2 / thread# 2 --------------------
                ...

                17911:     /usr/bin/java -Djava.library.path=/usr/lib/cc-ccr/lib com.sun.patchpro
                ----------------- lwp# 1 / thread# 1 --------------------
                f930555a ???????? ()
                ----------------- lwp# 2 / thread# 2 --------------------
                • 5. Re: smpatch analyze - five days analyzing?
                  807567
                  That's a strange result. lwp#1 is the main thread and pstack isn't showing anything meaningful for it.

                  Can you use pargs to see the full command-line used to launch the VM and try running that by hand?

                  If so, and it still gets stuck, try the following to try and get some data:

                  1. ctrl-\ to get a Java thread stack dump
                  2. pstack again (or "jstack -m" (jstack is a Java tool in the same directory as the java command))
                  3. Attach dbx to the process and use "where" on the main thread to see where dbx thinks it is

                  Also if the manually run command does get stuck, try adding the -client argument and see if that works ok.

                  Probably better to take this off forum, so if it's okay with you please email to David dot Holmes at Sun dot com

                  David Holmes