bzr.exe has long startup on Vista with Sophos antivirus monitor

[Paul Pelzl]

The bzr 1.0 standalone installer yields a bzr installation that can perform very poorly on Windows Vista. Any bzr command, even "bzr help", takes about two minutes to complete on a modern PC.

When a command is executed, bzr produces no output for a long period of time. In the task manager, I can see that bzr.exe CPU usage is near zero. The memory usage increases very slowly to about 10MB, and then suddenly the command begins execution with performance comparable to what I have seen on Windows XP boxes.

Using the Python 2.5-based installer on Vista, there were no performance problems.

My working theory is that this is a manifestation of a Vista bug that leads to extremely slow zip archive extraction:
http://www.google.com/search?q=vista+zip+slow
Extracting "library.zip" from the installation directory using WinAce is also extremely slow (curiously, it completes very quickly if library.exe is copied outside of the Program Files tree and extracted from a different location).

[Alexander Belchenko (bialix)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Paul Pelzl пишет:
| The bzr 1.0 standalone installer yields a bzr installation that can
| perform very poorly on Windows Vista. Any bzr command, even "bzr help",
| takes about two minutes to complete on a modern PC.

I think it's too long.

| When a command is executed, bzr produces no output for a long period of
| time. In the task manager, I can see that bzr.exe CPU usage is near
| zero. The memory usage increases very slowly to about 10MB, and then
| suddenly the command begins execution with performance comparable to
| what I have seen on Windows XP boxes.

So you think there is slow startup?

| Using the Python 2.5-based installer on Vista, there were no performance
| problems.

Good to know.

| My working theory is that this is a manifestation of a Vista bug that leads to extremely slow zip
archive extraction:
| http://www.google.com/search?q=vista+zip+slow

Actually we don't use built-in Vista support for extracting zip files. bzr.exe is used builtin
gzip library. I don't know though on which system dll it depends.
All rants about Vista unzip slowness related to built-in Vista unzip.
I want to note it again: we don't use built-in unzip. bzr.exe has its own unzip inside.

| Extracting "library.zip" from the installation directory using WinAce is also extremely slow
(curiously, it completes very quickly if library.exe is copied outside of the Program Files tree and
extracted from a different location).

That leads me to conclusion that Vista has some weird policy re Program Files folder.
May be some sort of security/viruses protection.
Also our bzr.exe does not use XP Manifest declaration. May be we should finally add it.

Paul, can you check my thoughts about Program Files policy by reinstalling bzr.exe outside of
Program Files in any other folder, e.g. to C:\Bazaar\ and then check performance again.

Also you could use my utility timeit[1] for measuring actual execution time.
(I recommend to use `bzr rocks` command for testing).
Use it in this manner:

timeit bzr rocks

(i.e. just prepend timeit to usual bzr invokation).

I don't have Vista box around but may be on the next week I'll have the chance to
install and run bzr.exe on Vista notebook of my big boss.

Also I'd like to see output of bzr import profiler. Just run any command
with global flag --profile-imports and then show us results. E.g.:

bzr --profile-imports rocks

If the problem is actually in extracting files from library.zip then I can
change our build process to not use library.zip at all and put all files
to the filesystem. (But usually zip works faster on XP).

[1] timeit: http://bialix.com/timeit/timeit.exe

 status incomplete
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFHn3YJzYr338mxwCURAp+IAJ9rf3+Nex8N4IvtrdOyMejx/1aPYwCfeAw3
XxILrvJV+RsJQT43ciuGA3o=
=Gv6G
-----END PGP SIGNATURE-----

[Alexander Belchenko (bialix)]

BTW, are you using some Antivirus monitor software? Maybe antivirus try to check our library.zip on each run?

[Paul Pelzl (pelzlpj)]

On Tue, Jan 29, 2008 at 06:52:57PM -0000, Alexander Belchenko wrote:
> | When a command is executed, bzr produces no output for a long period of
> | time. In the task manager, I can see that bzr.exe CPU usage is near
> | zero. The memory usage increases very slowly to about 10MB, and then
> | suddenly the command begins execution with performance comparable to
> | what I have seen on Windows XP boxes.
>
> So you think there is slow startup?

That is correct.

> | My working theory is that this is a manifestation of a Vista bug
> that leads to extremely slow zip archive extraction: |
> http://www.google.com/search?q=vista+zip+slow
>
> Actually we don't use built-in Vista support for extracting zip files.
> bzr.exe is used builtin gzip library. I don't know though on which
> system dll it depends. All rants about Vista unzip slowness related
> to built-in Vista unzip. I want to note it again: we don't use
> built-in unzip. bzr.exe has its own unzip inside.

Actually, not all rants about Vista unzip slowness are related to
built-in Vista unzip. I have seen complaints about WinZip, for example.
I believe Python's zipimport uses zlib internally; maybe other
problematic archival programs also use zlib.

> That leads me to conclusion that Vista has some weird policy re
> Program Files folder. May be some sort of security/viruses
> protection. Also our bzr.exe does not use XP Manifest declaration.
> May be we should finally add it.
>
> Paul, can you check my thoughts about Program Files policy by
> reinstalling bzr.exe outside of Program Files in any other folder,
> e.g. to C:\Bazaar\ and then check performance again.

I installed to the user's desktop, and there was no difference in
performance.

> Also you could use my utility timeit[1] for measuring actual execution time.
> (I recommend to use `bzr rocks` command for testing).
> Use it in this manner:
>
> timeit bzr rocks

77.236 sec. (So, not quite as bad as two minutes, but it *feels* like
it.)

> I don't have Vista box around but may be on the next week I'll have the chance to
> install and run bzr.exe on Vista notebook of my big boss.
>
> Also I'd like to see output of bzr import profiler. Just run any command
> with global flag --profile-imports and then show us results. E.g.:
>
> bzr --profile-imports rocks

I have attached this output.

Paul

C:\Program Files\BazaarStandalone\lib\library.zip\profile_imports.py:20: DeprecationWarning: The sre module is deprecated, please import re.
 cum inline name frame
28890.0 606.0 bzrlib @ __main__:64
12972.0 630.0 + [get_user_encoding]bzrlib.osutils @ bzrlib:19
5507.0 613.0 ++ [mutter]bzrlib.trace @ bzrlib.osutils:62
3049.0 605.0 +++ logging @ bzrlib.trace:54
618.0 618.0 ++++ atexit @ logging:1363
614.0 614.0 ++++ threading @ logging:38
609.0 609.0 ++++ string @ logging:29
603.0 603.0 ++++ traceback @ logging:29
1845.0 1239.0 +++ codecs @ bzrlib.trace:53
605.0 605.0 ++++ [aliases]encodings @ encodings...

[Paul Pelzl (pelzlpj)]

On Tue, Jan 29, 2008 at 06:58:40PM -0000, Alexander Belchenko wrote:
> BTW, are you using some Antivirus monitor software? Maybe antivirus try
> to check our library.zip on each run?

Yeah, this is the problem. Sophos anti-virus is installed on that
machine. When I disable "on-access scanning," then bzr.exe launches at
normal speeds (and WinAce can extract library.zip quickly).

On Windows XP, Sophos does not cause this problem.

Paul

[John A Meinel (jameinel)]

There is some very interesting actions going on. Specifically if you look at:
618.0 618.0 ++++ atexit @ logging:1363
614.0 614.0 ++++ threading @ logging:38
609.0 609.0 ++++ string @ logging:29
603.0 603.0 ++++ traceback @ logging:29

It seems like *each* import XXX from the standard library is costing ~600ms. If you look through the output you see ~600 show up a lot of times.

I wonder if each access is causing the virus software to scan the whole .zip file, which is takes approx 600ms. Or maybe just some sort of strange context switch delay?

[Alexander Belchenko (bialix)]

Paul Pelzl пишет:
> On Tue, Jan 29, 2008 at 06:58:40PM -0000, Alexander Belchenko wrote:
>> BTW, are you using some Antivirus monitor software? Maybe antivirus try
>> to check our library.zip on each run?
>
> Yeah, this is the problem. Sophos anti-virus is installed on that
> machine. When I disable "on-access scanning," then bzr.exe launches at
> normal speeds (and WinAce can extract library.zip quickly).
>
> On Windows XP, Sophos does not cause this problem.

Thanks for testing.

If you're saying that running from python sources does not hurt performance
on Vista with Sophos antivirus then we have some variants what to do next:

1) py2exe utility that converts bzr python program to standalone bzr.exe
program has the option to avoid packing python modules/packages to library.zip
and put them into some directory as regular files. I'd like to have them
into library.zip because of integrity and security reasons (and on XP
running from bzr.exe is faster than with python interpreter, but it's not
the case for you :-[) but have no strong opinion against unpacking library.zip

2) don't do anything and put warning into the FAQ.

