Closed Bug 1275672 Opened 4 years ago Closed 4 years ago
Symbol generation on Windows spends a lot of time in makecab
58 bytes, text/x-review-board-request
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)
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).
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/
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.
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
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 firstname.lastname@example.org: https://hg.mozilla.org/integration/mozilla-inbound/rev/d3137e8822b3 Remove accidental trailing /D from makecab.exe arguments; r=me
You need to log in before you can comment on or make changes to this bug.