This definitely isn't affecting all DCHECKs. I'm going to work around the problem for the purposes of my CL, via DCHECK_IS_ON(), but it seems suspicuous.

I don't know if it's relevant, but "real official" requires full_wpo_on_official=true also.

Did you check if CHECK also causes this?

Oh, er, wait I assumed you had dcheck_always_on=true. That's awful!

Is it a matter of symbol level?

I'll see if I can figure out what's special about that location.

I can confirm that I can repro (on x86 and x64 fwiw), and that full_wpo_on_official=true doesn't help.

Sooooo crapola. :(

Btw I have an idea for how to fix this in base/logging.h. CL coming soon (well, as soon as things build anyway)

Here's a simpler 1-line change that repros the problem and doesn't require patching in my larger rewrite of the file: https://codereview.chromium.org/2653613004/

(this function is exercised by net_perftests.exe!CookieMonsterTest.TestGetKey)

https://codereview.chromium.org/2653993002/

Oops, we seem to be all doing this. Anyway, as long as they use EAT_STREAM_PARAMETERS directly so that it uses g_swallow_stream rather than constructing an unreachable LogMessage it should be fine.

I've confirmed that this does fix Nick's case in a local build.

Something else we should check is that something like this:

scoped_refptr<TaskRunner> GetTaskRunner();

DCHECK(GetTaskRunner());

is affected by this codegen bug.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/fc670f47ae174fb59497fe5d3315b10cc7601cad

commit fc670f47ae174fb59497fe5d3315b10cc7601cad
Author: dcheng <dcheng@chromium.org>
Date: Wed Jan 25 17:48:43 2017

Make sure DCHECK compiles out completely if DCHECKS aren't enabled.

The MSVC optimizer can get confused when expressions that create
temporaries are completely optimized out.

Before:
2017-01-24  05:59 PM         1,139,712 chrome.exe
2017-01-24  05:53 PM        48,618,496 chrome.dll
2017-01-24  05:59 PM        68,739,584 chrome_child.dll

After:
2017-01-24  06:51 PM         1,136,128 chrome.exe
2017-01-24  06:45 PM        48,265,216 chrome.dll
2017-01-24  06:51 PM        68,245,504 chrome_child.dll

This results in a total savings of ~830KB in a mostly official build.
These numbers don't include the effect of full_wpo_on_official=true,
but it's been confirmed that this codegen bug happens either way.

BUG=684105
R=scottmg@chromium.org

Review-Url: https://codereview.chromium.org/2653073002
Cr-Commit-Position: refs/heads/master@{#446054}

[modify] https://crrev.com/fc670f47ae174fb59497fe5d3315b10cc7601cad/base/logging.h

So I have bad news. I changed Nick's patch to read:

DCHECK((pos == nullptr) || pos < end) << std::string(key, length);

And the generated code now looks like this:

// Lookup a domain key in a byte array generated by make_dafsa.py.
// The rule type is returned if key is found, otherwise kDafsaNotFound is
// returned.
int LookupStringInFixedSet(const unsigned char* graph,
                           size_t length,
                           const char* key,
                           size_t key_length) {
00007FF772D53318  push        r13  
00007FF772D5331A  push        r14  
00007FF772D5331C  push        r15  
00007FF772D5331E  sub         rsp,50h  
00007FF772D53322  mov         rax,qword ptr [__security_cookie (07FF773194C50h)]  
00007FF772D53329  xor         rax,rsp  
00007FF772D5332C  mov         qword ptr [rsp+48h],rax  
00007FF772D53331  xor         r14d,r14d  
  const unsigned char* pos = graph;
  const unsigned char* end = graph + length;
00007FF772D53334  lea         rsi,[rdx+rcx]  
00007FF772D53338  mov         rdi,r8  
00007FF772D5333B  mov         dword ptr [rsp+20h],r14d  
00007FF772D53340  mov         rbp,rcx  
  const unsigned char* offset = pos;
  const char* key_end = key + key_length;
00007FF772D53343  lea         r15,[r8+r9]  
00007FF772D53347  mov         rbx,rcx  
00007FF772D5334A  lea         r13d,[r14+1]  
  while (GetNextOffset(&pos, end, &offset)) {
00007FF772D5334E  cmp         rbp,rsi  
00007FF772D53351  jne         net::LookupStringInFixedSet+4Ch (07FF772D53358h)  
00007FF772D53353  xor         r8b,r8b  
00007FF772D53356  jmp         net::LookupStringInFixedSet+0BBh (07FF772D533C7h)  
00007FF772D53358  lea         r8,[rbp+2]  
00007FF772D5335C  cmp         r8,rsi  
00007FF772D5335F  jb          net::LookupStringInFixedSet+5Dh (07FF772D53369h)  
00007FF772D53361  mov         byte ptr [0],0  
00007FF772D53369  movzx       edx,byte ptr [rbp]  
00007FF772D5336D  mov         eax,edx  
00007FF772D5336F  mov         ecx,edx  
00007FF772D53371  and         eax,60h  
00007FF772D53374  cmp         eax,40h  
00007FF772D53377  je          net::LookupStringInFixedSet+94h (07FF772D533A0h)  
00007FF772D53379  cmp         eax,60h  
00007FF772D5337C  je          net::LookupStringInFixedSet+7Ah (07FF772D53386h)  
00007FF772D5337E  mov         r9,r13  
00007FF772D53381  and         ecx,3Fh  
00007FF772D53384  jmp         net::LookupStringInFixedSet+0A8h (07FF772D533B4h)  
00007FF772D53386  movzx       eax,byte ptr [rbp+1]  
00007FF772D5338A  and         ecx,1Fh  
00007FF772D5338D  shl         rcx,8  
00007FF772D53391  mov         r9d,3  
00007FF772D53397  or          rcx,rax  
00007FF772D5339A  movzx       eax,byte ptr [r8]  
00007FF772D5339E  jmp         net::LookupStringInFixedSet+0A1h (07FF772D533ADh)  
00007FF772D533A0  movzx       eax,byte ptr [rbp+1]  
00007FF772D533A4  mov         r9d,2  
00007FF772D533AA  and         ecx,1Fh  
00007FF772D533AD  shl         rcx,8  
00007FF772D533B1  or          rcx,rax  
00007FF772D533B4  lea         rax,[r9+rbp]  
00007FF772D533B8  add         rbx,rcx  
00007FF772D533BB  test        dl,dl  
00007FF772D533BD  mov         rbp,rsi  
00007FF772D533C0  mov         r8b,r13b  
00007FF772D533C3  cmovns      rbp,rax  
00007FF772D533C7  test        r8b,r8b  
00007FF772D533CA  je          net::LookupStringInFixedSet+19Ah (07FF772D534A6h)  
    DCHECK((pos == nullptr) || pos < end) << std::string(key, length);
00007FF772D533D0  test        r13b,r14b  
00007FF772D533D3  je          net::LookupStringInFixedSet+0FCh (07FF772D53408h)  
00007FF772D533D5  mov         rdx,qword ptr [rsp+40h]  
00007FF772D533DA  and         r14d,0FFFFFFFEh  
00007FF772D533DE  cmp         rdx,10h  
00007FF772D533E2  jb          net::LookupStringInFixedSet+0E8h (07FF772D533F4h)  
00007FF772D533E4  mov         rcx,qword ptr [rsp+28h]  
00007FF772D533E9  inc         rdx  
00007FF772D533EC  mov         r8,r13  
00007FF772D533EF  call        std::_Deallocate (07FF7725A1890h)+100000000h  
00007FF772D533F4  and         qword ptr [rsp+38h],0  
00007FF772D533FA  mov         qword ptr [rsp+40h],0Fh  
00007FF772D53403  mov         byte ptr [rsp+28h],0  
    //   char <char>+ end_char offsets
    //   char <char>+ return value
    //   char end_char offsets
    //   char return value
    //   end_char offsets
    //   return_value
    bool did_consume = false;
00007FF772D53408  xor         dl,dl  
    if (key != key_end && !IsEOL(offset, end)) {
00007FF772D5340A  cmp         rdi,r15  
00007FF772D5340D  je          net::LookupStringInFixedSet+1D1h (07FF772D534DDh)  
00007FF772D53413  cmp         rbx,rsi  
00007FF772D53416  jb          net::LookupStringInFixedSet+113h (07FF772D5341Fh)  
00007FF772D53418  mov         byte ptr [0],dl  
00007FF772D5341F  cmp         byte ptr [rbx],80h  
00007FF772D53422  jae         net::LookupStringInFixedSet+172h (07FF772D5347Eh)  
      // Leading <char> is not a match. Don't dive into this child
      if (!IsMatch(offset, end, key))
00007FF772D53424  cmp         rbx,rsi  
00007FF772D53427  jb          net::LookupStringInFixedSet+125h (07FF772D53431h)  
00007FF772D53429  mov         byte ptr [0],0  
00007FF772D53431  movsx       ecx,byte ptr [rdi]  
00007FF772D53434  movzx       eax,byte ptr [rbx]  
00007FF772D53437  cmp         eax,ecx  
00007FF772D53439  jne         net::LookupStringInFixedSet+42h (07FF772D5334Eh)  
        continue;
      did_consume = true;
      ++offset;
00007FF772D5343F  add         rbx,r13  
00007FF772D53442  mov         dl,r13b  
      ++key;
00007FF772D53445  add         rdi,r13  
      // Possible matches at this point:
      // <char>+ end_char offsets
      // <char>+ return value
      // end_char offsets
      // return value
      // Remove all remaining <char> nodes possible
      while (!IsEOL(offset, end) && key != key_end) {
00007FF772D53448  cmp         rbx,rsi  
00007FF772D5344B  jb          net::LookupStringInFixedSet+149h (07FF772D53455h)  
00007FF772D5344D  mov         byte ptr [0],0  
00007FF772D53455  cmp         byte ptr [rbx],80h  
00007FF772D53458  jae         net::LookupStringInFixedSet+172h (07FF772D5347Eh)  
00007FF772D5345A  cmp         rdi,r15  
00007FF772D5345D  je          net::LookupStringInFixedSet+1D1h (07FF772D534DDh)  
        if (!IsMatch(offset, end, key))
00007FF772D5345F  cmp         rbx,rsi  
00007FF772D53462  jb          net::LookupStringInFixedSet+160h (07FF772D5346Ch)  
00007FF772D53464  mov         byte ptr [0],0  
00007FF772D5346C  movsx       ecx,byte ptr [rdi]  
00007FF772D5346F  movzx       eax,byte ptr [rbx]  
00007FF772D53472  cmp         eax,ecx  
00007FF772D53474  jne         net::LookupStringInFixedSet+19Ah (07FF772D534A6h)  
          return kDafsaNotFound;
        ++key;
00007FF772D53476  add         rdi,r13  
        ++offset;
00007FF772D53479  add         rbx,r13  
      }
00007FF772D5347C  jmp         net::LookupStringInFixedSet+13Ch (07FF772D53448h)  
    }
    // Possible matches at this point:
    // end_char offsets
    // return_value
    // If one or more <char> elements were consumed, a failure
    // to match is terminal. Otherwise, try the next node.
    if (key == key_end) {
00007FF772D5347E  cmp         rdi,r15  
00007FF772D53481  je          net::LookupStringInFixedSet+1D1h (07FF772D534DDh)  
      // The DAFSA guarantees that if the first char is a match, all
      // remaining char elements MUST match if the key is truly present.
      if (did_consume)
        return kDafsaNotFound;
      continue;
    }
    if (!IsEndCharMatch(offset, end, key)) {
00007FF772D53483  cmp         rbx,rsi  
00007FF772D53486  jb          net::LookupStringInFixedSet+184h (07FF772D53490h)  
00007FF772D53488  mov         byte ptr [0],0  
00007FF772D53490  movsx       ecx,byte ptr [rdi]  
00007FF772D53493  movzx       eax,byte ptr [rbx]  
00007FF772D53496  bts         ecx,7  
00007FF772D5349A  cmp         eax,ecx  
00007FF772D5349C  je          net::LookupStringInFixedSet+1C3h (07FF772D534CFh)  
      if (did_consume)
00007FF772D5349E  test        dl,dl  
00007FF772D534A0  je          net::LookupStringInFixedSet+42h (07FF772D5334Eh)  
  return kDafsaNotFound;  // No match
00007FF772D534A6  or          eax,0FFFFFFFFh  
}
00007FF772D534A9  mov         rcx,qword ptr [rsp+48h]  
00007FF772D534AE  xor         rcx,rsp  
00007FF772D534B1  call        __security_check_cookie (07FF772F0BB50h)  
00007FF772D534B6  lea         r11,[rsp+50h]  
00007FF772D534BB  mov         rbx,qword ptr [r11+30h]  
00007FF772D534BF  mov         rbp,qword ptr [r11+48h]  
00007FF772D534C3  mov         rsp,r11  
00007FF772D534C6  pop         r15  
00007FF772D534C8  pop         r14  
00007FF772D534CA  pop         r13  
00007FF772D534CC  pop         rdi  
00007FF772D534CD  pop         rsi  
00007FF772D534CE  ret  
        return kDafsaNotFound;  // Unexpected
      continue;
    }
    ++key;
00007FF772D534CF  add         rdi,r13  
    pos = ++offset;  // Dive into child
00007FF772D534D2  add         rbx,r13  
    pos = ++offset;  // Dive into child
00007FF772D534D5  mov         rbp,rbx  
  }
00007FF772D534D8  jmp         net::LookupStringInFixedSet+42h (07FF772D5334Eh)  
      int return_value;
      if (GetReturnValue(offset, end, &return_value))
00007FF772D534DD  cmp         rbx,rsi  
00007FF772D534E0  jb          net::LookupStringInFixedSet+1DEh (07FF772D534EAh)  
00007FF772D534E2  mov         byte ptr [0],0  
00007FF772D534EA  mov         al,byte ptr [rbx]  
00007FF772D534EC  and         al,0E0h  
00007FF772D534EE  cmp         al,80h  
00007FF772D534F0  jne         net::LookupStringInFixedSet+192h (07FF772D5349Eh)  
00007FF772D534F2  movzx       eax,byte ptr [rbx]  
00007FF772D534F5  and         eax,0Fh  
        return return_value;
00007FF772D534F8  jmp         net::LookupStringInFixedSet+19Dh (07FF772D534A9h)  

As the disassembly shows, having any sort of non-trivial destructor confuses MSVC =(

(I'm going to try with wpo and see if it makes a difference)

I think it probably won't unfortunately. :( That matches what I found in the CHECK case, which is why the EAT macro is so goofy.

Maybe we are relying too much on the optimizer and should instead give assistance with the preprocessor, so that the compiler never sees the extra stream parameters at all. This would require changing a bunch of code, but it may be necessary if we can't count on the optimizer.

I am not surprised that the VC++ optimizer doesn't fully remove this code. When looking at global initializers last month I found some where the compiler had *mostly* removed all of the code, but it left multiple redundant writes of zero to a location on the stack - a clear NOP, caused by the optimizer not cleaning up SEH state after optimizing away everything else.

Yeah, that's an option I think we should consider. That being said, it's not a particularly complicated optimization: it's a simple dead-branch elimination, and every other compiler can do it =P

I haven't narrowed down exactly what causes this, but from my observations in https://codereview.chromium.org/2660533002/:

void F() {
  DLOG(INFO) << "Optimized";
  if (condition) {
    // Do other stuff.
    DLOG(INFO) << "Not optimized.";
  }
}

DCHECK / DLOG / etc in the function's top-level block appear to be correctly optimized, while DCHECK / DLOG statements that are nested in sub blocks are not.
There's at least one extra condition to trigger this bug that I haven't managed to track down yet... the provided snippet is simple enough that the optimizer correctly eliminates all the logging code.

The good news is... DLOG/DVLOG mostly appear to be unaffected by this bug--it's only about a 20-30KB change from changing it to use EAT_STREAM_PARAMETERS in NDEBUG mode.

The bad news is if the log statement isn't completely optimized out, code like:

  DLOG(info) << std::string("abc");

or

  DCHECK(condition) << std::string("def");

ends up still leaving artifacts in the binary.

I've been testing alternative logging implementations (https://codereview.chromium.org/2656053002/) to see if I can come up with something more optimizer friendly, but so far, no luck.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/37b415b92e8873dad49d71be1c7562319926a3c5

commit 37b415b92e8873dad49d71be1c7562319926a3c5
Author: dcheng <dcheng@chromium.org>
Date: Fri Jan 27 20:17:43 2017

Remove macros that combine DCHECK with other expressions via the comma operator.

Constructs like this make it harder to tweak how the DCHECK macro works.

BUG=684105

Review-Url: https://codereview.chromium.org/2658023005
Cr-Commit-Position: refs/heads/master@{#446748}

[modify] https://crrev.com/37b415b92e8873dad49d71be1c7562319926a3c5/media/blink/webmediaplayer_impl.cc

I was curious if this was a recent-ish regression (maybe due to a toolchain change), but it appears to have been happening for a very long time.

I looked for an affected DCHECK that's been in the codebase for a long time, and found the following one, at the bottom of net::SpdyFramer::ProcessInput() https://cs.chromium.org/chromium/src/net/spdy/spdy_framer.cc?type=cs&q=SpdyFramer&sq=package:chromium&l=619

I see what looks like an unnecessary call to ~LogMessage as far back as 32.0.1700.107 (i.e. 2/1/2014), which is the oldest build I could find symbols for. (There's a LOG(DFATAL) here too, which ought not to compile out, but I'm pretty sure the ~LogMessage I see is from the DCHECK after the bottom: label)

It's not completely fixed, but I haven't been able to find any more obvious gains.

Since we're having some issues with stack sizes, going to mark this as fixed and request a merge.

Actually I guess it doesn't hurt to keep this open if someone else has ideas.

Locally, I've tried implementing a NullStream class with a trivial ctor/dtor and a completely empty operator<<, but that didn't seem to help either.

This bug requires manual review: We are only 11 days from stable.
Please contact the milestone owner if you have questions.
Owners: amineer@(clank), cmasso@(bling), ketakid@(cros), govind@(desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

https://chromium.googlesource.com/chromium/src.git/+/fc670f47ae174fb59497fe5d3315b10cc7601cad is the patch I'd like to merge. It's adjusting the definition of the DCHECK macros in official builds. Since DCHECKs are skipped in official builds, the changed code only affects a conditional branch that's never taken (and should be optimized out), but wasn't on MSVC++. Because this branch is never actually executed, this patch is safe.

As for the why, PGO binaries end up inlining a bunch of code for logging code that's completely used, leading to huge stack frames that cause us to overflow the stack.

completely used => completely unused, doh.

+1 on merging that. It's very safe and may help a lot with the stack overflow crashes we're seeing.

Approving merge to M57 branch 2987 based on comment #28, #29 and #31. Please merge ASAP. Thank you.

Please merge your change to M57 branch 2987 latest by 5:00 PM PT Friday, 03/03 (sooner the better) so we can take it in for M57 Desktop Stable cut. Thank you.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/b6026eb7489ef89100fd8126b2a5d80d08bb9f45

commit b6026eb7489ef89100fd8126b2a5d80d08bb9f45
Author: Daniel Cheng <dcheng@chromium.org>
Date: Thu Mar 02 19:49:26 2017

Make sure DCHECK compiles out completely if DCHECKS aren't enabled.

The MSVC optimizer can get confused when expressions that create
temporaries are completely optimized out.

Before:
2017-01-24  05:59 PM         1,139,712 chrome.exe
2017-01-24  05:53 PM        48,618,496 chrome.dll
2017-01-24  05:59 PM        68,739,584 chrome_child.dll

After:
2017-01-24  06:51 PM         1,136,128 chrome.exe
2017-01-24  06:45 PM        48,265,216 chrome.dll
2017-01-24  06:51 PM        68,245,504 chrome_child.dll

This results in a total savings of ~830KB in a mostly official build.
These numbers don't include the effect of full_wpo_on_official=true,
but it's been confirmed that this codegen bug happens either way.

BUG=684105
R=scottmg@chromium.org

Review-Url: https://codereview.chromium.org/2653073002
Cr-Commit-Position: refs/heads/master@{#446054}
(cherry picked from commit fc670f47ae174fb59497fe5d3315b10cc7601cad)

Review-Url: https://codereview.chromium.org/2724253004 .
Cr-Commit-Position: refs/branch-heads/2987@{#741}
Cr-Branched-From: ad51088c0e8776e8dcd963dbe752c4035ba6dab6-refs/heads/master@{#444943}

[modify] https://crrev.com/b6026eb7489ef89100fd8126b2a5d80d08bb9f45/base/logging.h

I'd be interested in knowing exactly how much this affects the official build sizes.

As discussed in https://www.chromium.org/developers/windows-binary-sizes, tools\win\pe_summarize.py can be used to easily summarize differences in section sizes (just unzip the before and after builds onto your Windows machine), and SymbolSort (SymbolSort -in new\chrome.dll.pdb -diff old\chrome.dll.pdb -out change.txt) can give details on exactly where size changes happened.

From pe_summarize.py:

Memory size change from 57.0.2987.89\chrome-win64-pgo\chrome.exe to 57.0.2987.91\chrome-win64-pgo\chrome.exe
       .text:   -3488 bytes change
       .data:     -16 bytes change
      .pdata:      24 bytes change
      .reloc:       4 bytes change
Total change:   -3476 bytes

Memory size change from 57.0.2987.89\chrome-win64-pgo\chrome.dll to 57.0.2987.91\chrome-win64-pgo\chrome.dll
       .text: -441952 bytes change
      .rdata:  -27088 bytes change
       .data:    -160 bytes change
      .pdata:   -3624 bytes change
      .reloc:       4 bytes change
Total change: -472820 bytes

Memory size change from 57.0.2987.89\chrome-win64-pgo\chrome_child.dll to 57.0.2987.91\chrome-win64-pgo\chrome_child.dll
       .text: -336596 bytes change
      .rdata:  -49792 bytes change
       .data:      -8 bytes change
      .pdata:  -19452 bytes change
      .reloc:     324 bytes change
Total change: -405524 bytes

I've attached the output from SymbolSort, but it seems pretty noisy due to PGO.

Deleted: pgo-chrome_child_dll-change.txt 2.2 MB

pgo-chrome_child_dll-change.txt 2.2 MB View Download

Deleted: pgo-chrome_dll-change.txt 2.1 MB

pgo-chrome_dll-change.txt 2.1 MB View Download

Those SymbolSort results are noisier than I would have expected. Pity. Thanks for sharing the other data. That's some nice changes.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/6a592ee0e21c46e00bc003c57494f7390145e9ac

commit 6a592ee0e21c46e00bc003c57494f7390145e9ac
Author: Wez <wez@chromium.org>
Date: Fri May 25 20:29:07 2018

Remove redundant DCHECK_IS_ON() condition in DCHECK_OP() implementation.

The implementation was wrapped with a DCHECK_IS_ON() condition by
https://codereview.chromium.org/2653073002/ but the DCHECK_IS_ON() check
inside the implementation was not removed. Remove it to make the macro
a little easier to read.

Bug: 684105
Change-Id: Ia0e923f89432b31fc2ec32b7438e5e6c416433bf
Reviewed-on: https://chromium-review.googlesource.com/1072455
Commit-Queue: Daniel Cheng <dcheng@chromium.org>
Reviewed-by: Daniel Cheng <dcheng@chromium.org>
Cr-Commit-Position: refs/heads/master@{#561995}
[modify] https://crrev.com/6a592ee0e21c46e00bc003c57494f7390145e9ac/base/logging.h