Closed Bug 1275672 Opened 3 years ago Closed 3 years ago

Symbol generation on Windows spends a lot of time in makecab.exe

Categories

(Firefox Build System :: General, defect)

defect
Not set

Tracking

(firefox49 fixed)

RESOLVED FIXED
mozilla49
Tracking Status
firefox49 --- fixed

People

(Reporter: gps, Assigned: gps)

Details

Attachments

(1 file)

I profiled my system with xperf during `make buildsymbols` and was surprised to see that a disproportionate amount of CPU samples were in makecab.exe.

It appears compression is the culprit. This looks to be responsible for a few minutes of CPU time during symbol generation. Yikes.
My i7-6700K spends ~5 minutes CPU time in makecab.exe for xul.pdb.

Changing CompressionType=LZX to CompressionType=MSZIP reduces the run time of symbol generation from ~7:45 to ~4:05 on my machine. The resulting files are ~200 MB larger, however.

Disabling compression makes makecab.exe insanely fast. However, it is offset by zip.exe creating crashreporter-symbols.zip. zip.exe is using compression level 9 and the cab files without compression are >1.5GB larger, so zip.exe has to work a lot harder.
Poking through the contents of the final zip files, the .pd_ files hardly have any compression. I reckon we're wasting a lot of CPU cycles trying to compress them. We could possibly replace the zip.exe invocation with a custom Python script using mozpack that doesn't try to compress the .pd_ files and we'd come out ahead. As a bonus, that also makes the final zip archives more deterministic, as right now file times are creeping into the produced zip.
Filed bug 1275740 to make zip generation 2x faster by reducing compression level.
makecab.exe has 3 options for compression: disable, MSZIP, and LZX.

Here is a breakdown of the 3 levels of compression for an opt 32-bit
build on my i7-6700K:

       directory size     full.zip   xul.pd_  `buildsymbols`
None     1,360 MB          227 MB     146 MB        49s
MSZIP      520 MB          221 MB     142 MB       113s
LZX        436 MB          169 MB     102 MB       248s

(The original size of xul.pdb is ~500 MB.)

This commit switches us to MSZIP as the compression format. This
makes `builsymbols` >2x faster while only increasing the full zip
archive size by ~31%. This feels like an appropriate trade-off.

The memory related flag has been removed because it only applies
to LZX compression.

It's worth noting that using `zip` to compress xul.pdb and xul.sym:

Level  Zip Size    xul.pdb Compressed   Time
9        160.6 MB      139.8 MB         76s
7        161.4 MB      140.5 MB         30s
5        164.7 MB      143.2 MB         16s
4        170.0 MB      147.3 MB         12s
3        176.4 MB      151.6 MB         11s

So "MSZIP" compression appears to be using level 9. If we could swap
in our own cab generator that uses a zlib compression level less
than 9, we'll make symbol generation significantly faster without
sacrificing too much size. I'm inclined to punt that to a follow-up
bug.

Review commit: https://reviewboard.mozilla.org/r/55968/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/55968/
Attachment #8757528 - Flags: review?(ted)
Assignee: nobody → gps
Status: NEW → ASSIGNED
Sample size of 1 from each side, but on Try, here are reported processing times for xul.pdb:

               Before      After     Delta
Win32 Opt      486.96s     44.33s   -442.63s
Win32 Debug    732.23s     77.94s   -654.29s
Win64 Opt      477.13s     37.03s   -440.01s
Win64 Debug    787.80s     74.74s   -713.06s

Nearly 12 minute savings on Win 64 Debug!!!

This appears to make Windows builds clearly faster than OS X builds and only 6-10 minutes slower than Linux builds (well, for 32-bit opt at least).
Confirming also locally: instead of more than 5 minutes building symbols now takes 57 seconds!  Thanks!
Attachment #8757528 - Flags: review?(ted) → review+
Comment on attachment 8757528 [details]
MozReview Request: Bug 1275672 - Change symbols compression format to MSZIP; r?ted

https://reviewboard.mozilla.org/r/55968/#review52704

I don't remember xul.pdb being that large historically, but this is definitely the right tradeoff.
https://hg.mozilla.org/mozilla-central/rev/5eaeae696984
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
Something's not working as expected in this patch. I looked at the build log for the most recent nightly:
http://archive.mozilla.org/pub/firefox/nightly/2016/05/2016-05-30-07-12-07-mozilla-central/mozilla-central-win32-nightly-bm73-build1-build29.txt.gz

and found:
09:36:35     INFO -    adding: xul.pdb/87B0462538444D74A47F05C9A3DD3FF82/xul.pdb (176 bytes security) (deflated 72%)

Double-checking the symbol server showed the same thing:
luser@eye7:/tmp/symbols$ curl -I http://symbols.mozilla.org/xul.pdb/87B0462538444D74A47F05C9A3DD3FF82/xul.pdb
HTTP/1.1 200 OK
Connection: keep-alive
Date: Tue, 31 May 2016 09:46:12 GMT
Server: AmazonS3
X-Amz-Id-2: qpw9WjupnaFB2OhYHRaQEbq2M/9l+41myLHeNkdcEohZ1fEwGlgKsqmawTXugtxHsJ1S9YYBbRE=
X-Amz-Request-Id: 85E3929E520153E0
Last-Modified: Mon, 30 May 2016 16:37:28 GMT
Etag: "ec8e1ce997b50a1bf1d477ebbe582f63"
Accept-Ranges: bytes
Content-Type: application/vnd.palm
Content-Length: 523685888
Via: 1.1 vegur

The pdb files are being uploaded uncompressed, which sucks. Due to a design decision in symbolstore.py if PDB compression fails we'll just upload the original PDB file:
https://dxr.mozilla.org/mozilla-central/rev/4d63dde701b47b8661ab7990f197b6b60e543839/toolkit/crashreporter/tools/symbolstore.py#793
Pushed by gszorc@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d3137e8822b3
Remove accidental trailing /D from makecab.exe arguments; r=me
Product: Core → Firefox Build System
You need to log in before you can comment on or make changes to this bug.