Thread: ccache, MSVC, and meson

ccache, MSVC, and meson

From
Justin Pryzby
Date:
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.



Re: ccache, MSVC, and meson

From
Andres Freund
Date:
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



Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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



Re: ccache, MSVC, and meson

From
Andres Freund
Date:
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



Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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...



Re: ccache, MSVC, and meson

From
Andres Freund
Date:
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



Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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



Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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.



Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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



Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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.

Attachment

Re: ccache, MSVC, and meson

From
Justin Pryzby
Date:
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