Jump to content


This is a ready-only archive of the InstallSite Forum. You cannot post any new content here. / Dies ist ein Archiv des InstallSite Forums. Hier können keine neuen Beiträge veröffentlicht werden.
Photo

What goes inside InstallFiles action


5 replies to this topic

tktk

tktk
  • Full Members
  • 24 posts

Posted 04 July 2006 - 13:03

Hello all,

I have an installer that takes relatively long time to complete, and planning new version of the product. I want new installer will reduce installation time.

I have checked the installer's performance from WindowsInstaller log and found InstallFiles action account for 80% of whole installation time.

I think the major problem is that the installer has too many components (about 3000). From help in MSDN, I guess InstallFiles action checks whether the component should be installed or not, then extracts the files from cab file and copy them to local disk.

I'm planning to reduce the number of components to contain several related files (yes, the component contains one or two files in one component currently, that is not my design!).
# Plz do not concern about upgrade now

But I'm not sure this will improve the performance of installation. So my questions are:
1) How do you think about this idea?
2) What is actually going Inside InstallFiles action?

any suggetion would be greatly appreciated,
Thank you.


Zweitze

Zweitze
  • Full Members
  • 522 posts

Posted 04 July 2006 - 19:19

I recall that log files also show timing information (start an finish time of every action), better create some sample logs to figure out what action is really taking up so much time.


tktk

tktk
  • Full Members
  • 24 posts

Posted 05 July 2006 - 09:35

Hi Zweitze, thank you for the reply.

Yes, I had checked the log file and confirmed the most time consuming action as InstallFiles.

I have extracted the lines containing time stamp from the log (some part of the log is written in Japanese). We can read from the log that the total time of installation is 9:56 and InstallFiles action consumes 8:20.

Thank you.

