lamprizzle
16th January 2007 20:56 UTC

WriteUninstaller is sometimes slow
I've been using NSIS for a while and I feel like I'm pretty good at it, but here's a stumper.

I'm writing installers for games that range anywhere from 6 to 50 MB (before compression). I was getting reports that games were taking a long time to install, but only SOMETIMES (which is the really weird part), so I put some logs in there and found that the WriteUninstaller command was taking 3-5 minutes to complete on these long ones, whereas on a usual run it only takes 3-5 seconds. Any ideas on what would cause WriteUninstaller to SOMETIMES take so much longer to complete?

I tried looking at the source code to figure out what WriteUninstaller is doing that would sometimes be slow, but that's really difficult.

One unfortunate thing is that I'm dealing with a very lightly customized NSIS 2.06 or 2.07, which I haven't been able to upgrade, but our customizations shouldn't affect WriteUninstaller and I don't see anything in the release notes about any fix that has increased the efficiency of WriteUninstaller.

Some other things I've thought of but have no idea if they are factors:

- does the position of the WriteUninstaller call matter? Mine is about 1/3 of the way down the script and in fact occurs in a function after the Uninstall section.

- the game NSIS installer is being called by a parent NSIS installer.

- lzma compression

- we're using a customer plugin to show some HTML UI

- I use some un. functions during uninstallation.

There are a million things I could think up that could cause WriteUninstaller to be slow, but I can't figure out why it would only be slow SOMETIMES...and REALLY slow!

kichik
16th January 2007 21:04 UTC

If it only happens on some computers, I'd say it's an anti-virus. Sometimes, they like messing with files, especially executable files.

Red Wine
16th January 2007 21:08 UTC

EDIT: kichik is faster than me :)

There are a million things I could think up that could cause WriteUninstaller to be slow, but I can't figure out why it would only be slow SOMETIMES...and REALLY slow!

lamprizzle
17th January 2007 15:29 UTC

That was one of the things I thought of at first, too. But my customer is an OEM who is running my installers in an auto-build system. They claim that there is no anti-virus active.

It's strange that it would take so long to write uninstall.exe, yet extracting .exe's that are in the archive itself (using the "File" command) is quick, even for much bigger files. How would Windows even know the difference?

Red Wine
17th January 2007 16:18 UTC

Since this is not an AV issue, I'd suggest if is possible build your application with the advanced logging nsis build and ask your customer send you the installation details.

http://nsis.sourceforge.net/Special_Builds

Comperio
18th January 2007 01:41 UTC

One thing that I've run into several times before:
Most all A/V programs have a "real-time" scanning feature. Most also all the user the option to "disable" the feature. However, on a few, even though the user disables it, it's not truly really disabled--it more or less just suppresses any warnings. (From my experience, McAfee is the worst offender, but I've also seen it with others as well.)

So when your client claims "there is no anti-virus active" it probably means that they have simply tried to disable the real-time scanning feature. As a test to this, you might even try to uninstall the A/V software completely on the problem PC and see if you still have issues.

lamprizzle
6th February 2007 12:25 UTC

Thanks all for the replies, but I'm still stumped. I'm on-site now trying to figure this out.

It's not antivirus that's causing it, because they made a test dash that includes minimal other software (no AV).

I've put some logging into NSIS and got some outputs. It appears that the culprit is the call to GetCompressedDataFromDataBlockToMemory. See attached, where I've include the NSIS source code (so you can see where I've added logging) and a portion of the resulting log file. Note that I've added ms (milliseconds) to the logging.

GetCompressedDataFromDataBlockToMemory takes over 130 seconds on this failed run when it usually takes under 10.

Don't know what to do next...

kichik
6th February 2007 21:38 UTC

If no AV or other software is used, then the only reason I can find is solid compression. The uninstaller data is saved at the end of the installer's block. That means the when using solid compression installer has to decompress all of its data before it gets to the uninstaller data. That could take a while. You can smoothen it out by using WriteUninstaller at the end of the installer. But that won't help too much because the decompression will happen at some point anyway... Solid compression was the default for lzma in verseion 2.06. In version 2.07, you had to explicitly select solid compression.

However, you said it only happens sometimes and that the entire installation takes longer, so that doesn't seem like the problem.

_dodecomp (the function GetCompressedDataFromDataBlockToMemory actually calls) does some GUI work to update the progress. I'd add some logging around that piece of codem if I were you. The decompression process itself is pretty much deterministic aside from the I/O. But the computer had I/O problems, you would had have seen it in other places as well.

kichik
4th March 2007 19:24 UTC

Any news on this issue?

lamprizzle
5th March 2007 17:50 UTC

Thanks for checking in again.

My next step has been to simply reproduce the issue 100%, which I still can not do. No amount of debugging will help unless I know I can make the problem happen and no amount of fixing will help until I can be certain that my fix actually fixed it!

Additionally, if the partner finds themselves in a situation where they're not seeing it anymore, then I'm not worried about it. I'll definitely keep you "posted" if I find out more.

lamprizzle
23rd March 2007 17:39 UTC

Now I'm stuck. I've tried to do some additional logging using log_printf inside _dodecomp but NSIS crashes. I'm wondering if _dodecomp is called from somewhere else early enough to where logging is not ready yet.

kichik
23rd March 2007 18:02 UTC

Yes, it's called before the headers are loaded to decompress the headers. log_write, however, should be able to handle that. It doesn't touch the log if g_log_file isn't set or until log_dolog is set. If you can get the specifics on what's causing it to crash, that'd be great. If not, don't start logging until g_header is set.

lamprizzle
5th April 2007 19:40 UTC

Thanks kichik. I went the dumb route and just slapped if(g_header) in front of all my logging. So I was able to get the _dodecomp logging to work.

After 6 runs from the same image, I was finally able to get a failure. It looks like the SetFilePointer call in _dodecomp is taking 97 seconds. I've attached a file that contains a snippet of source code (to show where I've logged) and a snippet of the output log for the failure.

