locked
App-V 5 Publish Task - Publish Event RRS feed

  • Question

  • Hi everyone,

    I have been trying to work out issues with slow publishing time in our App-V 5 HF5 Full Infrastructure environment.  At first I thought our slow publish time would be improved by HF4/ UEM optimizations, but now I'm starting to wonder if something else is going on.

    We are seeing that from the time the publishing task starts, until the 1901 event ID is roughly 60 seconds.  The time from the 1901 - 1902 event seems reasonable, but the time it takes between the task starting and the 1901 event ID is the real killer for us.

    Testing steps;

    Adding myself to approx 25 global groups, and logging into a clean non-persistent VDI (results are similar in subsequent logins).
    Wait until publishing is totally finished
    Opening up compmgmt.msc, and inspecting the task scheduler -->MS-->AppV-->Publishing, and investigating the history tab.  Logging the time for 'Task Started', event ID 100.
    Opening up event viewer--->applications and services logs--> MS-->AppV-->Cient-->Operational.  Logging the time the latest 1901 event ID started.

    Subtracting the top time from the bottom.

    Usually the time it takes is anywhere from 60-90 seconds.  This seems to be true if you are in only 1 app, and not just a large amount. 
    This is also problematic because the progress bar isn't seen on screen until the 1901, so it seems like longer then it is.

    My questions:

    Is this normal?  Are other people seeing such a long delay between task start and 1901?
    Is the delay part of publishing, or does nothing actually happen until the 1901 event?

    We opened up a ticket with MS pre HF4 and were told this is normal behavior, and that HF4 improved that time.  Are other people seeing this?

    Information about our environment:
    Running App-V 5 HF5 in non-persistent VDIs under full infrastructure. 
    Using VMWare Persona to roam profiles.
    Do not have App-V 4.6 installed in this environment.

    Please let me know if there is more information I can give.  I'd be more then happy to attach any logs.

    Thanks,
    Andrew

    Monday, June 23, 2014 6:53 PM

Answers

  • The initial delay might be caused by the fact that some 'initialization' (namely WMI) happens when the first App-V command is launched. 
    I'm not sure if it would help to run 'an' App-V command very early in the logon process, so that things are in place before the scheduled task launches.

    Falko

    Twitter @kirk_tn   |   Blog kirxblog   |   Web kirx.org   |   Fireside appvbook.com

    Friday, June 27, 2014 8:43 AM
    Moderator