============================================
=== Verbose logging started: 2006/07/04 18:45:02 Build type: SHIP UNICODE 2.00.2600.1183 Calling process: C:\DOCUME~1\xxxxxx\setup.exe ===
=== ログ開始 : 2006/07/04 18:45:09 ===
Action start 18:45:09 : INSTALL.
Action start 18:45:09 : AppSearch.
Action 18:45:09: AppSearch. インストールされているアプリケーションを検索しています
Action ended 18:45:09 : AppSearch. Return value 1.
Action start 18:45:09 : LaunchConditions.
Action ended 18:45:09 : LaunchConditions. Return value 1.
Action start 18:45:09 : CustomAction xxxxxx.
Action ended 18:45:09 : CustomAction xxxxxx. Return value 1.
Action start 18:45:09 : SetupInitialization.
Action 18:45:10: SetupInitialization. Dialog created
Action ended 18:45:10 : SetupInitialization. Return value 1.
Action start 18:45:10 : FindRelatedProducts.
Action ended 18:45:10 : FindRelatedProducts. Return value 1.
Action start 18:45:10 : ValidateProductID.
Action ended 18:45:10 : ValidateProductID. Return value 1.
Action start 18:45:10 : CustomAction xxxxxx.
Action ended 18:45:10 : CustomAction xxxxxx. Return value 1.
Action start 18:45:10 : CustomAction xxxxxx.
Action ended 18:45:10 : CustomAction xxxxxx. Return value 1.
Action start 18:45:10 : CostInitialize.
Action ended 18:45:10 : CostInitialize. Return value 1.
Action start 18:45:10 : FileCost.
Action ended 18:45:10 : FileCost. Return value 1.
Action start 18:45:10 : IsolateComponents.
Action ended 18:45:10 : IsolateComponents. Return value 1.
Action start 18:45:10 : setUserProfileNT.
Action ended 18:45:10 : setUserProfileNT. Return value 1.
Action start 18:45:10 : setAllUsersProfile2K.
Action ended 18:45:10 : setAllUsersProfile2K. Return value 1.
Action start 18:45:10 : ResolveSource.
Action ended 18:45:10 : ResolveSource. Return value 1.
Action start 18:45:10 : CostFinalize.
Action ended 18:45:11 : CostFinalize. Return value 1.
Action start 18:45:11 : MigrateFeatureStates.
Action ended 18:45:11 : MigrateFeatureStates. Return value 0.
Action start 18:45:11 : CustomAction xxxxxx.
Action ended 18:45:11 : CustomAction xxxxxx. Return value 1.
Action start 18:45:11 : InstallWelcome.
Action 18:45:11: InstallWelcome. Dialog created
Action 18:45:12: LicenseAgreement. Dialog created
Action 18:45:14: DestinationFolder. Dialog created
Action 18:45:15: SetupType. Dialog created
Action 18:45:18: ReadyToInstall. Dialog created
Action ended 18:45:19 : InstallWelcome. Return value 1.
Action start 18:45:19 : SetupProgress.
Action 18:45:19: SetupProgress. Dialog created
Action ended 18:45:19 : SetupProgress. Return value 1.
Action start 18:45:19 : ExecuteAction.
Action start 18:45:21 : INSTALL.
Action start 18:45:21 : CustomAction xxxxxx.
Action ended 18:45:21 : CustomAction xxxxxx. Return value 1.
Action start 18:45:21 : AppSearch.
Action ended 18:45:22 : AppSearch. Return value 0.
Action start 18:45:22 : LaunchConditions.
Action ended 18:45:22 : LaunchConditions. Return value 1.
Action start 18:45:22 : FindRelatedProducts.
Action ended 18:45:22 : FindRelatedProducts. Return value 0.
Action start 18:45:22 : ValidateProductID.
Action ended 18:45:22 : ValidateProductID. Return value 1.
Action start 18:45:22 : CustomAction xxxxxx.
Action ended 18:45:22 : CustomAction xxxxxx. Return value 1.
Action start 18:45:22 : CustomAction xxxxxx.
Action ended 18:45:22 : CustomAction xxxxxx. Return value 1.
Action start 18:45:22 : CustomAction xxxxxx.
Action ended 18:45:22 : CustomAction xxxxxx. Return value 1.
Action start 18:45:22 : CustomAction xxxxxx.
Action ended 18:45:22 : CustomAction xxxxxx. Return value 1.
Action start 18:45:22 : CustomAction xxxxxx.
Action ended 18:45:22 : CustomAction xxxxxx. Return value 1.
Action start 18:45:22 : CostInitialize.
Action ended 18:45:22 : CostInitialize. Return value 1.
Action start 18:45:22 : FileCost.
Action ended 18:45:22 : FileCost. Return value 1.
Action start 18:45:22 : IsolateComponents.
Action ended 18:45:22 : IsolateComponents. Return value 1.
Action start 18:45:22 : CostFinalize.
Action ended 18:45:23 : CostFinalize. Return value 1.
Action start 18:45:23 : SetARPINSTALLLOCATION.
Action ended 18:45:23 : SetARPINSTALLLOCATION. Return value 1.
Action start 18:45:23 : SetODBCFolders.
Action ended 18:45:23 : SetODBCFolders. Return value 1.
Action start 18:45:23 : MigrateFeatureStates.
Action ended 18:45:23 : MigrateFeatureStates. Return value 0.
Action start 18:45:23 : InstallValidate.
Action ended 18:45:32 : InstallValidate. Return value 1.
Action start 18:45:32 : InstallInitialize.
Action ended 18:45:33 : InstallInitialize. Return value 1.
Action start 18:45:33 : RemoveExistingProducts.
Action ended 18:45:33 : RemoveExistingProducts. Return value 1.
Action start 18:45:33 : CustomAction xxxxxx.
Action 18:45:33: GenerateScript. Actionに対するスクリプト オペレーションを生成しています :
Action ended 18:45:34 : CustomAction xxxxxx. Return value 1.
Action start 18:45:34 : AllocateRegistrySpace.
Action ended 18:45:34 : AllocateRegistrySpace. Return value 1.
Action start 18:45:34 : ProcessComponents.
Action ended 18:45:34 : ProcessComponents. Return value 1.
Action start 18:45:34 : UnpublishComponents.
Action ended 18:45:34 : UnpublishComponents. Return value 1.
Action start 18:45:34 : MsiUnpublishAssemblies.
Action ended 18:45:34 : MsiUnpublishAssemblies. Return value 1.
Action start 18:45:34 : UnpublishFeatures.
Action ended 18:45:34 : UnpublishFeatures. Return value 1.
Action start 18:45:34 : StopServices.
Action ended 18:45:34 : StopServices. Return value 1.
Action start 18:45:34 : DeleteServices.
Action ended 18:45:34 : DeleteServices. Return value 1.
Action start 18:45:34 : UnregisterComPlus.
Action ended 18:45:34 : UnregisterComPlus. Return value 1.
Action start 18:45:34 : SelfUnregModules.
Action ended 18:45:34 : SelfUnregModules. Return value 1.
Action start 18:45:34 : UnregisterTypeLibraries.
Action ended 18:45:34 : UnregisterTypeLibraries. Return value 1.
Action start 18:45:34 : RemoveODBC.
Action ended 18:45:34 : RemoveODBC. Return value 1.
Action start 18:45:34 : UnregisterFonts.
Action ended 18:45:34 : UnregisterFonts. Return value 1.
Action start 18:45:34 : RemoveRegistryValues.
Action ended 18:45:34 : RemoveRegistryValues. Return value 1.
Action start 18:45:34 : UnregisterClassInfo.
Action ended 18:45:34 : UnregisterClassInfo. Return value 1.
Action start 18:45:34 : UnregisterExtensionInfo.
Action ended 18:45:34 : UnregisterExtensionInfo. Return value 1.
Action start 18:45:34 : UnregisterProgIdInfo.
Action ended 18:45:34 : UnregisterProgIdInfo. Return value 1.
Action start 18:45:34 : UnregisterMIMEInfo.
Action ended 18:45:34 : UnregisterMIMEInfo. Return value 1.
Action start 18:45:34 : RemoveIniValues.
Action ended 18:45:34 : RemoveIniValues. Return value 1.
Action start 18:45:34 : RemoveShortcuts.
Action ended 18:45:34 : RemoveShortcuts. Return value 1.
Action start 18:45:34 : RemoveEnvironmentStrings.
Action ended 18:45:34 : RemoveEnvironmentStrings. Return value 1.
Action start 18:45:34 : RemoveDuplicateFiles.
Action ended 18:45:34 : RemoveDuplicateFiles. Return value 1.
Action start 18:45:34 : RemoveFiles.
Action ended 18:45:34 : RemoveFiles. Return value 1.
Action start 18:45:34 : RemoveFolders.
Action ended 18:45:34 : RemoveFolders. Return value 1.
Action start 18:45:34 : CreateFolders.
Action ended 18:45:34 : CreateFolders. Return value 1.
Action start 18:45:34 : MoveFiles.
Action ended 18:45:34 : MoveFiles. Return value 1.
Action start 18:45:34 : InstallFiles.
Action ended 18:45:36 : InstallFiles. Return value 1.
Action start 18:45:36 : PatchFiles.
Action ended 18:45:36 : PatchFiles. Return value 1.
Action start 18:45:36 : DuplicateFiles.
Action ended 18:45:36 : DuplicateFiles. Return value 1.
Action start 18:45:36 : BindImage.
Action ended 18:45:36 : BindImage. Return value 1.
Action start 18:45:36 : CreateShortcuts.
Action ended 18:45:36 : CreateShortcuts. Return value 1.
Action start 18:45:36 : RegisterClassInfo.
Action ended 18:45:36 : RegisterClassInfo. Return value 1.
Action start 18:45:36 : RegisterExtensionInfo.
Action ended 18:45:36 : RegisterExtensionInfo. Return value 1.
Action start 18:45:36 : RegisterProgIdInfo.
Action ended 18:45:36 : RegisterProgIdInfo. Return value 1.
Action start 18:45:36 : RegisterMIMEInfo.
Action ended 18:45:36 : RegisterMIMEInfo. Return value 1.
Action start 18:45:36 : WriteRegistryValues.
Action ended 18:45:36 : WriteRegistryValues. Return value 1.
Action start 18:45:36 : WriteIniValues.
Action ended 18:45:36 : WriteIniValues. Return value 1.
Action start 18:45:36 : WriteEnvironmentStrings.
Action ended 18:45:36 : WriteEnvironmentStrings. Return value 1.
Action start 18:45:36 : CustomAction xxxxxx.
Action ended 18:45:36 : CustomAction xxxxxx. Return value 1.
Action start 18:45:36 : RegisterFonts.
Action ended 18:45:36 : RegisterFonts. Return value 1.
Action start 18:45:36 : InstallODBC.
Action ended 18:45:36 : InstallODBC. Return value 0.
Action start 18:45:36 : RegisterTypeLibraries.
Action ended 18:45:36 : RegisterTypeLibraries. Return value 1.
Action start 18:45:36 : SelfRegModules.
Action ended 18:45:36 : SelfRegModules. Return value 1.
Action start 18:45:36 : RegisterComPlus.
Action ended 18:45:36 : RegisterComPlus. Return value 1.
Action start 18:45:36 : InstallServices.
Action ended 18:45:36 : InstallServices. Return value 1.
Action start 18:45:36 : StartServices.
Action ended 18:45:36 : StartServices. Return value 1.
Action start 18:45:36 : RegisterUser.
Action ended 18:45:36 : RegisterUser. Return value 1.
Action start 18:45:36 : RegisterProduct.
Action ended 18:45:36 : RegisterProduct. Return value 1.
Action start 18:45:36 : PublishComponents.
Action ended 18:45:36 : PublishComponents. Return value 1.
Action start 18:45:36 : MsiPublishAssemblies.
Action ended 18:45:36 : MsiPublishAssemblies. Return value 1.
Action start 18:45:36 : PublishFeatures.
Action ended 18:45:36 : PublishFeatures. Return value 1.
Action start 18:45:36 : PublishProduct.
Action ended 18:45:36 : PublishProduct. Return value 1.
Action start 18:45:36 : InstallExecute.
Action 18:45:36: CustomAction xxxxxx.
Action 18:45:36: ProcessComponents. コンポーネントの登録を更新しています
Action 18:45:51: RemoveODBC. ODBC コンポーネントを削除しています
Action 18:45:51: CreateFolders. フォルダを作成しています
Action 18:45:51: MoveFiles. ファイルを移動しています
Action 18:45:51: InstallFiles. 新しいファイルをコピーしています
Action 18:54:11: CreateShortcuts. ショートカットを作成しています
Action 18:54:12: RegisterClassInfo. クラス サーバーを登録しています
Action 18:54:12: RegisterExtensionInfo. エクステンション サーバーを登録しています
Action 18:54:12: RegisterProgIdInfo. プログラム識別子の登録を解除しています
Action 18:54:12: WriteRegistryValues. システム レジストリの値を書き込んでいます
Action 18:54:12: CustomAction xxxxxx.
Action 18:54:12: RegisterFonts. フォントを登録しています
Action 18:54:25: RegisterTypeLibraries. タイプ ライブラリを登録しています
Action 18:54:25: RegisterUser. ユーザーを登録しています
Action 18:54:25: RegisterProduct. 製品を登録しています
Action 18:54:29: PublishFeatures. 製品機能を発行しています
Action 18:54:54: PublishProduct. 製品情報を発行しています
Action ended 18:54:54 : InstallExecute. Return value 1.
Action start 18:54:54 : InstallFinalize.
Action 18:54:54: RollbackCleanup. バックアップ ファイルを削除しています
Action ended 18:54:54 : InstallFinalize. Return value 1.
Action ended 18:54:54 : INSTALL. Return value 1.
Property(S): Time = 18:54:55
Action ended 18:54:55 : ExecuteAction. Return value 1.
Action start 18:54:55 : SetupCompleteSuccess.
Action 18:54:55: SetupCompleteSuccess. Dialog created
Action ended 18:54:57 : SetupCompleteSuccess. Return value 2.
Action ended 18:54:57 : INSTALL. Return value 1.
Property©: Time = 18:54:58
=== ログ終了 : 2006/07/04 18:54:58 ===
=== Verbose logging stopped: 2006/07/04 18:54:58 ===