Hopefully that gives us a clue. My main goal here is try to figure out a way to reproduce it 100%, because it is very painful getting a failure to happen, and when it does, we may or may not have all the logging we need to figure out the problem.

kichik
8th April 2007 16:22 UTC

__ensuredata is quite a heavy function which does the actual decompression. I'd be very surprised to find out it's SetFilePointer and not __ensuredata that comes right after it without a log call between them.

lamprizzle
12th April 2007 22:07 UTC

You're right...it is the __ensuredata function. I've attached another log that shows how many times this function iterates. Is it normal to iterate so many times? Is there something I can do to the test system to MAKE it slow down like this every time? Remember, I'm only seeing it slow down SOMEtimes - same computer, same software.

Thanks,

Mark

kichik
13th April 2007 12:20 UTC

It's decompressing almost 30mb... Of course it'd take that long. This definitly means the cause is the solid compression. The compressed uninstaller icon data is located at the end of the compressed data block. When you call WriteUninstaller and it tries to get that data, it has to first decompress the rest of the data.

If it only happens sometimes it's probably because your script sometimes skips extracting the rest of the files. Maybe because it has identified the data is already there or because WriteUninstaller is called before anything else but something that only gets extracted sometime like a plug-in.

lamprizzle
19th April 2007 15:51 UTC

Let me clarify what I mean by "sometimes." Here are my test steps:

1. format hard drive (main drive, C:)
2. boot from flash drive
3. "apply" an ImageX disk image to C: that was captured in the factory from our OEM partner and is in a state where it's ready to start preinstalling software silently
4. reboot and let the preinstall begin

Sometimes game uninstallers take a long to time to write, sometimes they don't...and I'm running these tests on the same machine every time. That means any variation in execution logic that you're concerned about would have to come from variations in step 3, which would be hard to believe.

Anyway, I did some more researching to figure out which versions of NSIS we started developing from, and it looked like it was the release of 2.0 (I was wrong above) or maybe even the release candidate before that, which means solid compression was still the default.

Another tidbit...I call WriteUninstaller before extracting any of the other program files, just so it's there in case installation doesn't finish for some reason.

So, do you think I'd have a better chance of fixing this by a) upgrading our base NSIS and not using solid compression or by b) moving my call to WriteUninstaller to happen after all the other files are extracted?

But if I'm going to convince myself that I actually fixed this problem, I'm going to need to be able to reproduce it 100%, which I still cannot do. I wonder if there could be some kind of processor timing inconsistencies or something.

Thanks for your diligence kichik.

kichik
19th April 2007 18:40 UTC

Then lets reproduce it before choosing the solution. If you want a temporary solution, I believe either (a) or (b) will work.

When this doesn't happen, does it still decompress 30mb? You can see how much it's going to decompress in the needed=X log line. It shows the number of required bytes.

lamprizzle
19th April 2007 19:56 UTC

I've attached another zip containing three files:

"fast writeuninstaller - ensuredata logging.txt" is the same log as you've seen before, but on a test run where this uninstaller writing only took about 15 seconds. The needed number of bytes you requested looks like it's the same.

"fast - no timestamp.txt" and "slow - no timestamp.txt" are the same logs as you've seen before, where the slow run took a long time and the fast run acted normally, but I stripped out the timestamp so that they can be diff'ed easily.

The only diffs I see are verify_time values, which makes sense, seeker values (I'm not sure what that is but it doesn't seem like something that should vary), and the value of filebuf (where I'm obviously logging it in the wrong data format...but should it vary?)

kichik
19th April 2007 20:47 UTC

Veresion 2.0 and earlier still used threads for the lzma implementation. That should explain everything. It's a timing issue due to a bug in the earlier betas or even a bug in the final implementation used in 2.0. In any case, newer versions use a state machine so there are no synchronization issues of any kind. Upgrading should definitly solve this problem in this case.

lamprizzle
6th June 2007 02:51 UTC

That was it. I updated to a newer NSIS base, implemented all of our customizations, and now I haven't seen the slowdown in 20 straight iterations (whereas before I would see it approximately 1 in 8 times). Thanks kichik!

oborstad
8th June 2007 17:40 UTC

Another alternative would be to write a small installer that creates the uninstaller as it's only thing to do. We ended up doing this as a solution to being able to provide a stand alone uninstaller from the root of the disk (and downloadable).

Owen.