1 2 Previous Next 16 Replies Latest reply on Aug 27, 2015 11:14 AM by russ mcdowell

    Windows Patching Latency

    russ mcdowell

      I patched 258 Windows servers, 2008 and 2012 recently for just MS critical and important patches for just the OS, so only around 7-10 patches.  In the first hour 172 machines reported as successful completed with 68 still running.  In the next hour only two more machines reported complete, one success and one failure.

       

      Attached is a sample BLDeploy log for a machine that was 'hung'.  I cancelled the job at 20:00, two hours after the start of patching.

       

      Too common to be busy server or busy network, not buying that. The server got the command to start, just never seems to finish and report status back.  Any ideas on what it could be?  This really hurts company perception of BSA and of course hurts operations.

        • 1. Re: Windows Patching Latency
          Bill Robinson

          Is the windows update service running on the targets?  that can slow down the patch deploys.

          • 2. Re: Windows Patching Latency
            russ mcdowell

            Windows Update service is not running on this particular machine.  Largely though it is running.  I'll look for one where the service is running and it was hung during patching and share its BLDeploy log.

             

            How/why does BSA patching rely on that service?

            • 3. Re: Windows Patching Latency
              Jim Wilson

              The actual patch deploy for this target took 14 minutes to install 9 patches, and the last message is when the reboot is about to start

               

              Can you post the bltargetjobmanager-a2d7c1eaf648315a9a5db556f0504875 log.

               

              bltargetjobmanager manages the target through the overall deploy including through the reboot phase.

               

              Also take a look at the Windows Event logs (System and Application) on the terget to see if /when the reboot took place and whether there were any problems

              • 4. Re: Windows Patching Latency
                Yanick Girouard

                Windows patching is nothing mor ethan calling the .msu packages in sequence on the target. This means it' susing the Windows Update service to install the patches. If it's already running because it's checking for updates for example, he .msu package launched will need to wait for the service to finish before it can start. This is why the service itself has to be enabled, but that the Windows Update settings must be set to "Never check for updates".

                1 of 1 people found this helpful
                • 5. Re: Windows Patching Latency
                  Mayur Thakare

                  Along with bltargetmanager that Jim has requested, would it be possible to get appserver / job server logs?

                  I see problem after machine getting rebooted. Is target machine behind proxy? Is is possible to connect  this server (with same ip/name that was used to connect before reboot) from the job server or appserver (a server which is handling this particular deploy job) ?

                  • 6. Re: Windows Patching Latency
                    russ mcdowell

                    Problem isn't the speed of the patching, the problem is the patching completes and that isn't getting back to the console.  So what I end up with are machines that appear in the console to still be patching when they're in fact done and ready for a reboot.

                    Having the same issue again tonight after spending the end of last week running the Patch Ready Zipkit and fixing issues that found.

                    • 7. Re: Windows Patching Latency
                      russ mcdowell

                      This job was set up from a patch analysis to patch but not reboot.  We manage reboots with a separate job to accommodate application tiered reboots.

                      If I'm doing something wrong with this, let me know.  Normally we analyze Friday and do simulate/stage then with the commit Sunday.  This particular run was all done Sunday set up with the below job options.

                       

                      Here's an example of the BLTargetManager log on one machine:

                       

                      08/23/15 15:57:51.834 DEBUG    bldeploy - TJM invoked with arguments:
                      08/23/15 15:57:51.873 DEBUG    bldeploy - args 0 = bltargetjobmanager
                      08/23/15 15:57:51.875 DEBUG    bldeploy - args 1 = -start
                      08/23/15 15:57:51.877 DEBUG    bldeploy - args 2 = -cmd
                      08/23/15 15:57:51.879 DEBUG    bldeploy - args 3 = bldeploy 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -DryRun -Xr -V2 -js0 -jr1 -jc0
                      08/23/15 15:57:51.887 DEBUG    bldeploy - args 4 = -me
                      08/23/15 15:57:51.889 DEBUG    bldeploy - args 5 = 9f71738993d43872958040e67721ba0e
                      08/23/15 15:57:51.891 DEBUG    bldeploy - args 6 = -mp
                      08/23/15 15:57:51.892 DEBUG    bldeploy - args 7 = -sp
                      08/23/15 15:57:51.893 DEBUG    bldeploy - args 8 = -ps
                      08/23/15 15:57:51.893 DEBUG    bldeploy - args 9 = -h60
                      08/23/15 15:57:51.893 DEBUG    bldeploy - BlTargetJobManager started
                      08/23/15 15:57:51.894 DEBUG    bldeploy - Commandline: bltargetjobmanager -start -cmd bldeploy 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -DryRun -Xr -V2 -js0 -jr1 -jc0  -me 9f71738993d43872958040e67721ba0e -mp -sp -ps -h60
                      08/23/15 15:57:51.922 DEBUG    bldeploy - Found path to cmd at C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\sbin/bldeploy.exe
                      08/23/15 15:57:51.925 DEBUG    bldeploy - Executing "C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\sbin\bldeploy.exe" 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -DryRun -Xr -V2 -js0 -jr1 -jc0  -StartNew
                      08/23/15 15:57:51.931 DEBUG    bldeploy - ProcessExecutor::createProcess batchFile=, cmd="C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\sbin\bldeploy.exe" 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -DryRun -Xr -V2 -js0 -jr1 -jc0  -StartNew, cmdDir=
                      08/23/15 15:57:52.107 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 15:57:52.621 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 15:57:52.623 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 15:57:52.625 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process ID (pid) = 3684
                      08/23/15 15:57:52.626 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 3224
                      08/23/15 15:57:52.628 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 15:57:52.630 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 15:57:52.632 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 15:57:52.633 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Real Memory = 3884 KB
                      08/23/15 15:57:52.635 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Virtual Memory = 2956 KB
                      08/23/15 15:57:52.637 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 15:57:52.639 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 15:57:52.640 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Usage% = 59.3%
                      08/23/15 15:57:52.641 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 15:57:52.643 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 15:57:52.644 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 15:57:52.646 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 15:57:51 2015

                      08/23/15 15:57:52.648 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Group ID = 0
                      08/23/15 15:57:52.649 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Got processes list: 1 entries
                      08/23/15 15:57:52.651 DEBUG    bldeploy - Compare to blp_prog=bldeploy.exe
                      08/23/15 15:57:52.652 DEBUG    bldeploy - Command has started
                      08/23/15 15:57:52.656 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 15:57:53.164 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 15:57:53.166 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 15:57:53.168 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process ID (pid) = 3684
                      08/23/15 15:57:53.170 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 3224
                      08/23/15 15:57:53.181 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 15:57:53.183 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 15:57:53.185 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 15:57:53.186 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Real Memory = 9936 KB
                      08/23/15 15:57:53.188 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Virtual Memory = 4516 KB
                      08/23/15 15:57:53.189 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 15:57:53.191 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 15:57:53.193 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Usage% = 53.1%
                      08/23/15 15:57:53.194 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 15:57:53.196 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 15:57:53.197 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 15:57:53.199 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 15:57:51 2015

                      08/23/15 15:57:53.201 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Group ID = 0
                      08/23/15 15:57:53.203 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Got processes list: 1 entries
                      08/23/15 15:57:53.204 DEBUG    bldeploy - Compare to blp_prog=bldeploy.exe
                      08/23/15 15:57:54.216 DEBUG    bldeploy - Received from PID=3684 EVENT=STARTED MSG=Package "prod eems 20150823-20393361 @ 2015-08-23 15-56-08-766-0500" UUID(9f71738993d43872958040e67721ba0e) started
                      08/23/15 15:57:54.219 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 15:57:54.724 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 15:57:54.726 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 15:57:54.728 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process ID (pid) = 3684
                      08/23/15 15:57:54.730 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 3224
                      08/23/15 15:57:54.731 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 15:57:54.733 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 15:57:54.735 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 15:57:54.736 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Real Memory = 10156 KB
                      08/23/15 15:57:54.738 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Virtual Memory = 4644 KB
                      08/23/15 15:57:54.739 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 15:57:54.741 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 15:57:54.743 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Usage% =  0.0%
                      08/23/15 15:57:54.744 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 15:57:54.746 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 15:57:54.748 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 15:57:54.749 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 15:57:51 2015

                      08/23/15 15:57:54.751 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Group ID = 0
                      08/23/15 15:57:54.753 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Got processes list: 1 entries
                      08/23/15 15:57:54.754 DEBUG    bldeploy - Compare to blp_prog=bldeploy.exe
                      08/23/15 15:57:55.757 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 15:57:56.263 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 15:57:56.270 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 15:57:56.272 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process ID (pid) = 3684
                      08/23/15 15:57:56.274 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 3224
                      08/23/15 15:57:56.275 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 15:57:56.277 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 15:57:56.279 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 15:57:56.280 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Real Memory = 10280 KB
                      08/23/15 15:57:56.282 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Virtual Memory = 4652 KB
                      08/23/15 15:57:56.283 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 15:57:56.285 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 15:57:56.287 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Usage% =  0.0%
                      08/23/15 15:57:56.288 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 15:57:56.290 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 15:57:56.292 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 15:57:56.294 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 15:57:51 2015

                      08/23/15 15:57:56.296 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Group ID = 0
                      08/23/15 15:57:56.297 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Got processes list: 1 entries
                      08/23/15 15:57:56.298 DEBUG    bldeploy - Compare to blp_prog=bldeploy.exe
                      08/23/15 15:57:57.301 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 15:57:57.808 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 15:57:57.810 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 15:57:57.811 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process ID (pid) = 3684
                      08/23/15 15:57:57.813 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 3224
                      08/23/15 15:57:57.815 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 15:57:57.821 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 15:57:57.823 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 15:57:57.824 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Real Memory = 10296 KB
                      08/23/15 15:57:57.826 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Virtual Memory = 4652 KB
                      08/23/15 15:57:57.828 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 15:57:57.830 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 15:57:57.831 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   CPU Usage% = 62.5%
                      08/23/15 15:57:57.833 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 15:57:57.834 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 15:57:57.835 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 15:57:57.837 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 15:57:51 2015

                      08/23/15 15:57:57.839 DEBUG    bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available):   Process Group ID = 0
                      08/23/15 15:57:57.841 INFO     bldeploy -  ALPERSITE 3920 sBladeL (Not_available): (Not_available): Got processes list: 1 entries
                      08/23/15 15:57:57.842 DEBUG    bldeploy - Compare to blp_prog=bldeploy.exe
                      08/23/15 15:57:58.851 DEBUG    bldeploy - Received from PID=3684 EVENT=INFO MSG=Package "prod eems 20150823-20393361 @ 2015-08-23 15-56-08-766-0500" UUID(9f71738993d43872958040e67721ba0e) initialized, entering wait queue for processing
                      08/23/15 15:57:58.854 DEBUG    bldeploy - Received from PID=3684 EVENT=INFO MSG=Package "prod eems 20150823-20393361 @ 2015-08-23 15-56-08-766-0500" UUID(9f71738993d43872958040e67721ba0e) processing instructions
                      08/23/15 15:57:58.857 DEBUG    bldeploy - TJM return code 0 changed to succeeded. Correct code set in STOP event exitCode value
                      08/23/15 15:57:58.859 DEBUG    bldeploy - Received from PID=3684 EVENT=STOP MSG=Package "prod eems 20150823-20393361 @ 2015-08-23 15-56-08-766-0500" UUID(9f71738993d43872958040e67721ba0e) completed. exitCode = 0 (DryRun successful)
                      08/23/15 15:57:58.865 DEBUG    bldeploy - Deleted event file: C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\\Transactions\events\9f71738993d43872958040e67721ba0e.out
                      08/23/15 15:57:58.870 DEBUG    bldeploy - Deleted event file: C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\\Transactions\events\9f71738993d43872958040e67721ba0e.in
                      08/23/15 15:57:58.873 DEBUG    bldeploy - Operation complete return code 0
                      08/23/15 16:01:43.052 DEBUG    bldeploy - TJM invoked with arguments:
                      08/23/15 16:01:43.054 DEBUG    bldeploy - args 0 = bltargetjobmanager
                      08/23/15 16:01:43.055 DEBUG    bldeploy - args 1 = -start
                      08/23/15 16:01:43.055 DEBUG    bldeploy - args 2 = -cmd
                      08/23/15 16:01:43.056 DEBUG    bldeploy - args 3 = bldeploy 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -V2 -RegAllCOM -UnregAllCOM -TreatLockedAsErr -js0 -jr1 -jc0
                      08/23/15 16:01:43.059 DEBUG    bldeploy - args 4 = -me
                      08/23/15 16:01:43.059 DEBUG    bldeploy - args 5 = 9f71738993d43872958040e67721ba0e
                      08/23/15 16:01:43.060 DEBUG    bldeploy - args 6 = -mp
                      08/23/15 16:01:43.061 DEBUG    bldeploy - args 7 = -sp
                      08/23/15 16:01:43.062 DEBUG    bldeploy - args 8 = -ps
                      08/23/15 16:01:43.062 DEBUG    bldeploy - args 9 = -h60
                      08/23/15 16:01:43.063 DEBUG    bldeploy - BlTargetJobManager started
                      08/23/15 16:01:43.064 DEBUG    bldeploy - Commandline: bltargetjobmanager -start -cmd bldeploy 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -V2 -RegAllCOM -UnregAllCOM -TreatLockedAsErr -js0 -jr1 -jc0  -me 9f71738993d43872958040e67721ba0e -mp -sp -ps -h60
                      08/23/15 16:01:43.080 DEBUG    bldeploy - Found path to cmd at C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\sbin/bldeploy.exe
                      08/23/15 16:01:43.083 DEBUG    bldeploy - Executing "C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\sbin\bldeploy.exe" 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -V2 -RegAllCOM -UnregAllCOM -TreatLockedAsErr -js0 -jr1 -jc0  -StartNew
                      08/23/15 16:01:43.088 DEBUG    bldeploy - ProcessExecutor::createProcess batchFile=, cmd="C:\Program Files\BMC Software\BladeLogic\8.0\RSCD\sbin\bldeploy.exe" 9f71738993d43872958040e67721ba0e -N=/temp/stage/d90ce4fd1b6238e3845dd764967ac304 -P=alpersite -Q=params.txt -PKG=prod%20eems%2020150823-20393361%20@%202015-08-23%2015-56-08-766-0500-2409401.1 -V2 -RegAllCOM -UnregAllCOM -TreatLockedAsErr -js0 -jr1 -jc0  -StartNew, cmdDir=
                      08/23/15 16:01:43.207 INFO     bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 16:01:43.715 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 16:01:43.717 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 16:01:43.719 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process ID (pid) = 5960
                      08/23/15 16:01:43.720 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 4380
                      08/23/15 16:01:43.721 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 16:01:43.723 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 16:01:43.724 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 16:01:43.726 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Real Memory = 8388 KB
                      08/23/15 16:01:43.728 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Virtual Memory = 3564 KB
                      08/23/15 16:01:43.729 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 16:01:43.731 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 16:01:43.733 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   CPU Usage% = 90.6%
                      08/23/15 16:01:43.735 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 16:01:43.736 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 16:01:43.738 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 16:01:43.740 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 16:01:43 2015

                      08/23/15 16:01:43.741 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process Group ID = 0
                      08/23/15 16:01:43.743 INFO     bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available): Got processes list: 1 entries
                      08/23/15 16:01:43.745 DEBUG    bldeploy - Compare to blp_prog=bldeploy.exe
                      08/23/15 16:01:43.746 DEBUG    bldeploy - Command has started
                      08/23/15 16:01:43.754 DEBUG    bldeploy - Received from PID=5960 EVENT=STARTED MSG=Package "prod eems 20150823-20393361 @ 2015-08-23 15-56-08-766-0500" UUID(9f71738993d43872958040e67721ba0e) started
                      08/23/15 16:01:43.757 INFO     bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available): Getting processes details
                      08/23/15 16:01:44.261 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available): Process Name = bldeploy.exe
                      08/23/15 16:01:44.263 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Command = bldeploy.exe
                      08/23/15 16:01:44.265 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process ID (pid) = 5960
                      08/23/15 16:01:44.266 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Parrent Process ID (ppid) = 4380
                      08/23/15 16:01:44.268 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process Owner Username = sBladeL
                      08/23/15 16:01:44.270 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   User ID = 0
                      08/23/15 16:01:44.271 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Group ID = 0
                      08/23/15 16:01:44.273 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Real Memory = 10172 KB
                      08/23/15 16:01:44.274 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Virtual Memory = 4664 KB
                      08/23/15 16:01:44.277 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Total CPU Time = 0 seconds
                      08/23/15 16:01:44.278 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   CPU Units = 0
                      08/23/15 16:01:44.280 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   CPU Usage% =  0.0%
                      08/23/15 16:01:44.281 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Memory Usage% =  0.0%
                      08/23/15 16:01:44.283 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Hostname = ALPERSITE
                      08/23/15 16:01:44.285 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Priority = 0
                      08/23/15 16:01:44.286 DEBUG    bldeploy -  ALPERSITE 4592 sBladeL (Not_available): (Not_available):   Process Start Time = Sun Aug 23 16:01:43 2015

                       

                      It repeats all of this every second or so and the file is currently over 16MB in size.

                      • 8. Re: Windows Patching Latency
                        Mayur Thakare

                        The bldeploy log ( bldeploy-a2d7c1eaf648315a9a5db556f0504875 log.) that you have attached with this issue suggests that deploy job is configured for reboot. I can see that deploy job is attempting reboot. However,  job options screen snapshot that you have attached suggests job is not configured to reboot.


                        So are we looking at two different problem?

                        1st : Deploy job attempt to reboot and do not return (as suggested by bldeploy log attached)

                        2nd : Deploy job is not set to reboot and still do not return (as suggested by job options screen)

                        • 9. Re: Windows Patching Latency
                          russ mcdowell

                          We have 3 standard patching job for each environment we patch for each month, two of them are set to up in BSA just like the job deploy screenshot above.  The BLDeploy and BLTargetManager logs reflect the NO REBOOT job settings.  The jobs we allow BSA to reboot the Reboot Option is set to reboot at the end of the job.

                          The reboot in the screenshot should be suppressed.

                           

                          After 10 hours of patching last night only 1 in 5 of our targeted servers received 100% of their patches.  This is grossly inadequate.

                          • 10. Re: Windows Patching Latency
                            Yanick Girouard

                            How many patches did you have to install in that wave, what were the analysis options used in your job and which products do you include in your catalog filters?

                             

                            There's several things at play here (that could be impacting the duration of the patching):

                             

                            1. The Windows Update Service being used by the system to check for updates in the background (as previously suggested)

                            2. The sheer number of patches to apply.

                            3. Antivirus affecting the performance

                            4. A lot of .NET patches requiring a recompile of assemblies (ngen.exe can take forever to complete sometimes)

                            5. CPU or memory resource issues on the servers during the patching.

                             

                            As for not all patches being applied, know that several MS patches require a reboot before subsequent patches can be completely applied or even applicable. Even though the Shavlik engine may return 100 patches missing for example, not all of the 100 patches will be applicable in a single pass. Multiple reboots/patch cycles may be required (usually no more than 2 passes is enough).

                            • 11. Re: Windows Patching Latency
                              russ mcdowell

                              So here's what I'm finding.  Svchost.exe is consuming 90+% of CPU and is effectively dragging patching down to the level of 1 patch being installed per hour.  With that process killed things appear to run fine but that process has to be repeatedly killed otherwise it eats all the CPU.

                               

                              We enforce our WSUS settings via an NSH job via BSA.  Those settings are:

                              AUOptions - 3 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\AUOptions

                              AutoInstallMinorUpdates - 0 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\AutoInstallMinorUpdates

                              DetectionFrequency - 6 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\DetectionFrequency

                              DetectionFrequencyEnabled - 0 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\DetectionFrequencyEnabled

                              ElevateNonAdmins - 0 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\ElevateNonAdmins

                              NoAUShutdownOption - 1 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\NoAUShutdownOption

                              NoAutoRebootWithLoggedOnUsers - 0 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\NoAutoRebootWithLoggedOnUsers

                              NoAutoUpdate - 0 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\NoAutoUpdate

                              RebootRelaunchTimeout - 5 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\RebootRelaunchTimeout

                              RebootRelaunchTimeoutEnabled - 1 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\RebootRelaunchTimeoutEnabled

                              RebootWarningTimeoutEnabled - 1 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\RebootWarningTimeoutEnabled

                              RescheduleWaitTime - 5 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\RescheduleWaitTime

                              RescheduleWaitTimeEnabled - 1 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\RescheduleWaitTimeEnabled

                              ScheduledInstallDay - 0 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\ScheduledInstallDay

                              ScheduledInstallTime - 3 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\ScheduledInstallTime

                              UseWUServer - 1 HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\UseWUServer

                               

                              I have confirmed these settings on the target server.

                               

                              I have set the WSUS service to manual but of course it keeps starting again.

                              • 12. Re: Windows Patching Latency
                                Bill Robinson

                                Is there a gpo overriding the wsus settings ?

                                 

                                Do you have process explorer or something to see what that svchost is doing ?

                                • 13. Re: Windows Patching Latency
                                  russ mcdowell

                                  I've asked the security department that question since they manage GPO.  I will say compliance runs largely reflect the above settings so I do not believe that to be the case.

                                   

                                  I have Windows Task Manager open and am repeatedly killed svchost.exe.  Am currently hung on the IE update MS15-079.  Been an hour now trying to get it to install.

                                  • 14. Re: Windows Patching Latency
                                    Yanick Girouard

                                    Just to clarify, the Windows Update service has to be enabled for Windows to be able to install Windows Updates. Executing a .msu file triggers the service to start, which is why you see it coming back up everytime.

                                     

                                    What is important is that the effective setting of the Windows Update settings is set to "Never Check for Updates". I can't be allowed to even check but not download, because the action of checking for updates locks the service, and this is why patches are appearing to install only once per hour.

                                     

                                    The key "HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\WindowsUpdate\AU\NoAutoUpdate" should be set to 1. Yours is set to 0.

                                     

                                    One way you can tell if it's enabled or not, is to simply open Windows Update on one of the servers being affected, and check the update setting in the GUI. If it's not set to "Never check for updates", it's enabled.

                                    1 of 1 people found this helpful
                                    1 2 Previous Next