Stefan Krueger

Stefan Krueger

    InstallSite.org

  • Administrators
  • 13,269 posts

Posted 06 July 2006 - 17:31

Do those files already exist on the target machine or are you installing in an empty folder. The first would take longer because Windows Istaller creates backup copies of all files it overwrites.

Zweitze

Zweitze
  • Full Members
  • 522 posts

Posted 06 July 2006 - 23:07

You could look at property DISABLEROLLBACKS and see if that helps, although you really shouldn't.
Maybe the target disk is fragmented, or has less than 15% free? (NTFS gets very slow in that situation).

tktk

tktk
  • Full Members
  • 24 posts

Posted 10 July 2006 - 02:44

Hi Stefan and Zweitze,

Stefan said:
QUOTE
Do those files already exist on the target machine or are you installing in an empty folder. The first would take longer because Windows Istaller creates backup copies of all files it overwrites.

No, it is new installation so any files does not exist before installation.

Zweitze said:
QUOTE
You could look at property DISABLEROLLBACKS and see if that helps, although you really shouldn't.
Maybe the target disk is fragmented, or has less than 15% free? (NTFS gets very slow in that situation).

DISABLEROLLBACK is not enabled. Here is fragment from the same log file:
MSI © (F0:98): Machine policy value 'DisableRollback' is 0
MSI © (F0:98): User policy value 'DisableRollback' is 0

And target disk is indeed fragmented by 39% and free space is 11%. Can you tell me the source of that, NTFS gets very slow..., information?

I feel grateful for your help but now I would like to clarify my point in question. I think the cause of the low performance of the installation is not the target environment but the structure, or design of the installer itself.

The number of components is so large and if I could reduce it, it could (or could not) reduce the time of installation, I think. So I have asked what is going inside InstallFiles action.

For example, if the extraction of files from cab file is performed by component unit, it could reduce tha time if the component number is small even if whole number of files to be installed is the same.

best regards.