Very slow decompression

[wyzerd]

This problem existed back around version 6 it has returned with 9.7. The installation is taking an extraordinary amount of time without progress indication.

You will find the log file attached that will show the 3GB installation took 21 minutes. this in itself is a problem, but even worse is that there was no indication that it was actually doing anything.

It starts with a full minute of Windows installer is preparing.. then 5 minutes of Training Data estimate installation time of 707464 minutes to complete. then switches to 0 seconds for the remaining 15 minutes.

decompress

decompress.JPG (41.85 KiB) Viewed 8042 times

I've also attached the aip

[Daniel]

Hello,

I'm not sure why you are encountering this behavior. Can you please generate and attach a verbose log of the installation or send it us to support at advancedinstaller dot com so we can investigate it?

All the best,
Daniel

[wyzerd]

Verbose log was 29MB. this forum would not allow upload.

[wyzerd]

Here are some excerpts from the large log file :

=== Verbose logging started: 12/6/2012 16:30:16 Build type: SHIP UNICODE 5.00.7601.00 Calling process: C:\Windows\SysWOW64\msiexec.exe ===
MSI (c) (98:7C) [16:30:16:369]: Font created. Charset: Req=0, Ret=0, Font: Req=MS Shell Dlg, Ret=MS Shell Dlg

MSI (c) (98:7C) [16:30:16:369]: Font created. Charset: Req=0, Ret=0, Font: Req=MS Shell Dlg, Ret=MS Shell Dlg

MSI (c) (98:14) [16:30:16:378]: Resetting cached policy values
MSI (c) (98:14) [16:30:16:378]: Machine policy value 'Debug' is 0
MSI (c) (98:14) [16:30:16:378]: ******* RunEngine:
******* Product: C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\TrainingData.msi
******* Action:
******* CommandLine: **********
MSI (c) (98:14) [16:30:16:384]: Machine policy value 'DisableUserInstalls' is 0
MSI (c) (98:14) [16:30:16:390]: SOFTWARE RESTRICTION POLICY: Verifying package --> 'C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\TrainingData.msi' against software restriction policy
MSI (c) (98:14) [16:30:16:390]: Note: 1: 2262 2: DigitalSignature 3: -2147287038
MSI (c) (98:14) [16:30:16:390]: SOFTWARE RESTRICTION POLICY: C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\TrainingData.msi is not digitally signed
MSI (c) (98:14) [16:30:16:392]: SOFTWARE RESTRICTION POLICY: C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\TrainingData.msi is permitted to run at the 'unrestricted' authorization level.
MSI (c) (98:14) [16:30:16:397]: Cloaking enabled.
MSI (c) (98:14) [16:30:16:397]: Attempting to enable all disabled privileges before calling Install on Server
MSI (c) (98:14) [16:30:16:402]: End dialog not enabled
...
MSI (s) (4C:34) [16:30:24:934]: Executing op: FolderCreate(Folder=C:\Users\Public\Documents\CMS\FocalData\Installation\0~Clinic\tele\,Foreign=0,SecurityDescriptor=BinaryData,)
MSI (s) (4C:34) [16:30:24:935]: Executing op: FolderCreate(Folder=C:\Users\Public\Documents\CMS\FocalData\Installation\1~QA Clinic\tele\,Foreign=0,SecurityDescriptor=BinaryData,)
MSI (s) (4C:34) [16:30:24:936]: Executing op: FolderCreate(Folder=C:\Users\Public\Documents\CMS\FocalData\Installation\3~IMRT Gert\1~IMRTWS06\plan\,Foreign=0,SecurityDescriptor=BinaryData,)
MSI (s) (4C:34) [16:30:24:937]: Executing op: FolderCreate(Folder=C:\Users\Public\Documents\CMS\FocalData\Installation\TrainingClinic\,Foreign=0,SecurityDescriptor=BinaryData,)
MSI (s) (4C:34) [16:30:24:938]: Executing op: ActionStart(Name=AI_ExtractFiles,Description=Extracting files from archive,)
MSI (s) (4C:34) [16:30:24:938]: Executing op: CustomActionSchedule(Action=AI_ExtractFiles,ActionType=1025,Source=BinaryData,Target=ExtractSourceFiles,CustomActionData=\\PC-BuildWin7\Releases\Training Data\3.30.00\Release\Setup.exe)
MSI (s) (4C:F8) [16:30:24:940]: Invoking remote custom action. DLL: C:\Windows\Installer\MSI3C4D.tmp, Entrypoint: ExtractSourceFiles
MSI (s) (4C:34) [16:38:12:822]: Executing op: ActionStart(Name=InstallFiles,Description=Copying new files,Template=File: [1], Directory: [9], Size: [6])
MSI (s) (4C:34) [16:38:12:822]: Executing op: ProgressTotal(Total=-1561828473,Type=0,ByteEquivalent=1)
MSI (s) (4C:34) [16:38:12:823]: Executing op: SetTargetFolder(Folder=C:\Users\Public\Documents\CMS\FocalData\ImrtTemplates\)
MSI (s) (4C:34) [16:38:12:823]: Executing op: SetSourceFolder(Folder=1\ImrtTe~1\|ImrtTemplates\)
MSI (s) (4C:34) [16:38:12:823]: Executing op: ChangeMedia(,MediaPrompt=Please insert the disk: ,,BytesPerTick=65536,CopierType=0,,,,,,IsFirstPhysicalMedia=1)
MSI (s) (4C:34) [16:38:12:823]: Executing op: FileCopy(SourceName=VMATTr~1.xml|VMATTraining.dosenormsettings.xml,SourceCabKey=VMATTraining.dosenormsettings.xml,DestName=VMATTraining.dosenormsettings.xml,Attributes=0,FileSize=5848,PerTick=65536,,VerifyMedia=1,,,,,CheckCRC=0,,,InstallMode=58982400,,,,,,,)
MSI (s) (4C:34) [16:38:12:823]: File: C:\Users\Public\Documents\CMS\FocalData\ImrtTemplates\VMATTraining.dosenormsettings.xml; To be installed; Won't patch; No existing file
MSI (s) (4C:34) [16:38:12:831]: Source for file 'VMATTraining.dosenormsettings.xml' is uncompressed, at 'C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\ImrtTemplates\'.
MSI (s) (4C:34) [16:38:12:844]: Executing op: FileCopy(SourceName=VMATTr~2.xml|VMATTraining.dvhparam.xml,SourceCabKey=VMATTraining.dvhparam.xml,DestName=VMATTraining.dvhparam.xml,Attributes=0,FileSize=700,PerTick=65536,,VerifyMedia=1,,,,,CheckCRC=0,,,InstallMode=58982400,,,,,,,)
...
Property(C): StartMenuFolder = C:\ProgramData\Microsoft\Windows\Start Menu\
Property(C): DesktopFolder = C:\Users\Public\Desktop\
Property(C): FontsFolder = C:\Windows\Fonts\
Property(C): GPTSupport = 1
Property(C): OLEAdvtSupport = 1
Property(C): ShellAdvtSupport = 1
Property(C): MsiAMD64 = 6
Property(C): Msix64 = 6
Property(C): PhysicalMemory = 8191
Property(C): VirtualMemory = 13695
Property(C): AdminUser = 1
Property(C): MsiTrueAdminUser = 1
Property(C): LogonUser = jenkinsb
Property(C): UserSID = S-1-5-21-2081705121-2112817753-1734353810-12368
Property(C): UserLanguageID = 1033
Property(C): ComputerName = PCVAL30
Property(C): SystemLanguageID = 1033
Property(C): ScreenX = 1528
Property(C): ScreenY = 915
Property(C): CaptionHeight = 19
Property(C): BorderTop = 1
Property(C): BorderSide = 1
Property(C): TextHeight = 16
Property(C): TextInternalLeading = 3
Property(C): ColorBits = 16
Property(C): TTCSupport = 1
Property(C): Time = 16:49:44
Property(C): Date = 12/6/2012
Property(C): MsiNetAssemblySupport = 4.0.30319.1
Property(C): MsiWin32AssemblySupport = 6.1.7601.17514
Property(C): MsiRunningElevated = 1
Property(C): Privileged = 1
Property(C): USERNAME = pcavl30
Property(C): DATABASE = C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\TrainingData.msi
Property(C): OriginalDatabase = C:\ProgramData\CMS\Install\Verify\Cache\Elekta Training Data\2578EAA\TrainingData.msi
Property(C): UILevel = 3
Property(C): ACTION = INSTALL
=== Logging stopped: 12/6/2012 16:49:44 ===
MSI (c) (98:14) [16:49:44:076]: Note: 1: 1707
MSI (c) (98:14) [16:49:44:076]: Product: Elekta Training Data -- Installation completed successfully.

