runtime: GODEBUG=gccheckmark=1 messes up the GC trigger

[aclements]

Checkmark appears to throw off the heap statistics used to compute the GC trigger.

For example,

$ GODEBUG=gctrace=1,gccheckmark=0 ./go1.test -test.bench=TimeFormat -test.benchtime=10s                          
gc #1 @0.296s 0%: 0+0+0+58+0 ms clock, 0+0+0+0/0/0+0 ms cpu, 4->262->262 MB, 1 P
testing: warning: no tests to run
PASS
BenchmarkTimeFormat gc #2 @2.182s 0%: 0+0+0+0+10 ms clock, 0+0+0+0/0/0+10 ms cpu, 325->325->1 MB, 1 P (forced)
gc #3 @2.185s 0%: 0+0+0+0+3 ms clock, 0+0+0+0/0/0+3 ms cpu, 287->287->0 MB, 1 P (forced)
gc #4 @2.189s 0%: 0+0+0+0+3 ms clock, 0+0+0+0/0/0+3 ms cpu, 287->287->1 MB, 1 P (forced)
gc #5 @2.197s 1%: 0+0+0+0+4 ms clock, 0+0+0+0/0/0+4 ms cpu, 287->287->0 MB, 1 P (forced)
gc #6 @2.601s 1%: 0+0+0+0+17 ms clock, 0+0+0+0/0/0+17 ms cpu, 317->317->0 MB, 1 P (forced)
gc #7 @4.059s 1%: 0+0+0+57+12 ms clock, 0+0+0+3/0/0+12 ms cpu, 396->399->4 MB, 1 P
gc #8 @6.653s 1%: 0+0+0+32+21 ms clock, 0+0+0+2/0/0+21 ms cpu, 489->491->3 MB, 1 P
gc #9 @9.848s 1%: 0+0+0+31+30 ms clock, 0+0+0+2/0/0+30 ms cpu, 532->534->3 MB, 1 P
gc #10 @13.316s 1%: 0+0+0+12+31 ms clock, 0+0+0+3/0/0+31 ms cpu, 555->555->2 MB, 1 P
gc #11 @16.931s 1%: 0+0+0+15+28 ms clock, 0+0+0+2/0/0+28 ms cpu, 561->561->2 MB, 1 P
gc #12 @20.537s 1%: 0+0+0+10+28 ms clock, 0+0+0+2/0/0+28 ms cpu, 561->562->2 MB, 1 P
50000000           396 ns/op

$ GODEBUG=gctrace=1,gccheckmark=1 ./go1.test -test.bench=TimeFormat -test.benchtime=10s                          
gc #1 @0.390s 0%: 0+0+0+56+0 ms clock, 0+0+0+0/0/0+0 ms cpu, 4->262->262 MB, 1 P
testing: warning: no tests to run
PASS
BenchmarkTimeFormat gc #2 @2.391s 0%: 0+0+0+0+8 ms clock, 0+0+0+0/0/0+8 ms cpu, 325->325->1 MB, 1 P (forced)
gc #3 @2.394s 0%: 0+0+0+0+2 ms clock, 0+0+0+0/0/0+2 ms cpu, 1->1->0 MB, 1 P (forced)
gc #4 @2.397s 0%: 0+0+0+0+2 ms clock, 0+0+0+0/0/0+2 ms cpu, 1->1->0 MB, 1 P (forced)
gc #5 @2.404s 0%: 0+0+0+0+3 ms clock, 0+0+0+0/0/0+3 ms cpu, 2->2->1 MB, 1 P (forced)
gc #6 @2.469s 0%: 0+0+0+34+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->5->3 MB, 1 P
gc #7 @2.530s 0%: 0+0+0+30+0 ms clock, 0+0+0+3/0/0+0 ms cpu, 5->7->3 MB, 1 P
gc #8 @2.620s 1%: 0+0+0+33+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 5->9->3 MB, 1 P
gc #9 @2.731s 1%: 0+0+0+31+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 5->10->3 MB, 1 P
gc #10 @2.857s 1%: 0+0+0+29+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 5->12->3 MB, 1 P
gc #11 @2.864s 1%: 0+0+0+0+3 ms clock, 0+0+0+2/0/0+3 ms cpu, 3->3->1 MB, 1 P (forced)
gc #12 @2.929s 1%: 0+0+0+34+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->6->3 MB, 1 P
gc #13 @3.000s 1%: 0+0+0+38+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 6->8->3 MB, 1 P
gc #14 @3.090s 1%: 0+0+0+31+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 6->9->3 MB, 1 P
gc #15 @3.211s 1%: 0+0+0+37+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 6->12->3 MB, 1 P
gc #16 @3.352s 1%: 0+0+0+35+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 6->14->3 MB, 1 P
gc #17 @3.523s 1%: 0+0+0+38+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 5->16->3 MB, 1 P
gc #18 @3.714s 1%: 0+0+0+31+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 5->17->3 MB, 1 P
gc #19 @3.916s 1%: 0+0+0+19+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->18->2 MB, 1 P
gc #20 @4.158s 1%: 0+0+0+32+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->20->3 MB, 1 P
gc #21 @4.409s 1%: 0+0+0+34+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->22->3 MB, 1 P
gc #22 @4.681s 1%: 0+0+0+34+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->24->3 MB, 1 P
gc #23 @4.983s 1%: 0+0+0+34+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->26->3 MB, 1 P
gc #24 @5.315s 1%: 0+0+0+32+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->28->3 MB, 1 P
gc #25 @5.658s 1%: 0+0+0+33+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->30->3 MB, 1 P
gc #26 @6.040s 1%: 0+0+0+35+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->31->3 MB, 1 P
gc #27 @6.413s 1%: 0+0+0+19+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->32->2 MB, 1 P
gc #28 @6.815s 1%: 0+0+0+16+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->33->2 MB, 1 P
gc #29 @7.238s 1%: 0+0+0+18+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->34->2 MB, 1 P
gc #30 @7.681s 1%: 0+0+0+34+0 ms clock, 0+0+0+3/0/0+0 ms cpu, 4->36->3 MB, 1 P
gc #31 @8.134s 1%: 0+0+0+34+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->38->3 MB, 1 P
gc #32 @8.607s 1%: 0+0+0+36+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->40->3 MB, 1 P
gc #33 @9.111s 1%: 0+0+0+35+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->42->3 MB, 1 P
gc #34 @9.634s 1%: 0+0+0+36+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->44->3 MB, 1 P
gc #35 @10.188s 1%: 0+0+0+31+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->46->3 MB, 1 P
gc #36 @10.762s 1%: 0+0+0+33+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->48->3 MB, 1 P
gc #37 @11.345s 0%: 0+0+0+18+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->49->2 MB, 1 P
gc #38 @11.949s 0%: 0+0+0+17+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->50->2 MB, 1 P
gc #39 @12.573s 0%: 0+0+0+19+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->51->2 MB, 1 P
gc #40 @13.198s 0%: 0+0+0+14+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->51->2 MB, 1 P
gc #41 @13.853s 0%: 0+0+0+32+0 ms clock, 0+0+0+2/0/0+0 ms cpu, 4->53->3 MB, 1 P
gc #42 @14.560s 0%: 0+0+0+31+0 ms clock, 0+0+0+3/0/0+0 ms cpu, 4->55->3 MB, 1 P
30000000           398 ns/op

This happens both on the current master (which doesn't have the GC pacer) and with the GC pacer.

@RLH @rsc

[rsc]

@aclements worth looking at soon?

[gopherbot]

CL https://golang.org/cl/11561 mentions this issue.