If you're interesting in testing ideas #1 on Vista with Sophos
I'll try to provide new standalone installer for you.

[Paul Pelzl (pelzlpj)]

On Thu, Jan 31, 2008 at 10:05:48AM -0000, Alexander Belchenko wrote:
> If you're saying that running from python sources does not hurt performance
> on Vista with Sophos antivirus then we have some variants what to do next:
>
> 1) py2exe utility that converts bzr python program to standalone bzr.exe
> program has the option to avoid packing python modules/packages to library.zip
> and put them into some directory as regular files. I'd like to have them
> into library.zip because of integrity and security reasons (and on XP
> running from bzr.exe is faster than with python interpreter, but it's not
> the case for you :-[) but have no strong opinion against unpacking library.zip
>
> 2) don't do anything and put warning into the FAQ.

My first reaction to this is that (1) is probably the best solution,
because I think it is quite likely that Sophos is *not* the only
antivirus software that triggers this condition. I would hate to have a
lot of of Vista users test out bzr for the first time and immediately
decide that it is broken.

> If you're interesting in testing ideas #1 on Vista with Sophos
> I'll try to provide new standalone installer for you.

If you can provide a test build, I would be happy to try it on that
Vista box.

Paul

[Alexander Belchenko (bialix)]

The test build without library.zip for testing is here: http://bzrdev.bialix.com/bzr-setup-1.2.0.dev.0-unpacked.exe

