What happened to that 4min delay?

[pbsdis]

Hi,

We are digging for a slow installation, which was reported to occur only on Spanish Vista OS (not on English Vista). The log file showed that there is a big time jump (4+ min).

Can anybody explain what happened during the time and how to reduce it or investigate to shorten it?


Thanks



MSI (s) (A0:68) [15:51:17:924]: Executing op: ActionStart(Name=RegisterUser,Description=Registering user,Template=[1])
MSI (s) (A0:68) [15:51:17:924]: Executing op: UserRegister(Owner=Admin,,ProductId=none)
MSI (s) (A0:68) [15:51:17:924]: Executing op: ActionStart(Name=RegisterProduct,Description=Registering product,Template=[1])
MSI (s) (A0:68) [15:51:17:924]: Executing op: ChangeMedia(MediaVolumeLabel=DISK1,MediaPrompt=Please insert the disk: 1,MediaCabinet=Data1.cab,BytesPerTick=0,CopierType=2,ModuleFileName=C:\Windows\Installer\47619.msi,,,,,IsFirstPhysicalMedia=1)
MSI (s) (A0:68) [15:51:17:924]: Executing op: DatabaseCopy(DatabasePath=C:\Windows\Installer\47619.msi,ProductCode={F52E6DC5-E735-4A58-A280-AEA3DED1679F},CabinetStreams=Data1.cab,,)
MSI (s) (A0:68) [15:51:18:080]: Executing op: ProductRegister(UpgradeCode={4EB823EB-27D7-4E7B-9469-961E2B0634D0},VersionString=2.03.26.002.25,HelpLink=www.nvtl.com,,InstallLocation=C:\Program Files\CompName\,InstallSource=C:\Users\Admin\Desktop\NvtlDriverSCRTME_V2.03.26.002MSI\,Publisher=CompName,,,,NoModify=1,NoRepair=1,,,,,,,EstimatedSize=3385,)
MSI (s) (A0:68) [15:51:18:111]: Executing op: ProductCPDisplayInfoRegister()
MSI (s) (A0:68) [15:51:18:111]: Executing op: ActionStart(Name=InstallDrivers32.5F1DC02E_0598_4666_8B42_4C5AA41526BB,,)
MSI (s) (A0:68) [15:51:18:111]: Executing op: CustomActionSchedule(Action=InstallDrivers32.5F1DC02E_0598_4666_8B42_4C5AA41526BB,ActionType=3110,Source=set oShell=createobject("WScript.Shell")
pth=Session.Property("CustomActionData")
oShell.run pth, 0, true,,CustomActionData="C:\Program Files\CompName\Drivers\Setuphelper32.exe" /install 0 /installdir "C:\Program Files\CompName" /relflags GEN_USB_MDM,GEN_USB_NDIS,USB_CD_FILTER,RM_NET_NDIS,ENABLESCR,GEN_USB_SCR,GEN_CDC_NDIS,TME_USB_MBNET)
MSI (s) (A0:9C) [15:51:18:111]: Generating random cookie.
MSI (s) (A0:9C) [15:51:18:126]: Created Custom Action Server with PID 760 (0x2F8).
MSI (s) (A0:DC) [15:51:18:158]: Running as a service.
MSI (s) (A0:DC) [15:51:18:158]: Hello, I'm your 32bit Elevated custom action server.
MSI (s) (A0:68) [15:55:33:522]: Executing op: ActionStart(Name=PublishFeatures,Description=Publishing product features,Template=Feature: [1])
MSI (s) (A0:68) [15:55:33:522]: Executing op: FeaturePublish(Feature=GenUSBInstaller,,Absent=2,Component=ls$,MEa4X9Kf([q63sv9J$rdR,l68=f3HPsdV8D.$nyr+I03X?9FEmUNe{FA6HD@Secyl?38X^4HK34?9[j%aXk6{=9GAQC+'&nfM0+`67MJ]=GH~=w&Nh?2%m+o1I8wQ=[pZr7NR2G1x0*)NfYyc?y.F=J(B{-9@@xce@VEZ8x_zs*vSS@2jQ(4V@OMI=F.(m*WYVJ=N]K&%?71x898P9W-H_Vh!Zk2[eyeo8}3k~*0_4Q'0g1Al7V*t@re8THzMsL%HnAz]nCg@?AFFV=bC+O+%m=2,K$rY8'p%qz6?Pm5u9klX8{xh92tYJ%Vcy31QMA~UM9E{9HO!`9+qVwrzLR_EG!Sj8$aI97IKZh*e'uk?'XuB=KeG,6s,{pT_P4YT9].}9^G64,(VZn3H)=GK,ozj8I^Nwlx8Em,qwj)StaYM9Ru0)Yhu=Jeeo{.Qpb8k?--Y1T)75'8_r4v)CWw8@Cm(2qR4zX0z^iPRzH&^A9TLB*&5*ubO1HkSn`VXAy(kel3}zANsTqZ_bT`7=_xEe=4kf%VYg8UT5~Ec?,?2ge{6{RYx-O%^*XEb?YcvQUAy-^1?Es@u'Y]{?YPm0!riJG(+,tR_UCK*AS6i}JHW=BZ{MhjEcVAF@T]&pt}rS{,v{uwe-T3n=wo-Z@EzZVA)
MSI (s) (A0:68) [15:55:33:522]: Executing op: FeaturePublish(Feature=SmartCardRegKey,,Absent=2,Component=f$_sW{]}H=)zU0Z.7M*t)
MSI (s) (A0:68) [15:55:33:522]: Executing op: ActionStart(Name=PublishProduct,Description=Publishing product information,)
MSI (s) (A0:68) [15:55:33:522]: Executing op: IconCreate(Icon=ARPPRODUCTICON.exe,Data=BinaryData)
MSI (s) (A0:68) [15:55:33:522]: Executing op: CleanupConfigData()

[GetExp]

From the log i can see that the delay is due to a custom action. what is that? is it doing any transaction with the system services?

[pbsdis]

Hi,

Thanks for your reply. Sorry for my late reply - I was occupied by something else.

We did some more investigation on the issue, here are some updates -

First, the issue occurs on Vista in general (32-bit and 64-bit, independent of OS languages).

The CA that cause the delay is a c++ function to install device driver files. The c++ uses Microsoft recommended Difx installation APIs (DriverPackageInstall()). The Difx version is 2.1 provided by Windows DDK.

The issue only occurs at silent mode. Neither full UI nor commandline with 'qb' option have the delay, but commandline with 'qn' option has.

We didn't observe the issue in non-Vista systems either. Could it be the MSI engine version on Vista that causes it?

Any help/hint/suggestion are greatly appreciated, we need to provide explanation and solution to it in short time.


Thanks!

[Stefan_Krueger]

I really don't see why /qn should be different from /qb here. But as GetExp already mentioned, the delay happens in the custom action. Since the DIFx custom actions are coming from Microsoft yu may need to contact them.

[GetExp]

One more thought ... Does the Device Driver installation, seeks any reponse from the user? or any delay occurs during the installation?... I would be interested if we isolate the problem by seperating the DD installation alone with a sample setup (just to analyze) and then find the difference... Will that help?

[Stefan_Krueger]

You could also try SysInternals Proceess Monitor to see if there's a permission problem which might be causing a time-out.