All replies

  • You are not still using sync.vbs are you? This was switched to an EXE in HF4. I know some customers modified the scheduled tasks and this persisted past the upgrade. What are you roaming with Persona?

    Steve Thomas, Senior Consultant, Microsoft

    App-V/MED-V/SCVMM/Server App-V/MDOP/AppCompat

    http://blogs.technet.com/gladiatormsft/
    The App-V Team blog: http://blogs.technet.com/appv/
    The MED-V Team Blog: http://blogs.technet.com/medv
    The SCVMM Team blog: http://blogs.technet.com/scvmm/

    “This posting is provided "AS IS" with no warranties, and confers no rights. User assumes all risks.”

    Monday, June 23, 2014 9:29 PM
  • I just double checked and we are not still using the sync.vbs.  Looking at the task scheduler under actions I see the exe is syncappvpublishingserver 1 -NetworkCostAware

    I just logged in under a profile with just 2 apps and here is a screenshot of the time from the task scheduler to the event ID

    Persona is roaming:

    All of HKCU

    All of appdata roaming and appdata local except
    (some of these are 4.6 exclusions but we only currently have 5 installed into this image)

    We are not preloading any of the above roamed, everything comes down on demand.  Beyond that, only settings out of the norm we have changed is the integrationrootuser point -- VMWare has a bug not allowing junction points to be created.  We set it in our VDI pools to C:\AppVirt, and everything works with it being there.
    I'm working on now getting an image set up with UE-V to see if the timing issue goes away.  I'll also setup a physical machine with the App-V 5 client to see if I get different timings there. 

    Let me know if there is anything else I can provide.  Thanks Steve.

    Tuesday, June 24, 2014 12:53 AM
  • Just as an update, I'm seeing essentially the same thing on a physical laptop, even on repeated logins with no publishing changes.

    The task eventid 100 started at 10:45:53AM, and the 19001 eventid doesn't indicate publishing start until 10:47:04AM.
    The 19002 event indicated publishing finished ended 2 seconds later, at 10:47:06.

    Is this 'normal'?  Is this what other users are experiencing?

    PS. Just noticed I have been saying the event ID was 1901/1902.  Its really 19001 and 19002 respectively.

    Tuesday, June 24, 2014 2:57 PM
  • Hello,

    All the scheduled task is doing is firing off an executable file, named;

    SyncAppvPublishingServer.exe

    which is located here;

    C:\Program Files\Microsoft Application Virtualization\Client\

    If you run that manually, how long does it take then?


    Nicke Källén | The Knack| Twitter: @Znackattack

    Tuesday, June 24, 2014 8:47 PM
  • If I run the exe with the exact command line being run from the task;
    SyncAppvPublishingServer.exe 1 -NetworkCostAware
    after login manually, publishing starts immediately.

    I tried disabling the scheduled task and adding a run key with the same command as above, and at login that starts publishing immediately also. 

    I tried exporting the task XML, changing the priority to 1 and importing, with the same delay from task start to publishing start.  I also tried changing some of the settings within the task and no luck.  I'll start doing some procmons, just going to be hard to catch with the task starting at login. 

    Before I do is this definitely not the behavior other people see?  

    Are there any logs for SyncAppvPublishingServer.exe I should be looking at?

    Wednesday, June 25, 2014 2:45 AM
  • Hello,

    All events are logged to the Event log. See this webpage for more info;

    http://blogs.technet.com/b/gladiatormsft/archive/2013/11/13/app-v-on-operational-troubleshooting-of-the-v5-client.aspx

    No, I do not see the same behavior.


    Nicke Källén | The Knack| Twitter: @Znackattack

    Wednesday, June 25, 2014 6:19 PM
  • Is a global sync quick too? Sync-AppvPublishingServer -global

    Steve Thomas, Senior Consultant, Microsoft

    App-V/MED-V/SCVMM/Server App-V/MDOP/AppCompat

    http://blogs.technet.com/gladiatormsft/
    The App-V Team blog: http://blogs.technet.com/appv/
    The MED-V Team Blog: http://blogs.technet.com/medv
    The SCVMM Team blog: http://blogs.technet.com/scvmm/

    “This posting is provided "AS IS" with no warranties, and confers no rights. User assumes all risks.”

    Wednesday, June 25, 2014 6:31 PM
  • Nicke,

    The only logs I have are under MS\AppV\Client\operational, and there is nothing before the 19001.  I'll look at enabling the debug logs and see if there is anything in there... just have to get my hands on an image to enable to logs since I can't reproduce this once I've logged in.

    When I look at the operational logs for task scheduler, there are no warning or errors between the log for creating the task and the task finishing.
    In the normal windows logs, under applications or system, there are no errors/warnings during the time when task starts to publishing end, and nothing at all about the publishing or task.

    Steve,

    We are seeing this on VDIs where global publishing is disabled at logon (we have some with, some without, client settings are GlobalRefreshEnabled = true, GlobalRefreshOnLogon = False, ) but if I run SyncAppvPublishingServer.exe 1 -global (I tried both 1 -global and -global 1, wasn't sure of syntax, but same result), it starts quickly, maybe 1 second before I see the progress bar. 
    Would it be of any help to add the -global to the run key at login and see if that causes any delays?

    I also tried running the task on demand since it is allowed, using
    schtasks /Run /TN \Microsoft\AppV\Publishing\1_user_logon
    and even that works quickly. 

    Think I should re-engage MS on this?

    • Edited by agallucci Wednesday, June 25, 2014 8:24 PM
    Wednesday, June 25, 2014 8:04 PM
  • Last thing to mention... I added a run key to the command to run the task;

    cmd.exe /k schtasks /Run /TN \Microsoft\AppV\Publishing\1_user_logon

    so I can see whats going on, and I get a success from schtasks but the exact same delay I am seeing just letting the task run normally...

    Wednesday, June 25, 2014 8:30 PM
  • Sorry to keep updating... after a lot more trying this and that, all I can point to at all is something with the SyncAppvPublishingServer.exe just doesn't like our environment...

    I wrote a custom exe, that only runs powershell.exe -command sync-appvpublishingserver 1 (with start and end time loggng), named it SyncAppvPublishingServer.exe, and replaced the stock exe.

    Since I can see the powershell window come up, I can easily identify that the current task does work and does kick off the exe in a timely manner, almost immediately after logging in.

    I do see about a 20 - 25 second delay before powershell 'initializes' and the progress bar starts, but guessing that's normal.  If its not or there is anything we can do to improve that great.  I don't know if its a sync command problem or just running something in powershell the first time takes a while.

    I'll start doing procmons next, seeing what could possibly be tripping up the stock exe in our environment.

    Thursday, June 26, 2014 5:41 PM
  • The initial delay might be caused by the fact that some 'initialization' (namely WMI) happens when the first App-V command is launched. 
    I'm not sure if it would help to run 'an' App-V command very early in the logon process, so that things are in place before the scheduled task launches.

    Falko

    Twitter @kirk_tn   |   Blog kirxblog   |   Web kirx.org   |   Fireside appvbook.com

    Friday, June 27, 2014 8:43 AM
    Moderator
  • The initial delay might be caused by the fact that some 'initialization' (namely WMI) happens when the first App-V command is launched. 
    I'm not sure if it would help to run 'an' App-V command very early in the logon process, so that things are in place before the scheduled task launches.

    Falko

    Twitter @kirk_tn   |   Blog kirxblog   |   Web kirx.org   |   Fireside appvbook.com

    To follow up on this, I don't have anything to add why the scheduled task was delaying, but the initial delay we are experiencing running powershell was greatly improved by following what Falko suggested:

    I found adding a runonce/run key doing something in powershell at login was already too late, basically doing it then (at user logon) was running at the same time the exe to sync was.
    However, in VMWare VDIs, you have the ability to run a exe/bat, etc file as soon as the session spins up.  We added this to the .bat file we are running-

    powershell.exe -executionpolicy bypass -command import-module AppVClient ; Import-Module “C:\Program Files\Microsoft Application Virtualization\Client\AppvClient\Microsoft.AppV.AppvClientComConsumer.dll” ; Import-Module “C:\Program Files\Microsoft Application Virtualization\Client\AppvClient\Microsoft.AppV.AppVClientPowerShell.dll” ; Import-Module “C:\Program Files\Microsoft Application Virtualization\Client\AppvClient\Microsoft.AppV.ClientProgrammability.Eventing.dll” ; Get-AppVClientConfiguration

    Some of that is probably overkill, it might be as simple as running the get-appvclientconfiguration, but this has cut down on the delay from 20-30 seconds to about 7-10.

    You could probably create a service that runs at system start (not at logon) that does the same thing.

    I'll come back and update this thread if I get anthing else.

    Friday, July 11, 2014 1:21 PM