MSI (c) (98:14) [16:49:44:077]: Windows Installer installed the product. Product Name: Elekta Training Data. Product Version: 3.30.00. Product Language: 1033. Manufacturer: Elekta Software. Installation success or error status: 0.

MSI (c) (98:14) [16:49:44:107]: Grabbed execution mutex.
MSI (c) (98:14) [16:49:44:107]: Cleaning up uninstalled install packages, if any exist
MSI (c) (98:14) [16:49:44:108]: MainEngineThread is returning 0
=== Verbose logging stopped: 12/6/2012 16:49:44 ===

291.73Days.JPG (14.55 KiB) Viewed 8024 times

last 10 minutes of the install

decompress.JPG (13.44 KiB) Viewed 8024 times

This was from a brand new installation package created in 9.7 instead of the updated one I used last time.

[wyzerd]

I used the new install on another machine to see if it would help.

At first it gave this:

decompress.JPG (15.16 KiB) Viewed 8024 times

Then went to 182 Minutes after about 10 minutes then to a more accurate reading when about 5 minutes were left.

[wyzerd]

I still don't have all the details needed to make the call on exactly what causes this problem. I have noticed that the amount of data in this product had doubled since the last release.

I suspect, 7z does some very odd caching and it is causing a disk swap once memory is exhausted. Changing the mechanism from LZMA to CAB and One CAB per feature, did fix the issue for the time being. (I also checked Compress CAB files.)

[Daniel]

Hello,

I'm afraid this is a Windows Installer behavior. Please keep in mind that we are using Windows Installer API functions for time remaining estimation. Also, regarding the archive type (CAB or using LZMA compression) there should be no difference during a first time install between their time remaining estimation because when using LZMA compression the files extraction is performed before the installation starts.

All the best,
Daniel

[wyzerd]

Yes, I am sure that LZMA is not the root cause of the problem, but since that one file was allowed to grow to over 2GB, I suspect that is what caused memory saturation and disk swap. CAB didn't really fix the problem, the part that reall fixed it was the seperation of the compressed bits into smaller files. By stretching these into 5 or so files, it was able to complete decompression without having to resort to disk swap. If LZMA could be modified to limit size for an individual file, the performance would be greatly enhanced.