Regression: opening large zip files is slow since 2.1.4 because the entire file is scanned

[ttencate]

Describe the bug

I have a 266 MB zip file, from which I only need to extract a 1 kB file. The rest of the files in the archive are irrelevant at this stage in the program.

However, opening the zip file using ZipArchive::new(file) takes about 7 seconds. It's a lot faster the second time round, because of Linux's filesystem cache.

I traced the root cause to Zip32CentralDirectoryEnd::find_and_parse, which locates the "end of central directory record" very quickly at the end of the file, but then keeps scanning backwards through the entire file to find another one.

To Reproduce

Have a large zip file:

$ ls -lh archive.zip
-rw-r--r-- 1 thomas thomas 266M Aug  8 12:20 archive.zip
$ cargo build --release
$ echo 3 | sudo tee /proc/sys/vm/drop_caches  # Flush filesystem cache (Linux only)
$ time target/release/repro
real	0m6.714s
user	0m0.560s
sys	0m1.293s

Use this as the main program:

fn main() {
    let file = std::fs::File::open("archive.zip").unwrap();
    let archive = zip::ZipArchive::new(file).unwrap();
}

Expected behavior

Extracting a single 1 kB file from a large archive should be possible quickly. unzip can do it:

$ echo 3 | sudo tee /proc/sys/vm/drop_caches
$ time unzip -l archive.zip
Archive:  archive.zip
  Length      Date    Time    Name
---------  ---------- -----   ----
...
---------                     -------
1228949561                     9 files

real	0m0.012s
user	0m0.005s
sys	0m0.000s
$ echo 3 | sudo tee /proc/sys/vm/drop_caches
$ time unzip archive.zip some_file.txt
Archive:  archive.zip
  inflating: some_file.txt           

real	0m0.012s
user	0m0.000s
sys	0m0.005s

Version

zip 2.1.6. This is also happening in 2.1.4, but not in 2.1.3. I think cb2d7ab or 9bf914d is the cause, but I haven't dug deeper.

[RisaI]

Can also confirm the regression. In our case, the difference is extreme (by an order of magnitude).

[electimon]

Also encountering this with extracting single tiny file from multiple small zip files (>9000 count), i thought i was going crazy, in my case llseek seems to be taking up alot of cputime.

[newinnovations]

I can also confirm. Extracting a 109 KB file from a 200 MB archive:

In 2.1.3:

       extract (zip)    0.2 ms (109 KB)

In 2.1.6:

       extract (zip)  675.5 ms (109 KB)

[newinnovations]

In 2.2.0:

       extract (zip)  683.4 ms (109 KB)

[RisaI]

The regression is indeed caused by cb2d7ab, as @ttencate suspected (confirmed by bisecting).

Looking at the code, the new way of looking for magic bytes is terribly (I mean extremely, by many orders of magnitude) slower. The correct way would be to lazy-load the potential CDE sections, but the current code collects ALL of the candidates before proceeding further. This is is further made worse in the zip64 case where there's a subsequent forward search for every candidate. The zip file is therefore read from back to start entirely and from each CDE candidate until the end again.

The back-to-start pass itself is extremely inefficient, because only the first case of a valid CDE is ever necessary. The backtracking then completely nukes performance when using network shares, for example (as was the case in our production environment). It also causes a 2000x slowdown in my local tests (44MB ZIP with 30 files, NVME SSD, 64GB RAM, 32 threads).

[ttencate]

Thank you for your excellent work @Pr0methean! I think the issue closure was triggered by your PR description, but @nickbabcock mentions that there's still a regression. Do you think we should reopen this one, or file a new one for that?

[richardstephens]

When we hit this issue, we implemented a regression test to test for the performance regression, in case the dependency got bumped by mistake. We implemented an instrumented cursor to track how many seeks and how much data was being read. The numbers we are seeing are as follows:

15kb test file

• zip2 v2.1.3: seek_count=25 read_bytes_count=1223
• zip2 v2.2.1: seek_count=39 read_bytes_count=17095
• zip2@33c71cc: seek_count=36 read_bytes_count=2739

4MB test file

• zip2 v2.1.3: seek_count=34 read_bytes_count=1476
• zip2 v2.2.1: seek_count=69 read_bytes_count=140228
• zip2@33c71cc:: seek_count=51 read_bytes_count=2992