But I want to note that unpacked version has 100-300ms slower on Win2k/WinXP so I really dislike the idea to switch using unpacked bzr.exe. So I'm resist to idea to make unpacked variant the default.

[Paul Pelzl (pelzlpj)]

On Sun, Feb 03, 2008 at 11:47:40PM -0000, Alexander Belchenko wrote:
> The test build without library.zip for testing is here:
> http://bzrdev.bialix.com/bzr-setup-1.2.0.dev.0-unpacked.exe

This build has good startup time on Vista even with Sophos "on-access
scanning" enabled.

> But I want to note that unpacked version has 100-300ms slower on
> Win2k/WinXP so I really dislike the idea to switch using unpacked
> bzr.exe. So I'm resist to idea to make unpacked variant the default.

I was also able to measure a significant timing difference, although it
is < 100ms on my XP box. So I understand your resistance.

If the packed bzr.exe remains the default, then I think the download
link on the website should make it clear that the standalone build is
*not* recommended for Vista.

Another idea: it is possible that Sophos just looks at the .ZIP file
extension to decide that the file may be "unsafe." I wonder if simply
using a different archive name, e.g. "library.foo" would solve the
problem.

Paul

[Alexander Belchenko (bialix)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Paul Pelzl пишет:
| Another idea: it is possible that Sophos just looks at the .ZIP file
| extension to decide that the file may be "unsafe." I wonder if simply
| using a different archive name, e.g. "library.foo" would solve the
| problem.

Here is test build with mangled name of library.zip (renamed to just 'python').
http://bzrdev.bialix.com/bzr-setup-1.2.0.dev.0-mangled.exe

Paul, can you test it?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFHqAHSzYr338mxwCURApNmAJ47d6zJpjWs+eiFRBwLtFLwTiiZjACfZsdH
cEbPGsNMPkf8M6BLsQofaqY=
=/Eqy
-----END PGP SIGNATURE-----

[Paul Pelzl (pelzlpj)]

On Tue, Feb 05, 2008 at 06:27:15AM -0000, Alexander Belchenko wrote:
> Paul Pelzl ??????????:
> | Another idea: it is possible that Sophos just looks at the .ZIP file
> | extension to decide that the file may be "unsafe." I wonder if simply
> | using a different archive name, e.g. "library.foo" would solve the
> | problem.
>
> Here is test build with mangled name of library.zip (renamed to just 'python').
> http://bzrdev.bialix.com/bzr-setup-1.2.0.dev.0-mangled.exe
>
> Paul, can you test it?

Unfortunately, this doesn't perform any better. Probably Sophos is
scanning for the magic numbers in the zip header.

Paul

[Jason Mobarak (silverjam)]

I seem to have a similar problem on Windows XP SP3 (with Sophos) -- unless this is normal slowdown with on-access scanning (but it seems like a lot).

This is bzr diff with on access scanning turned on:

> Measure-Command {bzr diff} | %{ $_.TotalSeconds }
13.2807554

This is bzr diff with on access scanning turned off:

> Measure-Command {bzr diff} | %{ $_.TotalSeconds }
2.9943691

[Jason Spashett (jspashett)]

I've had this problem before with other software. Not with bazaar or Sophos av but with:

McAfee Anti virus and Windows scripting host .js script. It seems like the exact same symptoms. I never found the cause. It would hang for a minute or two. Disabling the on access scan fixed the problem.There was no zipping involved in my .js script AFAIR.

[Krzysztof Nowicki (krissn)]

I'm experiencing this problem on my company laptop with Windows 7 and McAfee antivirus. According to my investigation the real problem lies in the zipinfo Python module and affects all programs using py2exe with the option to compress all python objects into a single ZIP archive (library.zip). The reason is that during startup of such an executable, py2exe uses the zipimport Python module to extract the imported modules from the ZIP file. Unfortunately the zipinfo module will open the ZIP file each time it needs to extract a module and close the file afterwards. In the Windows world with a resident antivirus software this means that the ZIP file will be scanned each time it is opened, i.e. each time one module is loaded. Smart antivirus scanners will scan the file only the first time and remember upon the next scan that it was clean. Apparently McAfee is not one of them (in contrary to what they claim).

In order to verify this I made an ugly hack in the zipinfo module - the file descriptor of the archive is reused every time instead of closing and opening it again. The result is a huge improvement in bzr startup time.

[Martin Packman (gz)]

Thanks for investigating further Krzysztof. Just to check, when you say "the zipinfo module" do you mean zipimport? I'm curious to see your ugly hack, could you attach it here? Is it the kind of thing you could clean up and propose for upstream python? The problem is likely to be that not holding the zipfile open is actually desirable, so the workaround may not be accepted.

Having a clear answer for users that run into this problem would be a good thing regardless.

[Krzysztof Nowicki (krissn)]

Yes, I meant the zipimport module.

The hack basically eliminates all fclose() calls and replaces all fopen() calls with a wrapper function, which keeps a copy of the filename of the last open file and it's file descriptor. If the supplied file name matches the stored one the function just returns the cached handle. Otherwise the existing handle is closed and a new one is opened. Everything is done on static global variables. The problem here is that the last used file is never actually closed, but I guess that could be fixed by some more sophisticated logic.

I could try to spend some time to develop a more clean solution.

[Krzysztof Nowicki (krissn)]

The patch itself attached.

[Martin Packman (gz)]

I see two possible ways forward.

1) Open and store the fd in zipimport_init, possibly with the share mode on windows as anything, including FILE_SHARE_DELETE. Close the fd in zipimporter_dealloc, and pass it down into read_directory and get_data functions. This could be proposed upstream, but persuading them to take it as a bug fix when it's a pretty large behaviour change may be hard.

2) See if keeping a handle open within the same process but outside the context of the zip importer is enough to stop the buggy scanners rechecking the archive every operation. That could then be a hacky fix in py2exe or even bzr, though again whether it's the sort of thing that should be enabled by default is another question.

[Krzysztof Nowicki (krissn)]

Option 1 sounds like the proper fix for this, but I'll also test option 2 at work on Monday to see if it makes any difference.

[Martin Pool (mbp)]

Thanks for cracking this long-standing issue, Krzysztof.