Обсуждение: ccache, MSVC, and meson
forking: <20220307191054.n5enrlf6kdn7zc42@alap3.anarazel.de> An update. ccache 4.6.1 was released which allows compiling postgres I submitted a request to update the package in chocolatey. But with the existing build system, it's no faster anyway, I guess due to poor use of parallelism. https://cirrus-ci.com/task/5972008205811712 Currently, meson doesn't (automatically) use ccache with MSVC - see mesonbuild/environment.py. And CC=ccache gives an error - I suppose it should not try to pop ccache off the compiler list if the list has only one element. |[21:44:49.791] File "C:\python\lib\site-packages\mesonbuild\compilers\detect.py", line 375, in _detect_c_or_cpp_compiler |[21:44:49.791] compiler_name = os.path.basename(compiler[0]) |[21:44:49.791] IndexError: list index out of range |... |[21:44:49.791] meson.build:1:0: ERROR: Unhandled python exception |[21:44:49.791] |[21:44:49.791] This is a Meson bug and should be reported! But it can be convinced to use ccache by renaming the executable to "pgccache". Which builds in 46sec: https://cirrus-ci.com/task/4862234995195904 This requires ccache 4.6, released in Feburary and already in choco. Note that ccache supports neither /Zi debugging nor precompiled headers. I'm not sure, but -Dc_args=/Z7 may do what's wanted here.
Hi, On 2022-05-22 18:26:06 -0500, Justin Pryzby wrote: > forking: <20220307191054.n5enrlf6kdn7zc42@alap3.anarazel.de> > > An update. > > ccache 4.6.1 was released which allows compiling postgres > I submitted a request to update the package in chocolatey. > > But with the existing build system, it's no faster anyway, I guess due to poor > use of parallelism. > https://cirrus-ci.com/task/5972008205811712 No, because it never uses caching, because the way we set the output director causes ccache to never cache. > Currently, meson doesn't (automatically) use ccache with MSVC - see > mesonbuild/environment.py. > > And CC=ccache gives an error - I suppose it should not try to pop ccache off the > compiler list if the list has only one element. > [...] > But it can be convinced to use ccache by renaming the executable to "pgccache". > Which builds in 46sec: https://cirrus-ci.com/task/4862234995195904 > This requires ccache 4.6, released in Feburary and already in choco. > Note that ccache supports neither /Zi debugging nor precompiled headers. > I'm not sure, but -Dc_args=/Z7 may do what's wanted here. The spurious message should be fixed, of course. I suspect you dont need a wrapper, you can just set CC='ccache cl.exe' or similar? Afaics it's not meaningful to do 'CC=ccache.exe' alone, because then it'll interpret arguments as ccache options, rather than compiler options. Greetings, Andres Freund
On Tue, May 24, 2022 at 12:30:59PM -0700, Andres Freund wrote: > Hi, > > On 2022-05-22 18:26:06 -0500, Justin Pryzby wrote: > > forking: <20220307191054.n5enrlf6kdn7zc42@alap3.anarazel.de> > > > > An update. > > > > ccache 4.6.1 was released which allows compiling postgres > > I submitted a request to update the package in chocolatey. > > > > But with the existing build system, it's no faster anyway, I guess due to poor > > use of parallelism. > > https://cirrus-ci.com/task/5972008205811712 > > No, because it never uses caching, because the way we set the output director > causes ccache to never cache. I think you're referring to the trailing backslash in the MSVC project file, meaning "write to a filename under this directory": src/tools/msvc/MSBuildProject.pm: <ObjectFileName>.\\$cfgname\\$self->{name}\\</ObjectFileName> ccache was fixed to handle that in 4.6, and could be worked around before that by adding "%(Filename).obj". https://github.com/ccache/ccache/issues/1018 In any case, it really is caching, but without any positive effect: [17:02:01.555] Hits: 1398 / 1398 (100.0 %) [17:02:01.555] Direct: 1398 / 1398 (100.0 %) [17:02:01.555] Preprocessed: 0 / 0 [17:02:01.555] Misses: 0 [17:02:01.555] Direct: 0 [17:02:01.555] Preprocessed: 0 [17:02:01.555] Primary storage: [17:02:01.555] Hits: 2796 / 2796 (100.0 %) [17:02:01.555] Misses: 0 > > Currently, meson doesn't (automatically) use ccache with MSVC - see > > mesonbuild/environment.py. > > > > And CC=ccache gives an error - I suppose it should not try to pop ccache off the > > compiler list if the list has only one element. > > [...] > > > But it can be convinced to use ccache by renaming the executable to "pgccache". > > Which builds in 46sec: https://cirrus-ci.com/task/4862234995195904 > > This requires ccache 4.6, released in Feburary and already in choco. > > Note that ccache supports neither /Zi debugging nor precompiled headers. > > I'm not sure, but -Dc_args=/Z7 may do what's wanted here. > > The spurious message should be fixed, of course. I suspect you dont need a > wrapper, you can just set CC='ccache cl.exe' or similar? Afaics it's not > meaningful to do 'CC=ccache.exe' alone, because then it'll interpret arguments > as ccache options, rather than compiler options. if meson didn't crash CC=ccache.exe might have worked, because I had set CCACHE_COMPILER. As I recall, CC='ccache cl.exe' didn't work because it didn't attempt to do any argument splitting. The copy of ccache.exe is necessary because otherwise ccache "skips" over any leading "ccache[.exe]" components while searching for the real compiler. This is the only way I've gotten it to work (but feel free to comment at: https://github.com/ccache/ccache/issues/1039) -- Justin
Hi, On 2022-05-24 14:52:02 -0500, Justin Pryzby wrote: > > The spurious message should be fixed, of course. I suspect you dont need a > > wrapper, you can just set CC='ccache cl.exe' or similar? Afaics it's not > > meaningful to do 'CC=ccache.exe' alone, because then it'll interpret arguments > > as ccache options, rather than compiler options. > > if meson didn't crash CC=ccache.exe might have worked, because I had set > CCACHE_COMPILER. Did you report the issue? Should be simple enough to fix. I seriously doubt it's a good idea to use CCACHE_COMPILER - there's no way meson (or autoconf or ..) can rely on the results of compiler tests that way, since CCACHE_COMPILER can change at any time. > As I recall, CC='ccache cl.exe' didn't work because it didn't attempt to do any > argument splitting. I tried it, and it works for me when building with ninja (compiling with cl.exe). I assume you are using msbuild? A cached build takes 21s on my VM, fwiw, vs 199s uncached. Greetings, Andres Freund
On Tue, May 24, 2022 at 01:30:39PM -0700, Andres Freund wrote: > > As I recall, CC='ccache cl.exe' didn't work because it didn't attempt to do any > > argument splitting. > > I tried it, and it works for me when building with ninja (compiling with > cl.exe). I assume you are using msbuild? Apparently it works to write "ccache.exe" but not just "ccache", which is what I used before. It seems to work by fooling meson, which intends to strip off the leading "ccache" but fails due to the "exe", but then happens to do what's desired. If I'm not wrong, pgccache.exe + CCACHE_COMPILER=cl runs 30sec faster on cirrus. I suppose it's because windows is running cmd.exe on the CC="ccache.exe cl". Also, /O2 cuts ~3 minutes off the test time on cirrus, which seems worth it, except that it omits frame pointers, which probably breaks debuggability. And when I pass /Oy- to "avoid omitting" frame pointers, several tests crash...
Hi, On 2022-05-24 17:17:47 -0500, Justin Pryzby wrote: > Also, /O2 cuts ~3 minutes off the test time on cirrus, which seems worth it, > except that it omits frame pointers, which probably breaks debuggability. It likely also causes us to use the non-debug C runtime? Which IMO would be bad, it does detect quite a few problems that are otherwise hard to find. > And when I pass /Oy- to "avoid omitting" frame pointers, several tests crash... Huh. Do you get a backtrace containing anything remotely meaningful? There's this helpful statement in the docs: https://docs.microsoft.com/en-us/cpp/build/reference/oy-frame-pointer-omission?view=msvc-170 > If you specify a debug compiler option (/Z7, /Zi, /ZI), we recommend that you specify the /Oy- option after any other optimizationcompiler options. Greetings, Andres Freund
On Tue, May 24, 2022 at 09:48:17PM -0700, Andres Freund wrote: > > And when I pass /Oy- to "avoid omitting" frame pointers, several tests crash... > > Huh. Do you get a backtrace containing anything remotely meaningful? They are interesting, but maybe not meaningful. I tested a bunch of different optimization cases, this is just one. But the other failures are similar. https://cirrus-ci.com/task/5710595927310336 compiled with /Z7 /O1, test world fails in 15min (compared to ~18min without /O1) Child-SP RetAddr Call Site 000000b6`e27fed80 00007ffa`93b5b6ba pg_stat_statements!pg_stat_statements_reset_1_7+0x8a98 000000b6`e27fedb0 00007ffa`93b5a731 pg_stat_statements!pg_stat_statements_reset_1_7+0x8a5e 000000b6`e27fedf0 00007ffa`93b5a48c pg_stat_statements!pg_stat_statements_reset_1_7+0x7ad5 000000b6`e27feeb0 00007ffa`93b517b5 pg_stat_statements!pg_stat_statements_reset_1_7+0x7830 000000b6`e27feee0 00007ffa`93b52c6f pg_stat_statements!PG_init+0x7ad 000000b6`e27fef80 00007ff6`5544ebc3 pg_stat_statements!pg_stat_statements_reset_1_7+0x13 000000b6`e27fefb0 00007ff6`5546fa07 postgres!ExecEvalXmlExpr+0x9b3 000000b6`e27ff040 00007ff6`5530639c postgres!ExecReScanResult+0x1ef 000000b6`e27ff080 00007ff6`55306e91 postgres!ExecWithCheckOptions+0x4d0 000000b6`e27ff0c0 00007ffa`93b52f0c postgres!standard_ExecutorRun+0x13d 000000b6`e27ff140 00007ff6`550e636d pg_stat_statements!pg_stat_statements_reset_1_7+0x2b0 000000b6`e27ff2c0 00007ff6`550e5ba0 postgres!PortalRunFetch+0x645 000000b6`e27ff300 00007ff6`55013d31 postgres!PortalRun+0x24c 000000b6`e27ff4e0 00007ff6`55010db9 postgres!die+0x1cad 000000b6`e27ff5b0 00007ff6`5500e004 postgres!PostgresMain+0xb31 000000b6`e27ff7a0 00007ff6`55001592 postgres!SubPostmasterMain+0x230 000000b6`e27ff9d0 00007ff6`554c6ef0 postgres!main+0x2a2 000000b6`e27ffbc0 00007ffa`91217974 postgres!pg_check_dir+0x68c 000000b6`e27ffc00 00007ffa`9c84a2f1 KERNEL32!BaseThreadInitThunk+0x14 000000b6`e27ffc30 00000000`00000000 ntdll!RtlUserThreadStart+0x21 2022-05-23 09:05:28.893 GMT postmaster[6644] LOG: server process (PID 6388) was terminated by exception 0xC0000354 2022-05-23 09:05:28.893 GMT postmaster[6644] DETAIL: Failed process was running: SELECT pg_stat_statements_reset(); Child-SP RetAddr Call Site 0000004e`65ffbd40 00007ffa`93b66d3a basebackup_to_shell!PG_init+0x5c8c 0000004e`65ffbd70 00007ffa`93b67898 basebackup_to_shell!PG_init+0x5c52 0000004e`65ffbdb0 00007ffa`93b6817e basebackup_to_shell!PG_init+0x67b0 0000004e`65ffbe10 00007ffa`93b656bb basebackup_to_shell!PG_init+0x7096 0000004e`65ffbe40 00007ffa`93b65441 basebackup_to_shell!PG_init+0x45d3 0000004e`65ffbea0 00007ffa`93b653d2 basebackup_to_shell!PG_init+0x4359 0000004e`65ffbee0 00007ffa`93b6556e basebackup_to_shell!PG_init+0x42ea 0000004e`65ffbf10 00007ffa`93b657be basebackup_to_shell!PG_init+0x4486 0000004e`65ffbf90 00007ffa`93b616ce basebackup_to_shell!PG_init+0x46d6 0000004e`65ffc010 00007ffa`93b61041 basebackup_to_shell!PG_init+0x5e6 0000004e`65ffc040 00007ff6`5545be58 basebackup_to_shell+0x1041 0000004e`65ffc070 00007ff6`55289171 postgres!bbsink_zstd_new+0x100 0000004e`65ffc0b0 00007ff6`55288bd1 postgres!SendBaseBackup+0x2c8d 0000004e`65ffc160 00007ff6`55288b68 postgres!SendBaseBackup+0x26ed 0000004e`65ffce90 00007ff6`55288b68 postgres!SendBaseBackup+0x2684 0000004e`65ffdbc0 00007ff6`552878d1 postgres!SendBaseBackup+0x2684 0000004e`65ffe8f0 00007ff6`5528661f postgres!SendBaseBackup+0x13ed 0000004e`65fff110 00007ff6`550ad66c postgres!SendBaseBackup+0x13b 0000004e`65fff300 00007ff6`55010da9 postgres!exec_replication_command+0x3c0 0000004e`65fff340 00007ff6`5500e004 postgres!PostgresMain+0xb21 0000004e`65fff530 00007ff6`55001592 postgres!SubPostmasterMain+0x230 0000004e`65fff760 00007ff6`554c6ef0 postgres!main+0x2a2 0000004e`65fff950 00007ffa`91217974 postgres!pg_check_dir+0x68c 0000004e`65fff990 00007ffa`9c84a2f1 KERNEL32!BaseThreadInitThunk+0x14 0000004e`65fff9c0 00000000`00000000 ntdll!RtlUserThreadStart+0x21 2022-05-23 09:10:16.466 GMT [5404][postmaster] LOG: server process (PID 1132) was terminated by exception 0xC0000354 -- Justin
On Sun, May 22, 2022 at 06:26:06PM -0500, Justin Pryzby wrote: > ccache 4.6.1 was released which allows compiling postgres 4.6.1 is now in choco. This is required to use with the current msbuild process. > But with the existing build system, it's no faster anyway, I guess due to poor > use of parallelism. > https://cirrus-ci.com/task/5972008205811712 Actually, it cuts the msbuild compilation time in half [0] (which is not impressive, but also not nothing). cache misses are slower, though. https://cirrus-ci.com/task/5926287305867264 [0] My compiled ccache may have been a non-optimized build... I don't know how to do make this work for msbuild without naming the binary something other than ccache. Maybe that's fine, but better done on the OS image, rather than in the CI config.
On Tue, May 24, 2022 at 09:48:17PM -0700, Andres Freund wrote: > Hi, > > On 2022-05-24 17:17:47 -0500, Justin Pryzby wrote: > > Also, /O2 cuts ~3 minutes off the test time on cirrus, which seems worth it, > > except that it omits frame pointers, which probably breaks debuggability. > > It likely also causes us to use the non-debug C runtime? Which IMO would be > bad, it does detect quite a few problems that are otherwise hard to find. > > > > And when I pass /Oy- to "avoid omitting" frame pointers, several tests crash... > > Huh. Do you get a backtrace containing anything remotely meaningful? I looked at this again. The issue isn't caused by optimizations, but (apparently) by an absence of options in "msbuild --buildtype plain". Adding /MD or /MDd fixes the issue. That's done in the existing build system here: src/tools/msvc/MSBuildProject.pm: runtime => 'MultiThreadedDebugDLL' src/tools/msvc/MSBuildProject.pm: runtime => 'MultiThreadedDLL' https://cirrus-ci.com/task/4895613501308928 BTW: vcvarsall isn't needed in the "check_world" scripts. -- Justin
On Tue, May 24, 2022 at 01:30:39PM -0700, Andres Freund wrote: > On 2022-05-24 14:52:02 -0500, Justin Pryzby wrote: > > > The spurious message should be fixed, of course. I suspect you dont need a > > > wrapper, you can just set CC='ccache cl.exe' or similar? Afaics it's not > > > meaningful to do 'CC=ccache.exe' alone, because then it'll interpret arguments > > > as ccache options, rather than compiler options. > > > > if meson didn't crash CC=ccache.exe might have worked, because I had set > > CCACHE_COMPILER. > > Did you report the issue? Should be simple enough to fix. > > I seriously doubt it's a good idea to use CCACHE_COMPILER - there's no way > meson (or autoconf or ..) can rely on the results of compiler tests that way, > since CCACHE_COMPILER can change at any time. This updated patch doesn't use CCACHE_COMPILER. cache misses are several times slower (12 minute build time vs 2:30 with ninja, without ccache), so it's possible that can be *slower* if the hit ratio is inadequate. ninja on cirrus builds 3x faster with ccache, but msbuild is only ~2x faster, so I recommend using it only with ninja. There's still warts requires using "plain" with /Z7 /MDd.
Вложения
Note that ccache 4.7 was released (and also uploaded to chocolatey). That supports depend mode with MSVC. PCH made cache misses a lot less slow. However, I still haven't found anyt way to improve compilation speed much on cirrusci... -- Justin