Performance regression in version 1.11

[fdegros]

I recently upgraded the version of libzip used by ChromeOS from version 1.10.0 to 1.11.1 which was released last month. Soon after, our automated performance tests picked up a significant performance regression.

A bisection of the libzip code points to commit 7a53a1a as the source of the performance regression. This single commit doubles the time taken to list all the files of a ZIP containing a significant number of files.

Example at commit f0eff80, which is the last one before the performance regression:

$ time mount-zip Many.zip 
real    0m0.759s
user    0m0.289s
sys     0m0.473s

Example at commit 7a53a1a, which introduces the performance regression:

$ time mount-zip Many.zip 
real    0m1.436s
user    0m0.376s
sys     0m1.062s

I tried to revert commit 7a53a1a at version 1.11.1, but there are quite a few merge conflicts that prevent me from doing so.

There is no mention of an expected performance regression in commit 7a53a1a.

[0-wiz-0]

What does your mount-zip do - is it only reading the files or does it actually change the archive?
Can you give some statistics about Many.zip (number of files, size)?
Can you try with 4e6f034 applied?

[dillof]

Looking at the diff of that commit, one line stands out:

zip_open.c:
530 +        || !_zip_string_equal(central->filename, local->filename))

Could you try running your test with this line removed (and a closing ) added to the line before)?

[fdegros]

The test archive Many.zip contains 100 top folders that contain 1000 files each. That's a total of 100,000 files of 15 bytes each, which are stored without any compression.

See Many (compressed).zip. Note that, in order to upload Many.zip, I had to compress it by putting in another ZIP called Many (compressed).zip.

In the section of the code where its time is measured, mount-zip simply lists all the files and their properties. It does not open nor extract any of the files.

I modified libzip's code as suggested:

$ git diff
diff --git a/lib/zip_open.c b/lib/zip_open.c
index 9dccad61..6056fcb1 100644
--- a/lib/zip_open.c
+++ b/lib/zip_open.c
@@ -603,7 +603,7 @@ _zip_headercomp(const zip_dirent_t *central, const zip_dirent_t *local) {
           and global headers for the bitflags */
        || (central->bitflags != local->bitflags)
 #endif
-        || (central->comp_method != local->comp_method) || (central->last_mod.time != local->last_mod.time) || (central->last_mod.date != local->last_mod.date) || !_zip_string_equal(central->filename, local->filename))
+        || (central->comp_method != local->comp_method) || (central->last_mod.time != local->last_mod.time) || (central->last_mod.date != local->last_mod.date))
         return -1;
 
     if ((central->crc != local->crc) || (central->comp_size != local->comp_size) || (central->uncomp_size != local->uncomp_size)) {

but that doesn't change the performance:

$ time mount-zip Many.zip 
real    0m1.437s
user    0m0.381s
sys     0m1.059s

[fdegros]

I also noticed that the "system" time was doubled by commit 7a53a1a. So I traced the system calls using the following command before and after commit 7a53a1a.

# At commit f0eff80889f1b0791e91516d2d84e8d5b84a1e02
$ strace -o trace1.log mount-zip Many.zip

# At commit 7a53a1acf29221b1e65b2a34e1a295621e769592
$ strace -o trace2.log mount-zip Many.zip

See traces.zip.

There is a stark difference in the number of issued system calls, going from ~300k to ~500k.

$ wc -l trace*.log
  305787 trace1.log
  505987 trace2.log

Looking at the differences, trace2.log contains many calls to newfstatat that are not present in trace1.log:

newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2190, ...}, 0) = 0

The pattern of syscalls is really regular. There are 2 extra syscalls to newfstatat(AT_FDCWD, "/etc/localtime") for each of the 100,000 files and each of the 100 directories present in the ZIP archive. That exactly accounts for the 200,200 extra syscalls.

[dillof]

We've moved the call to localtime() from zip_open() to zip_stat(). Do you stat each file 3 times? That would explain the extra syscalls.

[fdegros]

We've moved the call to localtime() from zip_open() to zip_stat().

This change makes each call to zip_stat() significantly more "expensive" (i.e. slower). This has surprising performance implications. I checked the news page and zip_stat() doc but didn't see any mention of this change.

Do you stat each file 3 times? That would explain the extra syscalls.

Yes, mount-zip calls zip_stat() several times for each file while building its internal tree structure. It assumes that zip_stat() is a "cheap" (i.e. fast) operation, and this assumption was corroborated by our observations and measurements until libzip 1.11 came out.

Would it be possible to fix this performance regression in zip_stat() itself? For example, would it be possible to cache the result of localtime() the first time zip_stat() is called, and reuse the cached value when zip_stat() is called again?

[dillof]

We now cache the conversion results.

We're confident this will fix the performance regression, but would appreciate if you could confirm it.

[fdegros]

Oh great. Thanks.

I confirm that commit c2854be fixes the performance regression.

At commit 46e309f (which is just before the commit that fixes the performance regression):

$ time mount-zip Many.zip
real    0m1.471s
user    0m0.367s
sys     0m1.106s

At commit c2854be (which fixes the performance regression):

$ time mount-zip Many.zip

real    0m0.781s
user    0m0.274s
sys     0m0.510s

The performance is back to what it used to be before commit 7a53a1a (which introduced the performance regression).

[0-wiz-0]

Thanks for the report and the testing!

[fdegros]

Would you now consider releasing an official version containing this fix? That would allow me to simply upgrade the version of libzip we are using instead of extracting, preparing and applying a patch to version 1.11.1.

[0-wiz-0]

I've just released libzip 1.11.2. Thank you for your support!

[fdegros]

Perfect. I'm now upgrading our version of libzip to 1.11.2.
By the way, I noticed that libzip.org still mentions version 1.11.1 as the current version.

[0-wiz-0]

Fixed, thanks.