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

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Gregory Szorc [:gps]]

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.

Comment 1

[Gregory Szorc [:gps]]

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.

Comment 2

[Gregory Szorc [:gps]]

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.

Comment 3

[Gregory Szorc [:gps]]

Filed bug 1275740 to make zip generation 2x faster by reducing compression level.

Comment 4

[Gregory Szorc [:gps]]

Attachment: MozReview Request: Bug 1275672 - Change symbols compression format to MSZIP; r?ted

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/

Comment 5

[Gregory Szorc [:gps]]

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).

Comment 6

[Gregory Szorc [:gps]]

Perfherder data for Win32:

https://treeherder.mozilla.org/perf.html#/graphs?series=%5Bmozilla-inbound,dd202f8b9be19eb0a5958e9b981dfa22cd203f9d,1,2%5D&series=%5Bmozilla-inbound,fc6ec8e0f50379a3e44705a34c53315f2c5a440d,1,2%5D&series=%5Bmozilla-inbound,4cb5017ed40c97f161c2c84e787a18d43f21302b,1,2%5D&series=%5Bmozilla-inbound,3b0cb0a6878bff1fc2f3ad74a405b27846f26795,1,2%5D&series=%5Bmozilla-inbound,15861d91e8e82533d1b738c084a9946662908bf1,1,2%5D&series=%5Bmozilla-inbound,20e5b9a4b853f1679dcaf8642f1882ade56d3501,1,2%5D

And Win64:

https://treeherder.mozilla.org/perf.html#/graphs?series=%5Bmozilla-inbound,403c195ab4b1e2e1c835eb3a3714275810ec486c,1,2%5D&series=%5Bmozilla-inbound,0594c537d40b8a557c91d3a1481c929cfe676b06,1,2%5D&series=%5Bmozilla-inbound,2049e79f443e2647eced00a550bf769f63f4bf0d,1,2%5D&series=%5Bmozilla-inbound,c81890519a403ad1c8143a6da562e1ccfccd152c,1,2%5D&series=%5Bmozilla-inbound,adac8b7a5a2b2444d419c4d12b865748e51b15a6,1,2%5D&series=%5Bmozilla-inbound,091d8ebc5e298270be2867414e263300a603c82a,1,2%5D

Here are the smallest times:

Win32 Opt      460s
Win32 Debug    738s
Win64 Opt      460s
Win64 Debug    775s

So, the data in comment #5 doesn't appear to be a fluke \o/

Comment 7

[Honza Bambas (:mayhemer)]

Confirming also locally: instead of more than 5 minutes building symbols now takes 57 seconds!  Thanks!

Comment 8

[(not currently active) Ted Mielczarek]

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.

Comment 9

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/5eaeae696984

Comment 10

[Gregory Szorc [:gps]]

I love perfherder graphs that render as cliffs: https://treeherder.mozilla.org/perf.html#/graphs?timerange=604800&series=%5Bmozilla-inbound,fc6ec8e0f50379a3e44705a34c53315f2c5a440d,1,2%5D&series=%5Bmozilla-inbound,3b0cb0a6878bff1fc2f3ad74a405b27846f26795,1,2%5D&series=%5Bmozilla-inbound,403c195ab4b1e2e1c835eb3a3714275810ec486c,1,2%5D&series=%5Bmozilla-inbound,c81890519a403ad1c8143a6da562e1ccfccd152c,1,2%5D

Comment 11

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/5eaeae696984

Comment 12

[(not currently active) Ted Mielczarek]

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

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d3137e8822b3
Remove accidental trailing /D from makecab.exe arguments; r=me

Comment 14

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d3137e8822b3