$ GODEBUG=gcpacertrace=1,gctrace=1 taskset -c 0 bug14812
pacer: assist ratio=+3.253021e+000 (scan 3 MB in 4->5 MB) workers=0+1
pacer: H_m_prev=2236962 h_t=+8.750000e-001 H_T=4194304 h_a=+8.750001e-001 H_a=4194304 h_g=+1.000000e+000 H_g=4473924 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=3212288 goalΔ=+1.250000e-001 actualΔ=+1.117587e-007 u_a/u_g=+1.000000e+000
gc 1 @0.007s 40%: 0.11+5.1+0.12 ms clock, 0.11+0/5.0/0+0.12 ms cpu, 4->4->3 MB, 5 MB goal, 1 P
pacer: sweep done at heap size 3MB; allocated 0MB of spans; swept 512 pages at +2.124320e-004 pages/byte
pacer: assist ratio=+5.971954e+000 (scan 5 MB in 6->7 MB) workers=0+1
pacer: H_m_prev=3689344 h_t=+9.374999e-001 H_T=7148103 h_a=+9.385040e-001 H_a=7151808 h_g=+1.000000e+000 H_g=7378688 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=6175736 goalΔ=+6.250006e-002 actualΔ=+1.004028e-003 u_a/u_g=+1.000000e+000
gc 2 @0.019s 49%: 0.089+8.8+0.13 ms clock, 0.089+0/8.8/0+0.13 ms cpu, 6->6->6 MB, 7 MB goal, 1 P
pacer: sweep done at heap size 6MB; allocated 0MB of spans; swept 902 pages at +1.597828e-004 pages/byte
pacer: assist ratio=+1.153557e+001 (scan 11 MB in 13->14 MB) workers=0+1
pacer: H_m_prev=7046040 h_t=+9.500000e-001 H_T=13739778 h_a=+1.098590e+000 H_a=14786752 h_g=+1.000000e+000 H_g=14092080 u_a=+4.981310e-001 u_g=+2.500000e-001 W_a=12840104 goalΔ=+5.000000e-002 actualΔ=+1.485904e-001 u_a/u_g=+1.992524e+000
gc 3 @0.040s 52%: 0.10+21+0.21 ms clock, 0.10+5.2/12/0+0.21 ms cpu, 13->14->13 MB, 14 MB goal, 1 P
pacer: sweep done at heap size 13MB; allocated 0MB of spans; swept 1834 pages at +1.664555e-004 pages/byte
pacer: assist ratio=+9.338967e+000 (scan 22 MB in 25->27 MB) workers=0+1
pacer: H_m_prev=14591352 h_t=+8.269650e-001 H_T=26657889 h_a=+9.981370e-001 H_a=29155520 h_g=+1.000000e+000 H_g=29182704 u_a=+7.118111e-001 u_g=+2.500000e-001 W_a=25386672 goalΔ=+1.730350e-001 actualΔ=+1.711720e-001 u_a/u_g=+2.847244e+000
gc 4 @0.087s 52%: 0.10+46+0.19 ms clock, 0.10+21/16/0+0.19 ms cpu, 25->27->27 MB, 27 MB goal, 1 P
pacer: sweep done at heap size 27MB; allocated 0MB of spans; swept 3588 pages at +1.967077e-004 pages/byte
pacer: assist ratio=+4.463766e+000 (scan 40 MB in 45->54 MB) workers=0+1
pacer: H_m_prev=28797984 h_t=+6.697983e-001 H_T=48086825 h_a=+9.474724e-001 H_a=56083280 h_g=+1.000000e+000 H_g=57595968 u_a=+5.452291e-001 u_g=+2.500000e-001 W_a=40943648 goalΔ=+3.302017e-001 actualΔ=+2.776741e-001 u_a/u_g=+2.180916e+000
gc 5 @0.569s 19%: 0.18+84+0.20 ms clock, 0.18+24/30/0+0.20 ms cpu, 45->53->44 MB, 54 MB goal, 1 P
Higher latency than expected at iteration 4.  Tick was delayed 20.788537ms
pacer: sweep done at heap size 46MB; allocated 2MB of spans; swept 6869 pages at +2.906206e-004 pages/byte
pacer: assist ratio=+2.894467e+000 (scan 59 MB in 67->88 MB) workers=0+1
pacer: H_m_prev=46389536 h_t=+5.321071e-001 H_T=71073738 h_a=+6.828647e-001 H_a=78067312 h_g=+1.000000e+000 H_g=92779072 u_a=+5.049315e-001 u_g=+2.500000e-001 W_a=35039824 goalΔ=+4.678929e-001 actualΔ=+1.507576e-001 u_a/u_g=+2.019726e+000
gc 6 @1.022s 14%: 0.20+75+0.21 ms clock, 0.20+19/15/15+0.21 ms cpu, 67->74->37 MB, 88 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 0MB of spans; swept 9555 pages at +4.096286e-004 pages/byte
pacer: assist ratio=+3.694326e+000 (scan 54 MB in 61->75 MB) workers=0+1
Higher latency than expected at iteration 12.  Tick was delayed 20.018315ms
pacer: H_m_prev=39710368 h_t=+6.138091e-001 H_T=64084952 h_a=+8.725351e-001 H_a=74359056 h_g=+1.000000e+000 H_g=79420736 u_a=+3.657233e-001 u_g=+2.500000e-001 W_a=52843184 goalΔ=+3.861909e-001 actualΔ=+2.587260e-001 u_a/u_g=+1.462893e+000
gc 7 @1.440s 13%: 0.16+116+0.24 ms clock, 0.16+13/31/38+0.24 ms cpu, 61->70->57 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 59MB; allocated 2MB of spans; swept 9103 pages at +2.534331e-004 pages/byte
pacer: assist ratio=+3.742529e+000 (scan 81 MB in 92->114 MB) workers=0+1
Higher latency than expected at iteration 16.  Tick was delayed 35.14135ms
pacer: H_m_prev=59850576 h_t=+6.176603e-001 H_T=96817899 h_a=+6.262070e-001 H_a=97329424 h_g=+1.000000e+000 H_g=119701152 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=51797744 goalΔ=+3.823397e-001 actualΔ=+8.546692e-003 u_a/u_g=+1.000000e+000
gc 8 @1.854s 11%: 0.11+81+0.20 ms clock, 0.11+0/20/58+0.20 ms cpu, 92->92->55 MB, 114 MB goal, 1 P
pacer: sweep done at heap size 57MB; allocated 1MB of spans; swept 11907 pages at +2.577848e-004 pages/byte
pacer: assist ratio=+8.168554e+000 (scan 89 MB in 101->111 MB) workers=0+1
pacer: H_m_prev=58713408 h_t=+8.045568e-001 H_T=105951679 h_a=+8.667079e-001 H_a=109600784 h_g=+1.000000e+000 H_g=117426816 u_a=+7.978462e-001 u_g=+2.500000e-001 W_a=32923984 goalΔ=+1.954432e-001 actualΔ=+6.215113e-002 u_a/u_g=+3.191385e+000
gc 9 @2.853s 9%: 0.20+63+0.41 ms clock, 0.20+35/15/0+0.41 ms cpu, 101->104->35 MB, 111 MB goal, 1 P
pacer: sweep done at heap size 48MB; allocated 12MB of spans; swept 13408 pages at +4.634272e-004 pages/byte
pacer: assist ratio=+8.097382e+000 (scan 56 MB in 64->71 MB) workers=0+1
Higher latency than expected at iteration 28.  Tick was delayed 23.878261ms
pacer: H_m_prev=37331200 h_t=+8.031043e-001 H_T=67312047 h_a=+9.947270e-001 H_a=74465552 h_g=+1.000000e+000 H_g=74662400 u_a=+6.501629e-001 u_g=+2.500000e-001 W_a=62997664 goalΔ=+1.968957e-001 actualΔ=+1.916227e-001 u_a/u_g=+2.600652e+000
gc 10 @3.036s 11%: 0.25+109+0.22 ms clock, 0.25+43/35/10+0.22 ms cpu, 64->71->68 MB, 71 MB goal, 1 P
pacer: sweep done at heap size 69MB; allocated 1MB of spans; swept 9116 pages at +2.003251e-004 pages/byte
pacer: assist ratio=+4.205826e+000 (scan 99 MB in 112->136 MB) workers=0+1
Higher latency than expected at iteration 36.  Tick was delayed 40.25449ms
pacer: H_m_prev=71361168 h_t=+6.523802e-001 H_T=117915784 h_a=+7.722295e-001 H_a=126468368 h_g=+1.000000e+000 H_g=142722336 u_a=+6.533140e-001 u_g=+2.500000e-001 W_a=43419504 goalΔ=+3.476198e-001 actualΔ=+1.198493e-001 u_a/u_g=+2.613256e+000
gc 11 @3.838s 10%: 0.11+93+0.24 ms clock, 0.11+37/20/0+0.24 ms cpu, 112->120->46 MB, 136 MB goal, 1 P
pacer: sweep done at heap size 67MB; allocated 20MB of spans; swept 15464 pages at +4.849332e-004 pages/byte
pacer: assist ratio=+4.470199e+000 (scan 69 MB in 78->93 MB) workers=0+1
pacer: H_m_prev=49190432 h_t=+6.695917e-001 H_T=82127937 h_a=+8.688724e-001 H_a=91930640 h_g=+1.000000e+000 H_g=98380864 u_a=+6.404013e-001 u_g=+2.500000e-001 W_a=51375624 goalΔ=+3.304083e-001 actualΔ=+1.992807e-001 u_a/u_g=+2.561605e+000
gc 12 @4.081s 11%: 0.11+93+0.18 ms clock, 0.11+36/30/0+0.18 ms cpu, 78->87->55 MB, 93 MB goal, 1 P
Higher latency than expected at iteration 39.  Tick was delayed 33.424721ms
pacer: sweep done at heap size 63MB; allocated 7MB of spans; swept 11251 pages at +3.443175e-004 pages/byte
pacer: assist ratio=+3.322591e+000 (scan 77 MB in 87->110 MB) workers=0+1
pacer: H_m_prev=58190712 h_t=+5.795566e-001 H_T=91915525 h_a=+6.386662e-001 H_a=95355152 h_g=+1.000000e+000 H_g=116381424 u_a=+3.804716e-001 u_g=+2.500000e-001 W_a=42860224 goalΔ=+4.204434e-001 actualΔ=+5.910955e-002 u_a/u_g=+1.521886e+000
gc 13 @4.357s 11%: 0.19+73+0.17 ms clock, 0.19+9.6/30/24+0.17 ms cpu, 87->90->46 MB, 110 MB goal, 1 P
pacer: sweep done at heap size 46MB; allocated 0MB of spans; swept 11666 pages at +3.320378e-004 pages/byte
pacer: assist ratio=+6.048463e+000 (scan 71 MB in 80->92 MB) workers=0+1
Higher latency than expected at iteration 46.  Tick was delayed 32.547045ms
pacer: H_m_prev=48581040 h_t=+7.447993e-001 H_T=84764165 h_a=+8.644973e-001 H_a=90579216 h_g=+1.000000e+000 H_g=97162080 u_a=+7.226284e-001 u_g=+2.500000e-001 W_a=51671112 goalΔ=+2.552007e-001 actualΔ=+1.196979e-001 u_a/u_g=+2.890514e+000
gc 14 @4.835s 12%: 0.23+93+0.22 ms clock, 0.23+44/32/0+0.22 ms cpu, 80->86->55 MB, 92 MB goal, 1 P
pacer: sweep done at heap size 64MB; allocated 8MB of spans; swept 11083 pages at +2.777829e-004 pages/byte
pacer: assist ratio=+4.999836e+000 (scan 83 MB in 94->111 MB) workers=0+1
pacer: H_m_prev=58544936 h_t=+6.994054e-001 H_T=99491579 h_a=+8.755778e-001 H_a=109805584 h_g=+1.000000e+000 H_g=117089872 u_a=+6.675724e-001 u_g=+2.500000e-001 W_a=59290656 goalΔ=+3.005946e-001 actualΔ=+1.761724e-001 u_a/u_g=+2.670290e+000
gc 15 @5.170s 12%: 0.12+104+0.21 ms clock, 0.12+43/34/0+0.21 ms cpu, 94->104->64 MB, 111 MB goal, 1 P
Higher latency than expected at iteration 50.  Tick was delayed 35.301847ms
pacer: sweep done at heap size 64MB; allocated 0MB of spans; swept 13433 pages at +3.340422e-004 pages/byte
pacer: assist ratio=+3.703527e+000 (scan 91 MB in 103->128 MB) workers=0+1
pacer: H_m_prev=67148784 h_t=+6.144870e-001 H_T=108410836 h_a=+6.341638e-001 H_a=109732112 h_g=+1.000000e+000 H_g=134297568 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=46652360 goalΔ=+3.855130e-001 actualΔ=+1.967683e-002 u_a/u_g=+1.000000e+000
gc 16 @5.824s 11%: 0.21+82+0.21 ms clock, 0.21+0/21/55+0.21 ms cpu, 103->104->50 MB, 128 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 0MB of spans; swept 13421 pages at +3.263737e-004 pages/byte
pacer: assist ratio=+7.849721e+000 (scan 80 MB in 90->100 MB) workers=0+1
Higher latency than expected at iteration 64.  Tick was delayed 20.736016ms
pacer: H_m_prev=52884232 h_t=+7.974051e-001 H_T=95054386 h_a=+8.504931e-001 H_a=97861904 h_g=+1.000000e+000 H_g=105768464 u_a=+7.335868e-001 u_g=+2.500000e-001 W_a=31208928 goalΔ=+2.025949e-001 actualΔ=+5.308799e-002 u_a/u_g=+2.934347e+000
gc 17 @6.634s 11%: 0.17+56+0.23 ms clock, 0.17+27/21/0+0.23 ms cpu, 90->93->33 MB, 100 MB goal, 1 P
pacer: sweep done at heap size 42MB; allocated 9MB of spans; swept 11972 pages at +4.275210e-004 pages/byte
pacer: assist ratio=+8.984493e+000 (scan 54 MB in 61->67 MB) workers=0+1
Higher latency than expected at iteration 67.  Tick was delayed 24.315046ms
pacer: H_m_prev=35394016 h_t=+8.208132e-001 H_T=64445892 h_a=+9.150378e-001 H_a=67780880 h_g=+1.000000e+000 H_g=70788032 u_a=+7.236459e-001 u_g=+2.500000e-001 W_a=41011896 goalΔ=+1.791868e-001 actualΔ=+9.422460e-002 u_a/u_g=+2.894584e+000
gc 18 @6.938s 11%: 0.11+68+0.24 ms clock, 0.11+32/26/0+0.24 ms cpu, 61->64->44 MB, 67 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 0MB of spans; swept 8300 pages at +2.375772e-004 pages/byte
pacer: assist ratio=+6.944303e+000 (scan 69 MB in 78->88 MB) workers=0+1
pacer: H_m_prev=46489544 h_t=+7.740361e-001 H_T=82474130 h_a=+7.963021e-001 H_a=83509264 h_g=+1.000000e+000 H_g=92979088 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=41899032 goalΔ=+2.259639e-001 actualΔ=+2.226595e-002 u_a/u_g=+1.000000e+000
gc 19 @7.595s 10%: 0.13+68+0.24 ms clock, 0.13+0/19/46+0.24 ms cpu, 78->79->45 MB, 88 MB goal, 1 P
pacer: sweep done at heap size 45MB; allocated 0MB of spans; swept 10223 pages at +2.520496e-004 pages/byte
pacer: assist ratio=+1.336533e+001 (scan 75 MB in 84->90 MB) workers=0+1
pacer: H_m_prev=47504008 h_t=+8.758851e-001 H_T=89112060 h_a=+8.770926e-001 H_a=89169424 h_g=+1.000000e+000 H_g=95008016 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=31783096 goalΔ=+1.241149e-001 actualΔ=+1.207557e-003 u_a/u_g=+1.000000e+000
gc 20 @8.246s 10%: 0.26+52+0.22 ms clock, 0.26+0/16/35+0.22 ms cpu, 84->85->34 MB, 90 MB goal, 1 P
pacer: sweep done at heap size 49MB; allocated 15MB of spans; swept 10913 pages at +3.332347e-004 pages/byte
pacer: assist ratio=+2.742008e+001 (scan 58 MB in 66->68 MB) workers=0+1
pacer: H_m_prev=36056616 h_t=+9.373388e-001 H_T=69853879 h_a=+9.668415e-001 H_a=70917648 h_g=+1.000000e+000 H_g=72113232 u_a=+8.945083e-001 u_g=+2.500000e-001 W_a=29829840 goalΔ=+6.266123e-002 actualΔ=+2.950272e-002 u_a/u_g=+3.578033e+000
gc 21 @8.919s 9%: 0.18+51+0.22 ms clock, 0.18+33/15/0+0.22 ms cpu, 66->67->32 MB, 68 MB goal, 1 P
pacer: sweep done at heap size 39MB; allocated 7MB of spans; swept 8685 pages at +2.900274e-004 pages/byte
pacer: assist ratio=+2.017148e+001 (scan 54 MB in 61->64 MB) workers=0+1
pacer: H_m_prev=33840384 h_t=+9.158885e-001 H_T=64834403 h_a=+9.300703e-001 H_a=65314320 h_g=+1.000000e+000 H_g=67680768 u_a=+2.929846e-001 u_g=+2.500000e-001 W_a=30953264 goalΔ=+8.411146e-002 actualΔ=+1.418176e-002 u_a/u_g=+1.171938e+000
gc 22 @9.429s 9%: 0.17+50+0.25 ms clock, 0.17+2.1/15/31+0.25 ms cpu, 61->62->33 MB, 64 MB goal, 1 P
pacer: sweep done at heap size 54MB; allocated 21MB of spans; swept 8001 pages at +2.477246e-004 pages/byte
pacer: assist ratio=+3.435260e+001 (scan 57 MB in 65->66 MB) workers=0+1
pacer: H_m_prev=35115136 h_t=+9.496342e-001 H_T=68461669 h_a=+9.542538e-001 H_a=68623888 h_g=+1.000000e+000 H_g=70230272 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=34729880 goalΔ=+5.036581e-002 actualΔ=+4.619608e-003 u_a/u_g=+1.000000e+000
gc 23 @9.810s 9%: 0.12+53+0.23 ms clock, 0.12+0/13/39+0.23 ms cpu, 65->65->37 MB, 66 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 0MB of spans; swept 8405 pages at +2.310720e-004 pages/byte
pacer: assist ratio=+3.450673e+001 (scan 64 MB in 73->75 MB) workers=0+1
pacer: H_m_prev=39392120 h_t=+9.500000e-001 H_T=76814634 h_a=+9.851771e-001 H_a=78200336 h_g=+1.000000e+000 H_g=78784240 u_a=+7.618435e-001 u_g=+2.500000e-001 W_a=46537216 goalΔ=+5.000000e-002 actualΔ=+3.517714e-002 u_a/u_g=+3.047374e+000
gc 24 @10.322s 9%: 0.12+73+0.20 ms clock, 0.12+37/31/0+0.20 ms cpu, 73->74->50 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 63MB; allocated 13MB of spans; swept 9574 pages at +2.013108e-004 pages/byte
pacer: assist ratio=+2.166291e+001 (scan 85 MB in 96->100 MB) workers=0+1
pacer: H_m_prev=52753232 h_t=+9.214011e-001 H_T=101360115 h_a=+9.504212e-001 H_a=102891024 h_g=+1.000000e+000 H_g=105506464 u_a=+8.774343e-001 u_g=+2.500000e-001 W_a=34435592 goalΔ=+7.859895e-002 actualΔ=+2.902018e-002 u_a/u_g=+3.509737e+000
gc 25 @10.817s 9%: 0.23+69+0.22 ms clock, 0.23+43/19/0+0.22 ms cpu, 96->98->37 MB, 100 MB goal, 1 P
pacer: sweep done at heap size 41MB; allocated 4MB of spans; swept 12588 pages at +3.650757e-004 pages/byte
pacer: assist ratio=+1.874835e+001 (scan 62 MB in 71->74 MB) workers=0+1
pacer: H_m_prev=39052664 h_t=+9.097739e-001 H_T=74581759 h_a=+9.655136e-001 H_a=76758544 h_g=+1.000000e+000 H_g=78105328 u_a=+7.245036e-001 u_g=+2.500000e-001 W_a=40722248 goalΔ=+9.022608e-002 actualΔ=+5.573973e-002 u_a/u_g=+2.898014e+000
gc 26 @11.452s 9%: 0.15+70+0.20 ms clock, 0.15+33/30/0+0.20 ms cpu, 71->73->44 MB, 74 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 0MB of spans; swept 9398 pages at +2.390966e-004 pages/byte
pacer: assist ratio=+1.317159e+001 (scan 72 MB in 82->88 MB) workers=0+1
pacer: H_m_prev=46166296 h_t=+8.741197e-001 H_T=86521164 h_a=+9.282892e-001 H_a=89021968 h_g=+1.000000e+000 H_g=92332592 u_a=+6.629573e-001 u_g=+2.500000e-001 W_a=41417176 goalΔ=+1.258803e-001 actualΔ=+5.416946e-002 u_a/u_g=+2.651829e+000
gc 27 @12.061s 9%: 0.25+72+0.20 ms clock, 0.25+30/30/4.8+0.20 ms cpu, 82->84->44 MB, 88 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 0MB of spans; swept 10895 pages at +2.752962e-004 pages/byte
pacer: assist ratio=+1.225095e+001 (scan 73 MB in 83->89 MB) workers=0+1
pacer: H_m_prev=46951512 h_t=+8.652358e-001 H_T=87575639 h_a=+9.218632e-001 H_a=90234384 h_g=+1.000000e+000 H_g=93903024 u_a=+8.712616e-001 u_g=+2.500000e-001 W_a=34704672 goalΔ=+1.347642e-001 actualΔ=+5.662745e-002 u_a/u_g=+3.485047e+000
gc 28 @12.648s 9%: 0.16+61+0.21 ms clock, 0.16+37/14/0+0.21 ms cpu, 83->86->37 MB, 89 MB goal, 1 P
pacer: sweep done at heap size 39MB; allocated 2MB of spans; swept 11043 pages at +3.476086e-004 pages/byte
pacer: assist ratio=+9.768305e+000 (scan 60 MB in 68->75 MB) workers=0+1
pacer: H_m_prev=39351680 h_t=+8.339432e-001 H_T=72168747 h_a=+9.599464e-001 H_a=77127184 h_g=+1.000000e+000 H_g=78703360 u_a=+8.613007e-001 u_g=+2.500000e-001 W_a=55465248 goalΔ=+1.660568e-001 actualΔ=+1.260032e-001 u_a/u_g=+3.445203e+000
gc 29 @13.109s 9%: 0.11+92+0.21 ms clock, 0.11+56/22/0+0.21 ms cpu, 68->73->59 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 65MB; allocated 5MB of spans; swept 9443 pages at +2.199273e-004 pages/byte
pacer: assist ratio=+5.010977e+000 (scan 90 MB in 101->119 MB) workers=0+1
pacer: H_m_prev=62843744 h_t=+6.999184e-001 H_T=106829234 h_a=+7.923742e-001 H_a=112639504 h_g=+1.000000e+000 H_g=125687488 u_a=+6.802931e-001 u_g=+2.500000e-001 W_a=41660720 goalΔ=+3.000816e-001 actualΔ=+9.245581e-002 u_a/u_g=+2.721172e+000
gc 30 @13.669s 10%: 0.16+77+0.25 ms clock, 0.16+33/27/0+0.25 ms cpu, 101->107->45 MB, 119 MB goal, 1 P
pacer: sweep done at heap size 48MB; allocated 3MB of spans; swept 13778 pages at +4.157453e-004 pages/byte
pacer: assist ratio=+5.529282e+000 (scan 68 MB in 77->90 MB) workers=0+1
pacer: H_m_prev=47211696 h_t=+7.241651e-001 H_T=81400758 h_a=+8.434269e-001 H_a=87031312 h_g=+1.000000e+000 H_g=94423392 u_a=+7.953756e-001 u_g=+2.500000e-001 W_a=35920248 goalΔ=+2.758349e-001 actualΔ=+1.192618e-001 u_a/u_g=+3.181502e+000
gc 31 @14.476s 9%: 0.27+67+0.22 ms clock, 0.27+37/15/0+0.22 ms cpu, 77->82->38 MB, 90 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 4MB of spans; swept 10652 pages at +4.046173e-004 pages/byte
pacer: assist ratio=+4.513190e+000 (scan 57 MB in 64->77 MB) workers=0+1
pacer: H_m_prev=40713928 h_t=+6.723666e-001 H_T=68088615 h_a=+8.585534e-001 H_a=75669008 h_g=+1.000000e+000 H_g=81427856 u_a=+6.922291e-001 u_g=+2.500000e-001 W_a=52522696 goalΔ=+3.276334e-001 actualΔ=+1.861867e-001 u_a/u_g=+2.768916e+000
gc 32 @14.678s 10%: 0.11+91+0.22 ms clock, 0.11+40/31/0+0.22 ms cpu, 64->72->56 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 71MB; allocated 14MB of spans; swept 9265 pages at +2.776665e-004 pages/byte
Higher latency than expected at iteration 145.  Tick was delayed 49.409209ms
pacer: assist ratio=+3.310443e+000 (scan 79 MB in 89->113 MB) workers=0+1
pacer: H_m_prev=59500376 h_t=+5.784156e-001 H_T=93916321 h_a=+6.646911e-001 H_a=99049744 h_g=+1.000000e+000 H_g=119000752 u_a=+4.398612e-001 u_g=+2.500000e-001 W_a=34467400 goalΔ=+4.215844e-001 actualΔ=+8.627546e-002 u_a/u_g=+1.759445e+000
gc 33 @15.085s 10%: 0.16+61+0.21 ms clock, 0.16+11/14/21+0.21 ms cpu, 89->94->37 MB, 113 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 0MB of spans; swept 12117 pages at +4.517649e-004 pages/byte
pacer: assist ratio=+5.285203e+000 (scan 56 MB in 63->74 MB) workers=0+1
pacer: H_m_prev=39071480 h_t=+7.133093e-001 H_T=66941531 h_a=+7.374977e-001 H_a=67886608 h_g=+1.000000e+000 H_g=78142960 u_a=+2.500837e-001 u_g=+2.500000e-001 W_a=35724544 goalΔ=+2.866907e-001 actualΔ=+2.418840e-002 u_a/u_g=+1.000335e+000
gc 34 @15.472s 10%: 0.19+60+0.20 ms clock, 0.19+0.005/20/37+0.20 ms cpu, 63->64->38 MB, 74 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 0MB of spans; swept 8315 pages at +2.506918e-004 pages/byte
pacer: assist ratio=+1.049849e+001 (scan 63 MB in 71->77 MB) workers=0+1
pacer: H_m_prev=40514512 h_t=+8.445564e-001 H_T=74731303 h_a=+9.133983e-001 H_a=77520400 h_g=+1.000000e+000 H_g=81029024 u_a=+7.421192e-001 u_g=+2.500000e-001 W_a=35975152 goalΔ=+1.554436e-001 actualΔ=+6.884192e-002 u_a/u_g=+2.968477e+000
gc 35 @16.085s 9%: 0.14+60+0.25 ms clock, 0.14+30/16/6.9+0.25 ms cpu, 71->73->38 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 0MB of spans; swept 9491 pages at +2.929048e-004 pages/byte
pacer: assist ratio=+8.948682e+000 (scan 62 MB in 70->77 MB) workers=0+1
pacer: H_m_prev=40789632 h_t=+8.201004e-001 H_T=74241224 h_a=+8.336146e-001 H_a=74792464 h_g=+1.000000e+000 H_g=81579264 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=32899400 goalΔ=+1.798996e-001 actualΔ=+1.351420e-002 u_a/u_g=+1.000000e+000
gc 36 @16.401s 9%: 0.28+53+0.18 ms clock, 0.28+0/18/33+0.18 ms cpu, 70->71->35 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 35MB; allocated 0MB of spans; swept 9158 pages at +2.803991e-004 pages/byte
pacer: assist ratio=+1.742696e+001 (scan 59 MB in 67->71 MB) workers=0+1
pacer: H_m_prev=37318088 h_t=+9.032931e-001 H_T=71027259 h_a=+9.804800e-001 H_a=73907728 h_g=+1.000000e+000 H_g=74636176 u_a=+8.205224e-001 u_g=+2.500000e-001 W_a=51722232 goalΔ=+9.670691e-002 actualΔ=+7.718694e-002 u_a/u_g=+3.282089e+000
gc 37 @16.855s 10%: 0.15+89+0.21 ms clock, 0.15+51/30/0+0.21 ms cpu, 67->70->55 MB, 71 MB goal, 1 P
pacer: sweep done at heap size 70MB; allocated 14MB of spans; swept 9050 pages at +1.912980e-004 pages/byte
Higher latency than expected at iteration 167.  Tick was delayed 44.356177ms
pacer: assist ratio=+9.227266e+000 (scan 90 MB in 102->111 MB) workers=0+1
pacer: H_m_prev=58615960 h_t=+8.249793e-001 H_T=106972915 h_a=+8.403269e-001 H_a=107872528 h_g=+1.000000e+000 H_g=117231920 u_a=+3.276925e-001 u_g=+2.500000e-001 W_a=33177352 goalΔ=+1.750207e-001 actualΔ=+1.534757e-002 u_a/u_g=+1.310770e+000
gc 38 @17.293s 9%: 0.26+57+1.3 ms clock, 0.26+4.4/11/38+1.3 ms cpu, 102->102->35 MB, 111 MB goal, 1 P
pacer: sweep done at heap size 35MB; allocated 0MB of spans; swept 13194 pages at +4.009007e-004 pages/byte
pacer: assist ratio=+1.727329e+001 (scan 60 MB in 68->71 MB) workers=0+1
pacer: H_m_prev=37631096 h_t=+9.024311e-001 H_T=71590567 h_a=+9.496391e-001 H_a=73367056 h_g=+1.000000e+000 H_g=75262192 u_a=+8.862773e-001 u_g=+2.500000e-001 W_a=32070440 goalΔ=+9.756890e-002 actualΔ=+4.720800e-002 u_a/u_g=+3.545109e+000
gc 39 @17.883s 9%: 0.18+56+0.21 ms clock, 0.18+35/15/0+0.21 ms cpu, 68->69->34 MB, 71 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 2MB of spans; swept 8984 pages at +2.944907e-004 pages/byte
pacer: assist ratio=+1.248334e+001 (scan 57 MB in 64->69 MB) workers=0+1
pacer: H_m_prev=36373656 h_t=+8.675368e-001 H_T=67929140 h_a=+9.589320e-001 H_a=71253520 h_g=+1.000000e+000 H_g=72747312 u_a=+8.108154e-001 u_g=+2.500000e-001 W_a=51949936 goalΔ=+1.324632e-001 actualΔ=+9.139524e-002 u_a/u_g=+3.243262e+000
gc 40 @18.316s 10%: 0.12+90+0.39 ms clock, 0.12+50/29/0+0.39 ms cpu, 64->67->56 MB, 69 MB goal, 1 P
Higher latency than expected at iteration 181.  Tick was delayed 64.568311ms
pacer: sweep done at heap size 66MB; allocated 10MB of spans; swept 8726 pages at +1.930589e-004 pages/byte
pacer: assist ratio=+7.363411e+000 (scan 88 MB in 100->112 MB) workers=0+1
pacer: H_m_prev=58871728 h_t=+7.855591e-001 H_T=105118947 h_a=+8.572395e-001 H_a=109338896 h_g=+1.000000e+000 H_g=117743456 u_a=+5.885885e-001 u_g=+2.500000e-001 W_a=47932872 goalΔ=+2.144409e-001 actualΔ=+7.168039e-002 u_a/u_g=+2.354354e+000
gc 41 @18.773s 10%: 0.12+78+0.19 ms clock, 0.12+26/19/21+0.19 ms cpu, 100->104->51 MB, 112 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 0MB of spans; swept 13373 pages at +3.119898e-004 pages/byte
pacer: assist ratio=+8.353096e+000 (scan 82 MB in 93->103 MB) workers=0+1
pacer: H_m_prev=54319896 h_t=+8.083990e-001 H_T=98232046 h_a=+8.558625e-001 H_a=100810256 h_g=+1.000000e+000 H_g=108639792 u_a=+6.882908e-001 u_g=+2.500000e-001 W_a=35612472 goalΔ=+1.916010e-001 actualΔ=+4.746344e-002 u_a/u_g=+2.753163e+000
gc 42 @19.985s 9%: 0.27+63+0.25 ms clock, 0.27+28/27/0+0.25 ms cpu, 93->96->38 MB, 103 MB goal, 1 P
pacer: sweep done at heap size 50MB; allocated 12MB of spans; swept 12334 pages at +3.757556e-004 pages/byte
pacer: assist ratio=+1.010233e+001 (scan 62 MB in 70->77 MB) workers=0+1
pacer: H_m_prev=40379816 h_t=+8.388622e-001 H_T=74252918 h_a=+9.230269e-001 H_a=77651472 h_g=+1.000000e+000 H_g=80759632 u_a=+8.688354e-001 u_g=+2.500000e-001 W_a=37068792 goalΔ=+1.611378e-001 actualΔ=+8.416467e-002 u_a/u_g=+3.475342e+000
gc 43 @20.374s 9%: 0.15+63+0.21 ms clock, 0.15+39/14/0+0.21 ms cpu, 70->74->40 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 4MB of spans; swept 9507 pages at +3.023473e-004 pages/byte
pacer: assist ratio=+6.915911e+000 (scan 62 MB in 71->80 MB) workers=0+1
pacer: H_m_prev=42024520 h_t=+7.731806e-001 H_T=74517064 h_a=+9.120940e-001 H_a=80354832 h_g=+1.000000e+000 H_g=84049040 u_a=+7.686713e-001 u_g=+2.500000e-001 W_a=50566904 goalΔ=+2.268194e-001 actualΔ=+1.389134e-001 u_a/u_g=+3.074685e+000
gc 44 @20.680s 10%: 0.11+86+0.25 ms clock, 0.11+44/25/0+0.25 ms cpu, 71->76->54 MB, 80 MB goal, 1 P
Higher latency than expected at iteration 205.  Tick was delayed 37.590974ms
pacer: sweep done at heap size 67MB; allocated 12MB of spans; swept 9837 pages at +2.622331e-004 pages/byte
pacer: assist ratio=+4.526149e+000 (scan 80 MB in 91->109 MB) workers=0+1
pacer: H_m_prev=57294376 h_t=+6.730329e-001 H_T=95855375 h_a=+7.914121e-001 H_a=102637840 h_g=+1.000000e+000 H_g=114588752 u_a=+6.942456e-001 u_g=+2.500000e-001 W_a=42840848 goalΔ=+3.269671e-001 actualΔ=+1.183792e-001 u_a/u_g=+2.776982e+000
gc 45 @21.364s 9%: 0.12+73+0.20 ms clock, 0.12+32/23/0+0.20 ms cpu, 91->97->46 MB, 109 MB goal, 1 P
pacer: sweep done at heap size 62MB; allocated 16MB of spans; swept 12555 pages at +3.975660e-004 pages/byte
pacer: assist ratio=+4.510371e+000 (scan 68 MB in 77->92 MB) workers=0+1
Higher latency than expected at iteration 215.  Tick was delayed 44.215742ms
pacer: H_m_prev=48543248 h_t=+6.721479e-001 H_T=81171490 h_a=+7.606446e-001 H_a=85467408 h_g=+1.000000e+000 H_g=97086496 u_a=+5.177504e-001 u_g=+2.500000e-001 W_a=39032600 goalΔ=+3.278521e-001 actualΔ=+8.849670e-002 u_a/u_g=+2.071001e+000
gc 46 @21.749s 10%: 0.12+70+0.68 ms clock, 0.12+18/29/10+0.68 ms cpu, 77->81->42 MB, 92 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 0MB of spans; swept 10459 pages at +3.279872e-004 pages/byte
pacer: assist ratio=+6.037762e+000 (scan 65 MB in 73->84 MB) workers=0+1
pacer: H_m_prev=44244280 h_t=+7.444356e-001 H_T=77181295 h_a=+7.543334e-001 H_a=77619216 h_g=+1.000000e+000 H_g=88488560 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=33752504 goalΔ=+2.555644e-001 actualΔ=+9.897795e-003 u_a/u_g=+1.000000e+000
gc 47 @22.197s 9%: 0.11+52+0.21 ms clock, 0.11+0/19/31+0.21 ms cpu, 73->74->36 MB, 84 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 0MB of spans; swept 9504 pages at +2.955753e-004 pages/byte
pacer: assist ratio=+1.244686e+001 (scan 60 MB in 68->73 MB) workers=0+1
pacer: H_m_prev=38284344 h_t=+8.672689e-001 H_T=71487164 h_a=+9.602377e-001 H_a=75046416 h_g=+1.000000e+000 H_g=76568688 u_a=+7.945221e-001 u_g=+2.500000e-001 W_a=56808296 goalΔ=+1.327311e-001 actualΔ=+9.296886e-002 u_a/u_g=+3.178088e+000
gc 48 @22.524s 10%: 0.11+93+0.21 ms clock, 0.11+50/32/0+0.21 ms cpu, 68->71->61 MB, 73 MB goal, 1 P
pacer: sweep done at heap size 70MB; allocated 9MB of spans; swept 9189 pages at +1.854841e-004 pages/byte
pacer: assist ratio=+7.382055e+000 (scan 96 MB in 109->122 MB) workers=0+1
pacer: H_m_prev=64370824 h_t=+7.859028e-001 H_T=114960035 h_a=+7.985950e-001 H_a=115777040 h_g=+1.000000e+000 H_g=128741648 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=37734064 goalΔ=+2.140972e-001 actualΔ=+1.269215e-002 u_a/u_g=+1.000000e+000
gc 49 @23.327s 9%: 0.11+60+0.26 ms clock, 0.11+0/20/38+0.26 ms cpu, 109->110->40 MB, 122 MB goal, 1 P
pacer: sweep done at heap size 48MB; allocated 7MB of spans; swept 14161 pages at +3.838776e-004 pages/byte
pacer: assist ratio=+1.472288e+001 (scan 68 MB in 76->81 MB) workers=0+1
pacer: H_m_prev=42790112 h_t=+8.866053e-001 H_T=80728053 h_a=+9.554189e-001 H_a=83672592 h_g=+1.000000e+000 H_g=85580224 u_a=+8.434800e-001 u_g=+2.500000e-001 W_a=54374616 goalΔ=+1.133947e-001 actualΔ=+6.881353e-002 u_a/u_g=+3.373920e+000
gc 50 @23.584s 10%: 0.15+88+0.19 ms clock, 0.15+52/27/0+0.19 ms cpu, 76->79->58 MB, 81 MB goal, 1 P
pacer: sweep done at heap size 67MB; allocated 8MB of spans; swept 10242 pages at +2.051533e-004 pages/byte
pacer: assist ratio=+9.361268e+000 (scan 94 MB in 107->117 MB) workers=0+1
pacer: H_m_prev=61618920 h_t=+8.272170e-001 H_T=112591137 h_a=+8.827757e-001 H_a=116014608 h_g=+1.000000e+000 H_g=123237840 u_a=+8.534157e-001 u_g=+2.500000e-001 W_a=34860720 goalΔ=+1.727830e-001 actualΔ=+5.555876e-002 u_a/u_g=+3.413663e+000
gc 51 @24.663s 9%: 0.18+62+0.20 ms clock, 0.18+37/15/0+0.20 ms cpu, 107->110->37 MB, 117 MB goal, 1 P
pacer: sweep done at heap size 40MB; allocated 3MB of spans; swept 14190 pages at +4.531609e-004 pages/byte
pacer: assist ratio=+8.881602e+000 (scan 60 MB in 68->75 MB) workers=0+1
pacer: H_m_prev=39524656 h_t=+8.187791e-001 H_T=71886616 h_a=+9.389331e-001 H_a=76635664 h_g=+1.000000e+000 H_g=79049312 u_a=+8.413301e-001 u_g=+2.500000e-001 W_a=47853736 goalΔ=+1.812209e-001 actualΔ=+1.201540e-001 u_a/u_g=+3.365320e+000
gc 52 @25.180s 9%: 0.11+93+0.84 ms clock, 0.11+55/22/0+0.84 ms cpu, 68->73->51 MB, 75 MB goal, 1 P
Higher latency than expected at iteration 250.  Tick was delayed 35.215103ms
pacer: sweep done at heap size 54MB; allocated 2MB of spans; swept 9383 pages at +2.515411e-004 pages/byte
pacer: assist ratio=+5.157607e+000 (scan 78 MB in 88->103 MB) workers=0+1
pacer: H_m_prev=54227992 h_t=+7.072111e-001 H_T=92578630 h_a=+7.269903e-001 H_a=93651216 h_g=+1.000000e+000 H_g=108455984 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=47191544 goalΔ=+2.927889e-001 actualΔ=+1.977918e-002 u_a/u_g=+1.000000e+000
gc 53 @25.578s 9%: 0.12+109+0.24 ms clock, 0.12+0/38/57+0.24 ms cpu, 88->89->51 MB, 103 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 0MB of spans; swept 11458 pages at +2.598975e-004 pages/byte
pacer: assist ratio=+1.043355e+001 (scan 83 MB in 94->102 MB) workers=0+1
pacer: H_m_prev=53495720 h_t=+8.437160e-001 H_T=98630913 h_a=+9.006868e-001 H_a=101678608 h_g=+1.000000e+000 H_g=106991440 u_a=+8.696399e-001 u_g=+2.500000e-001 W_a=34274136 goalΔ=+1.562840e-001 actualΔ=+5.697082e-002 u_a/u_g=+3.478560e+000
gc 54 @26.101s 10%: 0.21+65+0.23 ms clock, 0.21+40/15/0+0.23 ms cpu, 94->96->37 MB, 102 MB goal, 1 P
pacer: sweep done at heap size 58MB; allocated 21MB of spans; swept 12440 pages at +4.022476e-004 pages/byte
pacer: assist ratio=+9.103461e+000 (scan 59 MB in 67->74 MB) workers=0+1
pacer: H_m_prev=38862392 h_t=+8.227698e-001 H_T=70837194 h_a=+9.673375e-001 H_a=76455440 h_g=+1.000000e+000 H_g=77724784 u_a=+7.326554e-001 u_g=+2.500000e-001 W_a=54788416 goalΔ=+1.772302e-001 actualΔ=+1.445677e-001 u_a/u_g=+2.930621e+000
gc 55 @26.362s 10%: 0.12+94+0.21 ms clock, 0.12+45/33/0+0.21 ms cpu, 67->72->59 MB, 74 MB goal, 1 P
Higher latency than expected at iteration 262.  Tick was delayed 24.575075ms
pacer: sweep done at heap size 64MB; allocated 5MB of spans; swept 9361 pages at +2.209066e-004 pages/byte
pacer: assist ratio=+5.003849e+000 (scan 88 MB in 100->118 MB) workers=0+1
pacer: H_m_prev=62074256 h_t=+6.995483e-001 H_T=105498198 h_a=+8.205440e-001 H_a=113008912 h_g=+1.000000e+000 H_g=124148512 u_a=+5.942526e-001 u_g=+2.500000e-001 W_a=43113192 goalΔ=+3.004517e-001 actualΔ=+1.209956e-001 u_a/u_g=+2.377010e+000
gc 56 @27.268s 10%: 0.11+80+0.20 ms clock, 0.11+27/31/0+0.20 ms cpu, 100->107->46 MB, 118 MB goal, 1 P
Higher latency than expected at iteration 271.  Tick was delayed 24.635692ms
pacer: sweep done at heap size 52MB; allocated 6MB of spans; swept 13821 pages at +4.133509e-004 pages/byte
pacer: assist ratio=+5.131869e+000 (scan 70 MB in 79->93 MB) workers=0+1
pacer: H_m_prev=48847752 h_t=+7.059702e-001 H_T=83332811 h_a=+7.848872e-001 H_a=87187728 h_g=+1.000000e+000 H_g=97695504 u_a=+4.630972e-001 u_g=+2.500000e-001 W_a=33831432 goalΔ=+2.940298e-001 actualΔ=+7.891697e-002 u_a/u_g=+1.852389e+000
gc 57 @27.891s 9%: 0.13+56+0.18 ms clock, 0.13+12/18/16+0.18 ms cpu, 79->83->36 MB, 93 MB goal, 1 P
pacer: sweep done at heap size 36MB; allocated 0MB of spans; swept 10669 pages at +3.696011e-004 pages/byte
pacer: assist ratio=+7.156112e+000 (scan 57 MB in 65->73 MB) workers=0+1
pacer: H_m_prev=38357624 h_t=+7.798927e-001 H_T=68272453 h_a=+9.470958e-001 H_a=74685968 h_g=+1.000000e+000 H_g=76715248 u_a=+7.121359e-001 u_g=+2.500000e-001 W_a=50262040 goalΔ=+2.201073e-001 actualΔ=+1.672031e-001 u_a/u_g=+2.848544e+000
gc 58 @28.352s 10%: 0.27+88+0.19 ms clock, 0.27+40/30/0+0.19 ms cpu, 65->71->54 MB, 73 MB goal, 1 P
pacer: sweep done at heap size 62MB; allocated 8MB of spans; swept 9145 pages at +2.535395e-004 pages/byte
pacer: assist ratio=+4.196207e+000 (scan 79 MB in 89->108 MB) workers=0+1
pacer: H_m_prev=56946456 h_t=+6.518036e-001 H_T=94064363 h_a=+6.803549e-001 H_a=95690256 h_g=+1.000000e+000 H_g=113892912 u_a=+2.503915e-001 u_g=+2.500000e-001 W_a=31323528 goalΔ=+3.481964e-001 actualΔ=+2.855125e-002 u_a/u_g=+1.001566e+000
gc 59 @29.068s 9%: 0.19+52+0.21 ms clock, 0.19+0.020/15/32+0.21 ms cpu, 89->91->33 MB, 108 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 4MB of spans; swept 11709 pages at +4.213871e-004 pages/byte
pacer: assist ratio=+8.511617e+000 (scan 54 MB in 61->67 MB) workers=0+1
pacer: H_m_prev=35528888 h_t=+8.116038e-001 H_T=64364269 h_a=+9.008293e-001 H_a=67534352 h_g=+1.000000e+000 H_g=71057776 u_a=+7.386586e-001 u_g=+2.500000e-001 W_a=35744352 goalΔ=+1.883962e-001 actualΔ=+8.922548e-002 u_a/u_g=+2.954634e+000
gc 60 @29.396s 9%: 0.13+68+0.22 ms clock, 0.13+33/16/8.7+0.22 ms cpu, 61->64->38 MB, 67 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 0MB of spans; swept 8272 pages at +2.728375e-004 pages/byte
pacer: assist ratio=+6.945988e+000 (scan 60 MB in 68->77 MB) workers=0+1
pacer: H_m_prev=40526480 h_t=+7.739876e-001 H_T=71893472 h_a=+8.833209e-001 H_a=76324368 h_g=+1.000000e+000 H_g=81052960 u_a=+7.424851e-001 u_g=+2.500000e-001 W_a=40046624 goalΔ=+2.260124e-001 actualΔ=+1.093333e-001 u_a/u_g=+2.969940e+000
gc 61 @30.008s 9%: 0.12+67+0.18 ms clock, 0.12+33/22/0+0.18 ms cpu, 68->72->43 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 60MB; allocated 17MB of spans; swept 9345 pages at +2.934689e-004 pages/byte
pacer: assist ratio=+5.541905e+000 (scan 66 MB in 74->86 MB) workers=0+1
pacer: H_m_prev=45390752 h_t=+7.246370e-001 H_T=78282571 h_a=+8.616123e-001 H_a=84499984 h_g=+1.000000e+000 H_g=90781504 u_a=+7.466258e-001 u_g=+2.500000e-001 W_a=44630008 goalΔ=+2.753630e-001 actualΔ=+1.369753e-001 u_a/u_g=+2.986503e+000
gc 62 @30.259s 10%: 0.27+86+0.21 ms clock, 0.27+42/25/0+0.21 ms cpu, 74->80->48 MB, 86 MB goal, 1 P
Higher latency than expected at iteration 301.  Tick was delayed 20.031224ms
pacer: sweep done at heap size 71MB; allocated 23MB of spans; swept 10343 pages at +3.210492e-004 pages/byte
pacer: assist ratio=+4.282441e+000 (scan 70 MB in 79->96 MB) workers=0+1
pacer: H_m_prev=50571352 h_t=+6.577799e-001 H_T=83836171 h_a=+7.321532e-001 H_a=87597328 h_g=+1.000000e+000 H_g=101142704 u_a=+3.219850e-001 u_g=+2.500000e-001 W_a=63347056 goalΔ=+3.422201e-001 actualΔ=+7.437327e-002 u_a/u_g=+1.287940e+000
gc 63 @30.455s 10%: 0.15+103+0.20 ms clock, 0.15+7.4/36/49+0.20 ms cpu, 79->83->68 MB, 96 MB goal, 1 P
pacer: sweep done at heap size 68MB; allocated 0MB of spans; swept 10719 pages at +1.948719e-004 pages/byte
pacer: assist ratio=+7.194005e+000 (scan 107 MB in 121->136 MB) workers=0+1
pacer: H_m_prev=71772400 h_t=+7.809958e-001 H_T=127826342 h_a=+8.716376e-001 H_a=134331920 h_g=+1.000000e+000 H_g=143544800 u_a=+2.564441e-001 u_g=+2.500000e-001 W_a=48549248 goalΔ=+2.190042e-001 actualΔ=+9.064176e-002 u_a/u_g=+1.025776e+000
gc 64 @31.020s 10%: 0.18+89+0.19 ms clock, 0.18+0.57/30/36+0.19 ms cpu, 121->128->52 MB, 136 MB goal, 1 P
pacer: sweep done at heap size 52MB; allocated 0MB of spans; swept 16426 pages at +3.619846e-004 pages/byte
pacer: assist ratio=+1.046758e+001 (scan 85 MB in 96->104 MB) workers=0+1
pacer: H_m_prev=55006768 h_t=+8.440088e-001 H_T=101432964 h_a=+8.986629e-001 H_a=104439312 h_g=+1.000000e+000 H_g=110013536 u_a=+8.124669e-001 u_g=+2.500000e-001 W_a=33882344 goalΔ=+1.559912e-001 actualΔ=+5.465413e-002 u_a/u_g=+3.249867e+000
gc 65 @32.092s 9%: 0.19+60+0.18 ms clock, 0.19+34/18/0+0.18 ms cpu, 96->99->36 MB, 104 MB goal, 1 P
pacer: sweep done at heap size 60MB; allocated 23MB of spans; swept 12777 pages at +4.126664e-004 pages/byte
pacer: assist ratio=+9.724105e+000 (scan 59 MB in 67->73 MB) workers=0+1
pacer: H_m_prev=38419128 h_t=+8.331951e-001 H_T=70429756 h_a=+9.247883e-001 H_a=73948688 h_g=+1.000000e+000 H_g=76838256 u_a=+8.197163e-001 u_g=+2.500000e-001 W_a=37056872 goalΔ=+1.668049e-001 actualΔ=+9.159323e-002 u_a/u_g=+3.278865e+000
gc 66 @32.381s 9%: 0.14+67+0.18 ms clock, 0.14+38/18/0+0.18 ms cpu, 67->70->40 MB, 73 MB goal, 1 P
pacer: sweep done at heap size 42MB; allocated 2MB of spans; swept 9055 pages at +2.906913e-004 pages/byte
pacer: assist ratio=+6.688145e+000 (scan 62 MB in 70->80 MB) workers=0+1
pacer: H_m_prev=42010600 h_t=+7.664366e-001 H_T=74209062 h_a=+8.899127e-001 H_a=79396368 h_g=+1.000000e+000 H_g=84021200 u_a=+4.788930e-001 u_g=+2.500000e-001 W_a=36455416 goalΔ=+2.335634e-001 actualΔ=+1.234761e-001 u_a/u_g=+1.915572e+000
gc 67 @33.052s 9%: 0.13+68+0.19 ms clock, 0.13+15/16/20+0.19 ms cpu, 70->75->39 MB, 80 MB goal, 1 P
pacer: sweep done at heap size 42MB; allocated 2MB of spans; swept 9720 pages at +3.180566e-004 pages/byte
pacer: assist ratio=+6.640844e+000 (scan 61 MB in 69->78 MB) workers=0+1
pacer: H_m_prev=41321640 h_t=+7.649546e-001 H_T=72930818 h_a=+8.861350e-001 H_a=77938192 h_g=+1.000000e+000 H_g=82643280 u_a=+7.236861e-001 u_g=+2.500000e-001 W_a=45718776 goalΔ=+2.350454e-001 actualΔ=+1.211804e-001 u_a/u_g=+2.894744e+000
gc 68 @33.449s 9%: 0.11+77+0.23 ms clock, 0.11+36/27/0+0.23 ms cpu, 69->74->49 MB, 78 MB goal, 1 P
pacer: sweep done at heap size 63MB; allocated 14MB of spans; swept 9542 pages at +2.681455e-004 pages/byte
pacer: assist ratio=+5.155896e+000 (scan 74 MB in 84->98 MB) workers=0+1
Higher latency than expected at iteration 334.  Tick was delayed 32.310633ms
pacer: H_m_prev=51809576 h_t=+7.070842e-001 H_T=88443306 h_a=+7.734510e-001 H_a=91881744 h_g=+1.000000e+000 H_g=103619152 u_a=+3.527032e-001 u_g=+2.500000e-001 W_a=71855936 goalΔ=+2.929158e-001 actualΔ=+6.636684e-002 u_a/u_g=+1.410813e+000
gc 69 @33.605s 10%: 0.10+118+0.22 ms clock, 0.10+12/31/64+0.22 ms cpu, 84->87->77 MB, 98 MB goal, 1 P
pacer: sweep done at heap size 77MB; allocated 0MB of spans; swept 11242 pages at +1.739577e-004 pages/byte
pacer: assist ratio=+8.273786e+000 (scan 124 MB in 140->155 MB) workers=0+1
pacer: H_m_prev=81407360 h_t=+8.067265e-001 H_T=147080833 h_a=+8.870087e-001 H_a=153616400 h_g=+1.000000e+000 H_g=162814720 u_a=+7.312309e-001 u_g=+2.500000e-001 W_a=59549224 goalΔ=+1.932735e-001 actualΔ=+8.028226e-002 u_a/u_g=+2.924924e+000
gc 70 @34.519s 9%: 0.12+108+0.26 ms clock, 0.12+52/31/0+0.26 ms cpu, 140->146->64 MB, 155 MB goal, 1 P
pacer: sweep done at heap size 72MB; allocated 8MB of spans; swept 18781 pages at +3.613717e-004 pages/byte
pacer: assist ratio=+7.385648e+000 (scan 101 MB in 114->128 MB) workers=0+1
pacer: H_m_prev=67459464 h_t=+7.859535e-001 H_T=120479466 h_a=+8.586904e-001 H_a=125386256 h_g=+1.000000e+000 H_g=134918928 u_a=+8.131598e-001 u_g=+2.500000e-001 W_a=45286504 goalΔ=+2.140465e-001 actualΔ=+7.273686e-002 u_a/u_g=+3.252639e+000
gc 71 @35.457s 9%: 0.17+82+0.21 ms clock, 0.17+46/22/0+0.21 ms cpu, 114->119->48 MB, 128 MB goal, 1 P
pacer: sweep done at heap size 79MB; allocated 30MB of spans; swept 15334 pages at +3.961381e-004 pages/byte
pacer: assist ratio=+6.965840e+000 (scan 76 MB in 86->97 MB) workers=0+1
Higher latency than expected at iteration 356.  Tick was delayed 43.853445ms
pacer: H_m_prev=51320712 h_t=+7.746834e-001 H_T=91078014 h_a=+8.660059e-001 H_a=95764752 h_g=+1.000000e+000 H_g=102641424 u_a=+8.025825e-001 u_g=+2.500000e-001 W_a=36833080 goalΔ=+2.253166e-001 actualΔ=+9.132253e-002 u_a/u_g=+3.210330e+000
gc 72 @35.847s 9%: 0.11+62+0.25 ms clock, 0.11+34/15/0+0.25 ms cpu, 86->91->39 MB, 97 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 3MB of spans; swept 11716 pages at +3.921074e-004 pages/byte
pacer: assist ratio=+5.941801e+000 (scan 61 MB in 69->79 MB) workers=0+1
pacer: H_m_prev=41752248 h_t=+7.407540e-001 H_T=72680391 h_a=+8.973028e-001 H_a=79216656 h_g=+1.000000e+000 H_g=83504496 u_a=+2.818232e-001 u_g=+2.500000e-001 W_a=43257704 goalΔ=+2.592460e-001 actualΔ=+1.565488e-001 u_a/u_g=+1.127293e+000
gc 73 @36.261s 9%: 0.19+80+0.18 ms clock, 0.19+2.5/19/37+0.18 ms cpu, 69->75->46 MB, 79 MB goal, 1 P
pacer: sweep done at heap size 47MB; allocated 0MB of spans; swept 9699 pages at +2.601029e-004 pages/byte
pacer: assist ratio=+7.238097e+000 (scan 73 MB in 83->93 MB) workers=0+1
pacer: H_m_prev=49016440 h_t=+7.821388e-001 H_T=87354100 h_a=+7.869182e-001 H_a=87588368 h_g=+1.000000e+000 H_g=98032880 u_a=+2.501706e-001 u_g=+2.500000e-001 W_a=35224816 goalΔ=+2.178612e-001 actualΔ=+4.779366e-003 u_a/u_g=+1.000683e+000
gc 74 @36.846s 9%: 0.18+58+0.19 ms clock, 0.18+0.010/15/42+0.19 ms cpu, 83->83->38 MB, 93 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 0MB of spans; swept 10720 pages at +3.111207e-004 pages/byte
pacer: assist ratio=+1.502673e+001 (scan 63 MB in 71->76 MB) workers=0+1
pacer: H_m_prev=39952208 h_t=+8.886781e-001 H_T=75456860 h_a=+9.532461e-001 H_a=78036496 h_g=+1.000000e+000 H_g=79904416 u_a=+9.101632e-001 u_g=+2.500000e-001 W_a=42496080 goalΔ=+1.113219e-001 actualΔ=+6.456804e-002 u_a/u_g=+3.640653e+000
gc 75 @37.446s 9%: 0.18+78+0.23 ms clock, 0.18+52/18/0+0.23 ms cpu, 71->74->45 MB, 76 MB goal, 1 P
pacer: sweep done at heap size 72MB; allocated 26MB of spans; swept 9554 pages at +2.463587e-004 pages/byte
pacer: assist ratio=+9.332397e+000 (scan 74 MB in 83->91 MB) workers=0+1
pacer: H_m_prev=48172752 h_t=+8.268041e-001 H_T=88002182 h_a=+9.717733e-001 H_a=94985744 h_g=+1.000000e+000 H_g=96345504 u_a=+7.727412e-001 u_g=+2.500000e-001 W_a=69918336 goalΔ=+1.731959e-001 actualΔ=+1.449691e-001 u_a/u_g=+3.090965e+000
gc 76 @37.615s 10%: 0.11+120+0.21 ms clock, 0.11+63/38/0+0.21 ms cpu, 83->90->75 MB, 91 MB goal, 1 P
pacer: sweep done at heap size 77MB; allocated 1MB of spans; swept 11623 pages at +2.170670e-004 pages/byte
pacer: assist ratio=+4.810529e+000 (scan 112 MB in 127->151 MB) workers=0+1
pacer: H_m_prev=79196144 h_t=+6.893549e-001 H_T=133790390 h_a=+6.993993e-001 H_a=134585872 h_g=+1.000000e+000 H_g=158392288 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=43848192 goalΔ=+3.106451e-001 actualΔ=+1.004444e-002 u_a/u_g=+1.000000e+000
gc 77 @38.116s 9%: 0.12+71+0.23 ms clock, 0.12+0/15/53+0.23 ms cpu, 127->128->47 MB, 151 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 4MB of spans; swept 16457 pages at +4.044250e-004 pages/byte
pacer: assist ratio=+1.014871e+001 (scan 77 MB in 87->94 MB) workers=0+1
pacer: H_m_prev=49711968 h_t=+8.396552e-001 H_T=91452880 h_a=+9.077557e-001 H_a=94838288 h_g=+1.000000e+000 H_g=99423936 u_a=+6.482709e-001 u_g=+2.500000e-001 W_a=36389824 goalΔ=+1.603448e-001 actualΔ=+6.810044e-002 u_a/u_g=+2.593083e+000
gc 78 @38.762s 9%: 0.13+74+0.57 ms clock, 0.13+29/30/0+0.57 ms cpu, 87->90->39 MB, 94 MB goal, 1 P
pacer: sweep done at heap size 71MB; allocated 31MB of spans; swept 11605 pages at +3.489476e-004 pages/byte
pacer: assist ratio=+9.614726e+000 (scan 63 MB in 72->78 MB) workers=0+1
pacer: H_m_prev=41256016 h_t=+8.315325e-001 H_T=75561735 h_a=+9.826593e-001 H_a=81796624 h_g=+1.000000e+000 H_g=82512032 u_a=+8.387526e-001 u_g=+2.500000e-001 W_a=65128192 goalΔ=+1.684675e-001 actualΔ=+1.511268e-001 u_a/u_g=+3.355010e+000
gc 79 @38.948s 10%: 0.099+133+0.59 ms clock, 0.099+78/33/0+0.59 ms cpu, 72->78->70 MB, 78 MB goal, 1 P
pacer: sweep done at heap size 76MB; allocated 6MB of spans; swept 10013 pages at +2.094311e-004 pages/byte
pacer: assist ratio=+4.354140e+000 (scan 103 MB in 116->140 MB) workers=0+1
Higher latency than expected at iteration 395.  Tick was delayed 26.735579ms
pacer: H_m_prev=73777328 h_t=+6.622503e-001 H_T=122636387 h_a=+7.576055e-001 H_a=129671440 h_g=+1.000000e+000 H_g=147554656 u_a=+4.951149e-001 u_g=+2.500000e-001 W_a=51445176 goalΔ=+3.377497e-001 actualΔ=+9.535521e-002 u_a/u_g=+1.980459e+000
gc 80 @39.688s 10%: 0.11+118+0.26 ms clock, 0.11+29/30/28+0.26 ms cpu, 116->123->55 MB, 140 MB goal, 1 P
pacer: sweep done at heap size 55MB; allocated 0MB of spans; swept 15855 pages at +3.785020e-004 pages/byte
pacer: assist ratio=+5.837807e+000 (scan 85 MB in 96->111 MB) workers=0+1
pacer: H_m_prev=58283288 h_t=+7.367016e-001 H_T=101220679 h_a=+7.406318e-001 H_a=101449744 h_g=+1.000000e+000 H_g=116566576 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=34801104 goalΔ=+2.632984e-001 actualΔ=+3.930191e-003 u_a/u_g=+1.000000e+000
gc 81 @40.666s 9%: 0.11+56+0.20 ms clock, 0.11+0/16/39+0.20 ms cpu, 96->96->37 MB, 111 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 0MB of spans; swept 12413 pages at +3.744516e-004 pages/byte
pacer: assist ratio=+1.236822e+001 (scan 62 MB in 70->75 MB) workers=0+1
Higher latency than expected at iteration 409.  Tick was delayed 75.602625ms
pacer: H_m_prev=39472480 h_t=+8.663857e-001 H_T=73670872 h_a=+9.591562e-001 H_a=77332752 h_g=+1.000000e+000 H_g=78944960 u_a=+8.027133e-001 u_g=+2.500000e-001 W_a=48010240 goalΔ=+1.336143e-001 actualΔ=+9.277045e-002 u_a/u_g=+3.210853e+000
gc 82 @41.095s 10%: 4.0+187+0.29 ms clock, 4.0+105/54/0+0.29 ms cpu, 70->73->51 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 73MB; allocated 21MB of spans; swept 9466 pages at +2.274189e-004 pages/byte
pacer: assist ratio=+7.314585e+000 (scan 81 MB in 92->103 MB) workers=0+1
pacer: H_m_prev=54411008 h_t=+7.842567e-001 H_T=97083206 h_a=+8.792624e-001 H_a=102252560 h_g=+1.000000e+000 H_g=108822016 u_a=+8.503380e-001 u_g=+2.500000e-001 W_a=42198832 goalΔ=+2.157433e-001 actualΔ=+9.500566e-002 u_a/u_g=+3.401352e+000
gc 83 @41.761s 10%: 0.14+71+0.24 ms clock, 0.14+43/14/0+0.24 ms cpu, 92->97->45 MB, 103 MB goal, 1 P
pacer: sweep done at heap size 59MB; allocated 14MB of spans; swept 12511 pages at +3.691716e-004 pages/byte
pacer: assist ratio=+5.680144e+000 (scan 69 MB in 78->91 MB) workers=0+1
pacer: H_m_prev=47823904 h_t=+7.305545e-001 H_T=82761873 h_a=+8.436387e-001 H_a=88170000 h_g=+1.000000e+000 H_g=95647808 u_a=+7.923870e-001 u_g=+2.500000e-001 W_a=35277336 goalΔ=+2.694455e-001 actualΔ=+1.130842e-001 u_a/u_g=+3.169548e+000
gc 84 @42.370s 10%: 0.15+69+0.26 ms clock, 0.15+37/15/0+0.26 ms cpu, 78->84->38 MB, 91 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 6MB of spans; swept 10791 pages at +4.089816e-004 pages/byte
pacer: assist ratio=+4.751081e+000 (scan 56 MB in 64->76 MB) workers=0+1
pacer: H_m_prev=39986952 h_t=+6.860644e-001 H_T=67420576 h_a=+7.622520e-001 H_a=70467088 h_g=+1.000000e+000 H_g=79973904 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=36588664 goalΔ=+3.139356e-001 actualΔ=+7.618764e-002 u_a/u_g=+1.000000e+000
gc 85 @43.071s 10%: 0.13+64+0.54 ms clock, 0.13+0/15/41+0.54 ms cpu, 64->67->39 MB, 76 MB goal, 1 P
pacer: sweep done at heap size 40MB; allocated 0MB of spans; swept 8630 pages at +2.668304e-004 pages/byte
pacer: assist ratio=+8.181689e+000 (scan 63 MB in 71->79 MB) workers=0+1
pacer: H_m_prev=41482952 h_t=+8.049384e-001 H_T=74874172 h_a=+8.507585e-001 H_a=76774928 h_g=+1.000000e+000 H_g=82965904 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=29582448 goalΔ=+1.950616e-001 actualΔ=+4.582017e-002 u_a/u_g=+1.000000e+000
gc 86 @43.571s 10%: 0.11+48+0.21 ms clock, 0.11+0/14/28+0.21 ms cpu, 71->73->32 MB, 79 MB goal, 1 P
pacer: sweep done at heap size 34MB; allocated 2MB of spans; swept 9400 pages at +3.302153e-004 pages/byte
pacer: assist ratio=+1.381695e+001 (scan 53 MB in 60->64 MB) workers=0+1
pacer: H_m_prev=33556416 h_t=+8.795591e-001 H_T=63071267 h_a=+9.603185e-001 H_a=65781264 h_g=+1.000000e+000 H_g=67112832 u_a=+6.245202e-001 u_g=+2.500000e-001 W_a=38816792 goalΔ=+1.204409e-001 actualΔ=+8.075942e-002 u_a/u_g=+2.498081e+000
gc 87 @44.188s 9%: 0.15+73+0.25 ms clock, 0.15+27/18/17+0.25 ms cpu, 60->62->41 MB, 64 MB goal, 1 P
pacer: sweep done at heap size 52MB; allocated 10MB of spans; swept 8058 pages at +2.246483e-004 pages/byte
pacer: assist ratio=+1.009941e+001 (scan 68 MB in 77->83 MB) workers=0+1
pacer: H_m_prev=44007192 h_t=+8.389078e-001 H_T=80925167 h_a=+9.126943e-001 H_a=84172304 h_g=+1.000000e+000 H_g=88014384 u_a=+8.209724e-001 u_g=+2.500000e-001 W_a=35653448 goalΔ=+1.610922e-001 actualΔ=+7.378649e-002 u_a/u_g=+3.283890e+000
gc 88 @44.398s 10%: 0.15+68+0.52 ms clock, 0.15+39/18/0+0.52 ms cpu, 77->80->38 MB, 83 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 0MB of spans; swept 10303 pages at +3.299979e-004 pages/byte
pacer: assist ratio=+7.885188e+000 (scan 61 MB in 69->77 MB) workers=0+1
pacer: H_m_prev=40423352 h_t=+7.983005e-001 H_T=72693335 h_a=+8.976504e-001 H_a=76709392 h_g=+1.000000e+000 H_g=80846704 u_a=+7.384266e-001 u_g=+2.500000e-001 W_a=41928528 goalΔ=+2.016995e-001 actualΔ=+9.934991e-002 u_a/u_g=+2.953707e+000
gc 89 @45.459s 9%: 0.15+75+0.22 ms clock, 0.15+37/25/0+0.22 ms cpu, 69->73->45 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 47MB; allocated 2MB of spans; swept 9392 pages at +2.705902e-004 pages/byte
pacer: assist ratio=+6.262695e+000 (scan 70 MB in 79->90 MB) workers=0+1
pacer: H_m_prev=47523520 h_t=+7.524250e-001 H_T=83281406 h_a=+8.683926e-001 H_a=88792592 h_g=+1.000000e+000 H_g=95047040 u_a=+7.755314e-001 u_g=+2.500000e-001 W_a=41901672 goalΔ=+2.475750e-001 actualΔ=+1.159675e-001 u_a/u_g=+3.102126e+000
gc 90 @45.987s 9%: 0.14+82+0.19 ms clock, 0.14+43/22/0+0.19 ms cpu, 79->84->45 MB, 90 MB goal, 1 P
Higher latency than expected at iteration 458.  Tick was delayed 30.668047ms
pacer: sweep done at heap size 61MB; allocated 15MB of spans; swept 10867 pages at +3.394047e-004 pages/byte
pacer: assist ratio=+4.941078e+000 (scan 67 MB in 76->90 MB) workers=0+1
pacer: H_m_prev=47486024 h_t=+6.963396e-001 H_T=80552421 h_a=+7.413612e-001 H_a=82690320 h_g=+1.000000e+000 H_g=94972048 u_a=+4.085764e-001 u_g=+2.500000e-001 W_a=34965536 goalΔ=+3.036604e-001 actualΔ=+4.502164e-002 u_a/u_g=+1.634305e+000
gc 91 @46.557s 9%: 0.31+63+0.20 ms clock, 0.31+10/28/19+0.20 ms cpu, 76->78->37 MB, 90 MB goal, 1 P
pacer: sweep done at heap size 39MB; allocated 1MB of spans; swept 10120 pages at +3.251695e-004 pages/byte
pacer: assist ratio=+8.498099e+000 (scan 60 MB in 68->75 MB) workers=0+1
pacer: H_m_prev=39649488 h_t=+8.113802e-001 H_T=71820298 h_a=+9.144403e-001 H_a=75906576 h_g=+1.000000e+000 H_g=79298976 u_a=+8.014242e-001 u_g=+2.500000e-001 W_a=38249480 goalΔ=+1.886198e-001 actualΔ=+1.030600e-001 u_a/u_g=+3.205697e+000
gc 92 @46.972s 10%: 0.12+95+0.25 ms clock, 0.12+52/22/0+0.25 ms cpu, 68->72->41 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 53MB; allocated 11MB of spans; swept 9294 pages at +2.992453e-004 pages/byte
pacer: assist ratio=+5.934836e+000 (scan 63 MB in 71->82 MB) workers=0+1
pacer: H_m_prev=43358120 h_t=+7.405005e-001 H_T=75464829 h_a=+9.082632e-001 H_a=82738704 h_g=+1.000000e+000 H_g=86716240 u_a=+6.805778e-001 u_g=+2.500000e-001 W_a=48384408 goalΔ=+2.594995e-001 actualΔ=+1.677627e-001 u_a/u_g=+2.722311e+000
gc 93 @47.368s 10%: 0.10+101+0.19 ms clock, 0.10+43/34/0+0.19 ms cpu, 71->78->52 MB, 82 MB goal, 1 P
Higher latency than expected at iteration 472.  Tick was delayed 40.27582ms
pacer: sweep done at heap size 56MB; allocated 4MB of spans; swept 10128 pages at +2.966770e-004 pages/byte
pacer: assist ratio=+4.053890e+000 (scan 75 MB in 85->104 MB) workers=0+1
pacer: H_m_prev=54816584 h_t=+6.418991e-001 H_T=90003302 h_a=+7.029174e-001 H_a=93348112 h_g=+1.000000e+000 H_g=109633168 u_a=+3.801071e-001 u_g=+2.500000e-001 W_a=36968376 goalΔ=+3.581009e-001 actualΔ=+6.101821e-002 u_a/u_g=+1.520428e+000
gc 94 @48.567s 9%: 0.21+64+0.24 ms clock, 0.21+8.4/15/32+0.24 ms cpu, 85->89->39 MB, 104 MB goal, 1 P
pacer: sweep done at heap size 40MB; allocated 0MB of spans; swept 11421 pages at +3.635616e-004 pages/byte
pacer: assist ratio=+6.960522e+000 (scan 62 MB in 70->79 MB) workers=0+1
pacer: H_m_prev=41911112 h_t=+7.745627e-001 H_T=74373894 h_a=+9.160952e-001 H_a=80305680 h_g=+1.000000e+000 H_g=83822224 u_a=+7.425988e-001 u_g=+2.500000e-001 W_a=46174008 goalΔ=+2.254373e-001 actualΔ=+1.415325e-001 u_a/u_g=+2.970395e+000
gc 95 @49.074s 9%: 0.14+114+0.21 ms clock, 0.14+56/30/0+0.21 ms cpu, 70->76->49 MB, 79 MB goal, 1 P
Higher latency than expected at iteration 489.  Tick was delayed 36.013556ms
pacer: sweep done at heap size 52MB; allocated 2MB of spans; swept 9831 pages at +2.859796e-004 pages/byte
pacer: assist ratio=+4.593841e+000 (scan 73 MB in 83->99 MB) workers=0+1
pacer: H_m_prev=52320664 h_t=+6.770776e-001 H_T=87745813 h_a=+7.334242e-001 H_a=90693904 h_g=+1.000000e+000 H_g=104641328 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=40860216 goalΔ=+3.229224e-001 actualΔ=+5.634658e-002 u_a/u_g=+1.000000e+000
gc 96 @49.497s 9%: 0.12+73+0.24 ms clock, 0.12+0/15/48+0.24 ms cpu, 83->86->44 MB, 99 MB goal, 1 P
pacer: sweep done at heap size 45MB; allocated 0MB of spans; swept 11097 pages at +3.041369e-004 pages/byte
pacer: assist ratio=+8.448665e+000 (scan 70 MB in 79->88 MB) workers=0+1
pacer: H_m_prev=46319144 h_t=+8.103655e-001 H_T=83854580 h_a=+8.142183e-001 H_a=84033040 h_g=+1.000000e+000 H_g=92638288 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=40942136 goalΔ=+1.896345e-001 actualΔ=+3.852824e-003 u_a/u_g=+1.000000e+000
gc 97 @50.058s 9%: 0.13+68+0.21 ms clock, 0.13+0/15/53+0.21 ms cpu, 79->80->44 MB, 88 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 0MB of spans; swept 10286 pages at +2.515841e-004 pages/byte
pacer: assist ratio=+1.739601e+001 (scan 74 MB in 84->88 MB) workers=0+1
pacer: H_m_prev=46424824 h_t=+9.032563e-001 H_T=88358340 h_a=+9.496662e-001 H_a=90512912 h_g=+1.000000e+000 H_g=92849648 u_a=+8.027645e-001 u_g=+2.500000e-001 W_a=45426464 goalΔ=+9.674366e-002 actualΔ=+4.640990e-002 u_a/u_g=+3.211058e+000
gc 98 @50.515s 9%: 0.15+142+0.22 ms clock, 0.15+78/45/0+0.22 ms cpu, 84->86->49 MB, 88 MB goal, 1 P
Higher latency than expected at iteration 504.  Tick was delayed 29.930573ms
pacer: sweep done at heap size 76MB; allocated 27MB of spans; swept 11077 pages at +2.510879e-004 pages/byte
pacer: assist ratio=+1.350974e+001 (scan 81 MB in 92->98 MB) workers=0+1
Higher latency than expected at iteration 510.  Tick was delayed 49.01151ms
pacer: H_m_prev=51492176 h_t=+8.771157e-001 H_T=96656773 h_a=+9.170655e-001 H_a=98713872 h_g=+1.000000e+000 H_g=102984352 u_a=+2.500914e-001 u_g=+2.500000e-001 W_a=35038584 goalΔ=+1.228843e-001 actualΔ=+3.994973e-002 u_a/u_g=+1.000366e+000
gc 99 @51.218s 9%: 0.58+120+0.74 ms clock, 0.58+0.011/31/74+0.74 ms cpu, 92->94->37 MB, 98 MB goal, 1 P
pacer: sweep done at heap size 47MB; allocated 9MB of spans; swept 12076 pages at +3.406567e-004 pages/byte
pacer: assist ratio=+2.086215e+001 (scan 64 MB in 72->75 MB) workers=0+1
pacer: H_m_prev=39732984 h_t=+9.185757e-001 H_T=76230737 h_a=+9.632112e-001 H_a=78004240 h_g=+1.000000e+000 H_g=79465968 u_a=+8.303631e-001 u_g=+2.500000e-001 W_a=38305288 goalΔ=+8.142430e-002 actualΔ=+4.463552e-002 u_a/u_g=+3.321452e+000
gc 100 @51.843s 9%: 0.24+106+0.46 ms clock, 0.24+61/33/0+0.46 ms cpu, 72->74->41 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 54MB; allocated 13MB of spans; swept 9551 pages at +2.554015e-004 pages/byte
pacer: assist ratio=+1.452152e+001 (scan 69 MB in 78->82 MB) workers=0+1
Higher latency than expected at iteration 521.  Tick was delayed 29.698386ms
pacer: H_m_prev=43432344 h_t=+8.851605e-001 H_T=81876938 h_a=+9.350095e-001 H_a=84042000 h_g=+1.000000e+000 H_g=86864688 u_a=+8.683899e-001 u_g=+2.500000e-001 W_a=32750384 goalΔ=+1.148395e-001 actualΔ=+4.984907e-002 u_a/u_g=+3.473559e+000
gc 101 @52.334s 10%: 0.12+56+0.54 ms clock, 0.12+35/15/0+0.54 ms cpu, 78->80->35 MB, 82 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 2MB of spans; swept 10285 pages at +3.345232e-004 pages/byte
pacer: assist ratio=+1.141350e+001 (scan 58 MB in 65->70 MB) workers=0+1
pacer: H_m_prev=37142176 h_t=+8.560034e-001 H_T=68936004 h_a=+9.126785e-001 H_a=71041040 h_g=+1.000000e+000 H_g=74284352 u_a=+6.996644e-001 u_g=+2.500000e-001 W_a=36728912 goalΔ=+1.439966e-001 actualΔ=+5.667508e-002 u_a/u_g=+2.798657e+000
gc 102 @52.874s 10%: 0.16+65+0.32 ms clock, 0.16+29/29/0+0.32 ms cpu, 65->67->39 MB, 70 MB goal, 1 P
pacer: sweep done at heap size 56MB; allocated 16MB of spans; swept 8701 pages at +2.537011e-004 pages/byte
pacer: assist ratio=+1.081288e+001 (scan 64 MB in 73->79 MB) workers=0+1
pacer: H_m_prev=41646128 h_t=+8.486946e-001 H_T=76990973 h_a=+9.365484e-001 H_a=80649744 h_g=+1.000000e+000 H_g=83292256 u_a=+8.142510e-001 u_g=+2.500000e-001 W_a=51189936 goalΔ=+1.513054e-001 actualΔ=+8.785380e-002 u_a/u_g=+3.257004e+000
gc 103 @53.122s 10%: 0.14+88+0.20 ms clock, 0.14+50/28/0+0.20 ms cpu, 73->76->55 MB, 79 MB goal, 1 P
pacer: sweep done at heap size 60MB; allocated 5MB of spans; swept 9873 pages at +2.230017e-004 pages/byte
pacer: assist ratio=+7.204308e+000 (scan 87 MB in 98->110 MB) workers=0+1
pacer: H_m_prev=58009856 h_t=+7.812772e-001 H_T=103331635 h_a=+8.612365e-001 H_a=107970064 h_g=+1.000000e+000 H_g=116019712 u_a=+8.325190e-001 u_g=+2.500000e-001 W_a=37281120 goalΔ=+2.187228e-001 actualΔ=+7.995933e-002 u_a/u_g=+3.330076e+000
gc 104 @54.257s 10%: 0.13+64+1.0 ms clock, 0.13+37/14/0+1.0 ms cpu, 98->102->40 MB, 110 MB goal, 1 P
pacer: sweep done at heap size 68MB; allocated 28MB of spans; swept 13208 pages at +4.265759e-004 pages/byte
pacer: assist ratio=+6.412030e+000 (scan 62 MB in 70->80 MB) workers=0+1
pacer: H_m_prev=42259104 h_t=+7.575033e-001 H_T=74270514 h_a=+8.912056e-001 H_a=79920656 h_g=+1.000000e+000 H_g=84518208 u_a=+7.900557e-001 u_g=+2.500000e-001 W_a=46747392 goalΔ=+2.424967e-001 actualΔ=+1.337023e-001 u_a/u_g=+3.160223e+000
gc 105 @54.576s 10%: 0.16+83+0.19 ms clock, 0.16+45/23/0+0.19 ms cpu, 70->76->50 MB, 80 MB goal, 1 P
pacer: sweep done at heap size 58MB; allocated 8MB of spans; swept 9784 pages at +2.851731e-004 pages/byte
pacer: assist ratio=+4.436003e+000 (scan 74 MB in 84->101 MB) workers=0+1
Higher latency than expected at iteration 551.  Tick was delayed 21.907844ms
pacer: H_m_prev=52971168 h_t=+6.674871e-001 H_T=88328736 h_a=+8.302899e-001 H_a=96952592 h_g=+1.000000e+000 H_g=105942336 u_a=+2.697882e-001 u_g=+2.500000e-001 W_a=42143480 goalΔ=+3.325129e-001 actualΔ=+1.628028e-001 u_a/u_g=+1.079153e+000
gc 106 @55.338s 9%: 0.23+79+0.24 ms clock, 0.23+1.5/18/36+0.24 ms cpu, 84->92->45 MB, 101 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 5MB of spans; swept 11861 pages at +3.431546e-004 pages/byte
pacer: assist ratio=+6.079338e+000 (scan 70 MB in 79->91 MB) workers=0+1
pacer: H_m_prev=47745304 h_t=+7.458990e-001 H_T=83358477 h_a=+8.497729e-001 H_a=88317968 h_g=+1.000000e+000 H_g=95490608 u_a=+5.185239e-001 u_g=+2.500000e-001 W_a=33834336 goalΔ=+2.541010e-001 actualΔ=+1.038739e-001 u_a/u_g=+2.074096e+000
gc 107 @56.010s 9%: 0.21+63+0.20 ms clock, 0.21+17/15/16+0.20 ms cpu, 79->84->36 MB, 91 MB goal, 1 P
pacer: sweep done at heap size 36MB; allocated 0MB of spans; swept 10810 pages at +3.819514e-004 pages/byte
pacer: assist ratio=+6.648801e+000 (scan 57 MB in 64->73 MB) workers=0+1
pacer: H_m_prev=38355408 h_t=+7.652273e-001 H_T=67706013 h_a=+8.814252e-001 H_a=72162832 h_g=+1.000000e+000 H_g=76710816 u_a=+8.031665e-001 u_g=+2.500000e-001 W_a=33338120 goalΔ=+2.347727e-001 actualΔ=+1.161979e-001 u_a/u_g=+3.212666e+000
gc 108 @56.608s 9%: 0.18+64+0.20 ms clock, 0.18+35/15/0+0.20 ms cpu, 64->68->36 MB, 73 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 7MB of spans; swept 8837 pages at +3.498958e-004 pages/byte
pacer: assist ratio=+4.930932e+000 (scan 54 MB in 61->72 MB) workers=0+1
pacer: H_m_prev=37796168 h_t=+6.959611e-001 H_T=64100831 h_a=+7.200478e-001 H_a=65011216 h_g=+1.000000e+000 H_g=75592336 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=28007048 goalΔ=+3.040389e-001 actualΔ=+2.408670e-002 u_a/u_g=+1.000000e+000
gc 109 @56.872s 9%: 0.19+60+0.83 ms clock, 0.19+0/15/41+0.83 ms cpu, 61->61->30 MB, 72 MB goal, 1 P
pacer: sweep done at heap size 30MB; allocated 0MB of spans; swept 7964 pages at +3.121229e-004 pages/byte
pacer: assist ratio=+9.892740e+000 (scan 49 MB in 55->60 MB) workers=0+1
pacer: H_m_prev=31777704 h_t=+8.359372e-001 H_T=58341869 h_a=+9.264551e-001 H_a=61218320 h_g=+1.000000e+000 H_g=63555408 u_a=+8.470267e-001 u_g=+2.500000e-001 W_a=30729400 goalΔ=+1.640628e-001 actualΔ=+9.051790e-002 u_a/u_g=+3.388107e+000
gc 110 @57.373s 9%: 0.13+61+0.62 ms clock, 0.13+36/15/0+0.62 ms cpu, 55->58->33 MB, 60 MB goal, 1 P
pacer: sweep done at heap size 37MB; allocated 4MB of spans; swept 7501 pages at +2.930210e-004 pages/byte
pacer: assist ratio=+6.633653e+000 (scan 51 MB in 58->66 MB) workers=0+1
pacer: H_m_prev=34850248 h_t=+7.646265e-001 H_T=61497669 h_a=+9.963749e-001 H_a=69574160 h_g=+1.000000e+000 H_g=69700496 u_a=+4.845339e-001 u_g=+2.500000e-001 W_a=59986416 goalΔ=+2.353735e-001 actualΔ=+2.317484e-001 u_a/u_g=+1.938136e+000
gc 111 @57.518s 9%: 0.16+127+0.20 ms clock, 0.16+29/36/34+0.20 ms cpu, 58->66->64 MB, 66 MB goal, 1 P
pacer: sweep done at heap size 65MB; allocated 0MB of spans; swept 8521 pages at +1.952444e-004 pages/byte
pacer: assist ratio=+4.284097e+000 (scan 95 MB in 107->129 MB) workers=0+1
pacer: H_m_prev=67947488 h_t=+6.577333e-001 H_T=112638811 h_a=+8.261709e-001 H_a=124083728 h_g=+1.000000e+000 H_g=135894976 u_a=+6.501938e-001 u_g=+2.500000e-001 W_a=58246984 goalΔ=+3.422667e-001 actualΔ=+1.684377e-001 u_a/u_g=+2.600775e+000
gc 112 @58.189s 9%: 0.13+116+0.22 ms clock, 0.13+46/35/0+0.22 ms cpu, 107->118->62 MB, 129 MB goal, 1 P
pacer: sweep done at heap size 77MB; allocated 14MB of spans; swept 15175 pages at +3.873429e-004 pages/byte
pacer: assist ratio=+3.650422e+000 (scan 89 MB in 101->125 MB) workers=0+1
pacer: H_m_prev=65961976 h_t=+6.098324e-001 H_T=106187724 h_a=+7.534701e-001 H_a=115662352 h_g=+1.000000e+000 H_g=131923952 u_a=+6.532169e-001 u_g=+2.500000e-001 W_a=48955592 goalΔ=+3.901676e-001 actualΔ=+1.436377e-001 u_a/u_g=+2.612868e+000
gc 113 @58.600s 10%: 0.10+88+0.21 ms clock, 0.10+35/27/0+0.21 ms cpu, 101->110->52 MB, 125 MB goal, 1 P
pacer: sweep done at heap size 63MB; allocated 10MB of spans; swept 14147 pages at +4.263683e-004 pages/byte
pacer: assist ratio=+3.737873e+000 (scan 75 MB in 85->105 MB) workers=0+1
Higher latency than expected at iteration 589.  Tick was delayed 29.602069ms
pacer: H_m_prev=55452552 h_t=+6.172630e-001 H_T=89681362 h_a=+7.783774e-001 H_a=98615568 h_g=+1.000000e+000 H_g=110905104 u_a=+4.806862e-001 u_g=+2.500000e-001 W_a=40643800 goalΔ=+3.827370e-001 actualΔ=+1.611144e-001 u_a/u_g=+1.922745e+000
gc 114 @59.129s 10%: 0.10+78+0.22 ms clock, 0.10+18/20/15+0.22 ms cpu, 85->94->43 MB, 105 MB goal, 1 P
pacer: sweep done at heap size 54MB; allocated 10MB of spans; swept 12064 pages at +4.152324e-004 pages/byte
pacer: assist ratio=+4.224480e+000 (scan 64 MB in 72->87 MB) workers=0+1
pacer: H_m_prev=46046072 h_t=+6.537406e-001 H_T=76148257 h_a=+6.872871e-001 H_a=77692944 h_g=+1.000000e+000 H_g=92092144 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=42637888 goalΔ=+3.462594e-001 actualΔ=+3.354655e-002 u_a/u_g=+1.000000e+000
gc 115 @59.462s 9%: 0.18+75+0.21 ms clock, 0.18+0/15/56+0.21 ms cpu, 72->74->46 MB, 87 MB goal, 1 P
pacer: sweep done at heap size 56MB; allocated 10MB of spans; swept 9513 pages at +2.496201e-004 pages/byte
pacer: assist ratio=+8.430234e+000 (scan 73 MB in 83->92 MB) workers=0+1
pacer: H_m_prev=48338016 h_t=+8.100970e-001 H_T=87496498 h_a=+9.102921e-001 H_a=92339728 h_g=+1.000000e+000 H_g=96676032 u_a=+7.860461e-001 u_g=+2.500000e-001 W_a=50635512 goalΔ=+1.899030e-001 actualΔ=+1.001950e-001 u_a/u_g=+3.144185e+000
gc 116 @59.809s 10%: 0.15+88+0.22 ms clock, 0.15+47/27/0+0.22 ms cpu, 83->88->54 MB, 92 MB goal, 1 P
pacer: sweep done at heap size 62MB; allocated 8MB of spans; swept 11300 pages at +2.700636e-004 pages/byte
pacer: assist ratio=+6.123077e+000 (scan 84 MB in 95->109 MB) workers=0+1
pacer: H_m_prev=57376184 h_t=+7.475326e-001 H_T=100266754 h_a=+7.550064e-001 H_a=100695568 h_g=+1.000000e+000 H_g=114752368 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=33672704 goalΔ=+2.524674e-001 actualΔ=+7.473715e-003 u_a/u_g=+1.000000e+000
gc 117 @60.833s 9%: 0.21+53+0.21 ms clock, 0.21+0/15/37+0.21 ms cpu, 95->96->36 MB, 109 MB goal, 1 P
pacer: sweep done at heap size 36MB; allocated 0MB of spans; swept 12320 pages at +3.828297e-004 pages/byte
pacer: assist ratio=+1.272448e+001 (scan 60 MB in 68->72 MB) workers=0+1
Higher latency than expected at iteration 608.  Tick was delayed 28.233789ms
pacer: H_m_prev=38194096 h_t=+8.700295e-001 H_T=71424084 h_a=+9.786166e-001 H_a=75571472 h_g=+1.000000e+000 H_g=76388192 u_a=+7.512667e-001 u_g=+2.500000e-001 W_a=54368616 goalΔ=+1.299705e-001 actualΔ=+1.085871e-001 u_a/u_g=+3.005067e+000
gc 118 @61.036s 10%: 0.13+95+0.26 ms clock, 0.13+47/34/0+0.26 ms cpu, 68->72->58 MB, 72 MB goal, 1 P
pacer: sweep done at heap size 71MB; allocated 12MB of spans; swept 9251 pages at +1.989341e-004 pages/byte
pacer: assist ratio=+6.869712e+000 (scan 92 MB in 104->117 MB) workers=0+1
pacer: H_m_prev=61606360 h_t=+7.718590e-001 H_T=109157780 h_a=+7.984639e-001 H_a=110796816 h_g=+1.000000e+000 H_g=123212720 u_a=+3.165326e-001 u_g=+2.500000e-001 W_a=44128440 goalΔ=+2.281410e-001 actualΔ=+2.660497e-002 u_a/u_g=+1.266131e+000
gc 119 @61.426s 9%: 0.21+71+0.21 ms clock, 0.21+4.7/15/47+0.21 ms cpu, 104->105->47 MB, 117 MB goal, 1 P
pacer: sweep done at heap size 50MB; allocated 2MB of spans; swept 13554 pages at +3.194617e-004 pages/byte
pacer: assist ratio=+1.263050e+001 (scan 78 MB in 89->95 MB) workers=0+1
pacer: H_m_prev=50025144 h_t=+8.690868e-001 H_T=93501336 h_a=+9.356055e-001 H_a=96828944 h_g=+1.000000e+000 H_g=100050288 u_a=+5.810507e-001 u_g=+2.500000e-001 W_a=60222648 goalΔ=+1.309132e-001 actualΔ=+6.651870e-002 u_a/u_g=+2.324203e+000
gc 120 @62.110s 9%: 0.27+101+0.23 ms clock, 0.27+33/35/23+0.23 ms cpu, 89->92->65 MB, 95 MB goal, 1 P
pacer: sweep done at heap size 65MB; allocated 0MB of spans; swept 11848 pages at +2.062417e-004 pages/byte
pacer: assist ratio=+1.151602e+001 (scan 106 MB in 120->130 MB) workers=0+1
pacer: H_m_prev=68237144 h_t=+8.572419e-001 H_T=126732884 h_a=+8.636787e-001 H_a=127172112 h_g=+1.000000e+000 H_g=136474288 u_a=+2.500890e-001 u_g=+2.500000e-001 W_a=38934584 goalΔ=+1.427581e-001 actualΔ=+6.436785e-003 u_a/u_g=+1.000356e+000
gc 121 @62.899s 9%: 0.19+60+0.18 ms clock, 0.19+0.005/20/39+0.18 ms cpu, 120->121->42 MB, 130 MB goal, 1 P
Higher latency than expected at iteration 627.  Tick was delayed 21.006341ms
pacer: sweep done at heap size 42MB; allocated 0MB of spans; swept 15552 pages at +3.906683e-004 pages/byte
pacer: assist ratio=+2.282116e+001 (scan 71 MB in 81->84 MB) workers=0+1
Higher latency than expected at iteration 633.  Tick was delayed 29.203433ms
pacer: H_m_prev=44150872 h_t=+9.254014e-001 H_T=85008151 h_a=+9.667895e-001 H_a=86835472 h_g=+1.000000e+000 H_g=88301744 u_a=+8.601805e-001 u_g=+2.500000e-001 W_a=53279088 goalΔ=+7.459858e-002 actualΔ=+4.138809e-002 u_a/u_g=+3.440722e+000
gc 122 @63.534s 9%: 0.13+89+0.24 ms clock, 0.13+54/28/0+0.24 ms cpu, 81->82->57 MB, 84 MB goal, 1 P
pacer: sweep done at heap size 60MB; allocated 2MB of spans; swept 10626 pages at +2.013122e-004 pages/byte
pacer: assist ratio=+1.543263e+001 (scan 96 MB in 108->115 MB) workers=0+1
pacer: H_m_prev=60384048 h_t=+8.914982e-001 H_T=114216321 h_a=+9.328191e-001 H_a=116711440 h_g=+1.000000e+000 H_g=120768096 u_a=+9.315841e-001 u_g=+2.500000e-001 W_a=40694120 goalΔ=+1.085018e-001 actualΔ=+4.132083e-002 u_a/u_g=+3.726336e+000
gc 123 @64.360s 9%: 0.20+69+0.21 ms clock, 0.20+47/15/0+0.21 ms cpu, 108->111->43 MB, 115 MB goal, 1 P
pacer: sweep done at heap size 44MB; allocated 0MB of spans; swept 14276 pages at +3.657713e-004 pages/byte
pacer: assist ratio=+1.259505e+001 (scan 72 MB in 82->87 MB) workers=0+1
pacer: H_m_prev=46132840 h_t=+8.687615e-001 H_T=86211273 h_a=+8.939952e-001 H_a=87375376 h_g=+1.000000e+000 H_g=92265680 u_a=+2.831602e-001 u_g=+2.500000e-001 W_a=50234792 goalΔ=+1.312385e-001 actualΔ=+2.523370e-002 u_a/u_g=+1.132641e+000
gc 124 @64.752s 9%: 0.12+82+0.21 ms clock, 0.12+2.7/21/54+0.21 ms cpu, 82->83->54 MB, 87 MB goal, 1 P
pacer: sweep done at heap size 55MB; allocated 1MB of spans; swept 10694 pages at +2.082901e-004 pages/byte
pacer: assist ratio=+2.128806e+001 (scan 92 MB in 104->108 MB) workers=0+1
pacer: H_m_prev=56940520 h_t=+9.200904e-001 H_T=109330944 h_a=+9.527310e-001 H_a=111189520 h_g=+1.000000e+000 H_g=113881040 u_a=+9.571572e-001 u_g=+2.500000e-001 W_a=40981224 goalΔ=+7.990962e-002 actualΔ=+3.264065e-002 u_a/u_g=+3.828629e+000
gc 125 @65.744s 9%: 0.17+71+0.20 ms clock, 0.17+50/15/0+0.20 ms cpu, 104->106->44 MB, 108 MB goal, 1 P
pacer: sweep done at heap size 48MB; allocated 4MB of spans; swept 13601 pages at +3.345599e-004 pages/byte
pacer: assist ratio=+1.640484e+001 (scan 74 MB in 84->88 MB) workers=0+1
pacer: H_m_prev=46461464 h_t=+8.975607e-001 H_T=88163449 h_a=+9.403707e-001 H_a=90152464 h_g=+1.000000e+000 H_g=92922928 u_a=+8.333064e-001 u_g=+2.500000e-001 W_a=34247112 goalΔ=+1.024393e-001 actualΔ=+4.280999e-002 u_a/u_g=+3.333226e+000
gc 126 @66.168s 9%: 0.22+60+0.20 ms clock, 0.22+35/19/0+0.20 ms cpu, 84->85->37 MB, 88 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 6MB of spans; swept 11033 pages at +3.340501e-004 pages/byte
pacer: assist ratio=+1.355208e+001 (scan 61 MB in 69->74 MB) workers=0+1
pacer: H_m_prev=38836664 h_t=+8.774327e-001 H_T=72913222 h_a=+9.486020e-001 H_a=75677200 h_g=+1.000000e+000 H_g=77673328 u_a=+8.098055e-001 u_g=+2.500000e-001 W_a=47425448 goalΔ=+1.225673e-001 actualΔ=+7.116929e-002 u_a/u_g=+3.239222e+000
gc 127 @66.678s 9%: 0.17+81+0.22 ms clock, 0.17+45/28/0+0.22 ms cpu, 69->72->51 MB, 74 MB goal, 1 P
pacer: sweep done at heap size 59MB; allocated 8MB of spans; swept 9266 pages at +2.144231e-004 pages/byte
pacer: assist ratio=+9.136627e+000 (scan 82 MB in 93->102 MB) workers=0+1
pacer: H_m_prev=53752168 h_t=+8.234498e-001 H_T=98014379 h_a=+9.028966e-001 H_a=102284816 h_g=+1.000000e+000 H_g=107504336 u_a=+8.728157e-001 u_g=+2.500000e-001 W_a=44852080 goalΔ=+1.765502e-001 actualΔ=+7.944678e-002 u_a/u_g=+3.491263e+000
gc 128 @67.258s 9%: 0.11+77+0.19 ms clock, 0.11+48/17/0+0.19 ms cpu, 93->97->48 MB, 102 MB goal, 1 P
pacer: sweep done at heap size 50MB; allocated 1MB of spans; swept 12514 pages at +3.271931e-004 pages/byte
pacer: assist ratio=+6.909807e+000 (scan 76 MB in 85->96 MB) workers=0+1
pacer: H_m_prev=50831904 h_t=+7.730401e-001 H_T=90127003 h_a=+9.092365e-001 H_a=97050128 h_g=+1.000000e+000 H_g=101663808 u_a=+7.277037e-001 u_g=+2.500000e-001 W_a=53013592 goalΔ=+2.269599e-001 actualΔ=+1.361964e-001 u_a/u_g=+2.910815e+000
gc 129 @67.889s 9%: 0.19+93+0.20 ms clock, 0.19+44/30/0+0.20 ms cpu, 85->92->57 MB, 96 MB goal, 1 P
pacer: sweep done at heap size 79MB; allocated 22MB of spans; swept 11875 pages at +2.947388e-004 pages/byte
pacer: assist ratio=+4.791293e+000 (scan 85 MB in 96->114 MB) workers=0+1
pacer: H_m_prev=60058936 h_t=+6.882987e-001 H_T=101397426 h_a=+6.891613e-001 H_a=101449232 h_g=+1.000000e+000 H_g=120117872 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=32728344 goalΔ=+3.117013e-001 actualΔ=+8.625773e-004 u_a/u_g=+1.000000e+000
gc 130 @68.273s 9%: 0.17+56+0.28 ms clock, 0.17+0/15/40+0.28 ms cpu, 96->96->35 MB, 114 MB goal, 1 P
pacer: sweep done at heap size 35MB; allocated 0MB of spans; swept 12412 pages at +4.099632e-004 pages/byte
pacer: assist ratio=+1.042991e+001 (scan 57 MB in 65->70 MB) workers=0+1
pacer: H_m_prev=37126696 h_t=+8.437181e-001 H_T=68451160 h_a=+9.721550e-001 H_a=73219600 h_g=+1.000000e+000 H_g=74253392 u_a=+7.652076e-001 u_g=+2.500000e-001 W_a=52730240 goalΔ=+1.562819e-001 actualΔ=+1.284369e-001 u_a/u_g=+3.060830e+000
gc 131 @68.637s 9%: 0.10+94+0.22 ms clock, 0.10+48/31/0+0.22 ms cpu, 65->69->56 MB, 70 MB goal, 1 P
Higher latency than expected at iteration 684.  Tick was delayed 71.482154ms
pacer: sweep done at heap size 58MB; allocated 1MB of spans; swept 8966 pages at +2.120281e-004 pages/byte
pacer: assist ratio=+5.555145e+000 (scan 86 MB in 98->113 MB) workers=0+1
Higher latency than expected at iteration 689.  Tick was delayed 20.366839ms
pacer: H_m_prev=59748512 h_t=+7.252972e-001 H_T=103083940 h_a=+8.210732e-001 H_a=108806416 h_g=+1.000000e+000 H_g=119497024 u_a=+7.478888e-001 u_g=+2.500000e-001 W_a=36930816 goalΔ=+2.747028e-001 actualΔ=+9.577603e-002 u_a/u_g=+2.991555e+000
gc 132 @69.123s 9%: 0.11+68+0.24 ms clock, 0.11+34/17/0+0.24 ms cpu, 98->103->39 MB, 113 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 3MB of spans; swept 13308 pages at +4.578926e-004 pages/byte
pacer: assist ratio=+5.420447e+000 (scan 60 MB in 68->79 MB) workers=0+1
pacer: H_m_prev=41857968 h_t=+7.193890e-001 H_T=71970127 h_a=+7.371175e-001 H_a=72712208 h_g=+1.000000e+000 H_g=83715936 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=29831048 goalΔ=+2.806110e-001 actualΔ=+1.772853e-002 u_a/u_g=+1.000000e+000
gc 133 @69.867s 9%: 0.17+49+0.27 ms clock, 0.17+0/15/32+0.27 ms cpu, 68->69->32 MB, 79 MB goal, 1 P
pacer: sweep done at heap size 32MB; allocated 0MB of spans; swept 8905 pages at +3.209405e-004 pages/byte
pacer: assist ratio=+1.097903e+001 (scan 52 MB in 59->64 MB) workers=0+1
Higher latency than expected at iteration 698.  Tick was delayed 50.135733ms
pacer: H_m_prev=33843592 h_t=+8.508302e-001 H_T=62638742 h_a=+9.955069e-001 H_a=67535120 h_g=+1.000000e+000 H_g=67687184 u_a=+7.507272e-001 u_g=+2.500000e-001 W_a=57176512 goalΔ=+1.491698e-001 actualΔ=+1.446766e-001 u_a/u_g=+3.002909e+000
gc 134 @69.991s 9%: 0.11+112+0.22 ms clock, 0.11+56/39/0+0.22 ms cpu, 59->64->61 MB, 64 MB goal, 1 P
pacer: sweep done at heap size 63MB; allocated 1MB of spans; swept 8270 pages at +1.844775e-004 pages/byte
pacer: assist ratio=+5.178924e+000 (scan 93 MB in 105->123 MB) workers=0+1
pacer: H_m_prev=64781936 h_t=+7.081897e-001 H_T=110659836 h_a=+8.341036e-001 H_a=118816784 h_g=+1.000000e+000 H_g=129563872 u_a=+7.750632e-001 u_g=+2.500000e-001 W_a=52163520 goalΔ=+2.918103e-001 actualΔ=+1.259139e-001 u_a/u_g=+3.100253e+000
gc 135 @70.709s 9%: 0.14+93+0.20 ms clock, 0.14+49/22/0+0.20 ms cpu, 105->113->56 MB, 123 MB goal, 1 P
Higher latency than expected at iteration 705.  Tick was delayed 24.355215ms
pacer: sweep done at heap size 60MB; allocated 3MB of spans; swept 14533 pages at +3.835890e-004 pages/byte
pacer: assist ratio=+4.302388e+000 (scan 82 MB in 93->112 MB) workers=0+1
pacer: H_m_prev=59090528 h_t=+6.589124e-001 H_T=98026007 h_a=+7.102028e-001 H_a=101056784 h_g=+1.000000e+000 H_g=118181056 u_a=+2.902312e-001 u_g=+2.500000e-001 W_a=36117888 goalΔ=+3.410876e-001 actualΔ=+5.129039e-002 u_a/u_g=+1.160925e+000
gc 136 @71.611s 9%: 0.22+73+0.21 ms clock, 0.22+2.9/24/34+0.21 ms cpu, 93->96->39 MB, 112 MB goal, 1 P
pacer: sweep done at heap size 40MB; allocated 1MB of spans; swept 12362 pages at +3.899887e-004 pages/byte
pacer: assist ratio=+7.949200e+000 (scan 62 MB in 70->78 MB) workers=0+1
pacer: H_m_prev=40949840 h_t=+7.996840e-001 H_T=73696773 h_a=+9.216646e-001 H_a=78691856 h_g=+1.000000e+000 H_g=81899680 u_a=+7.577131e-001 u_g=+2.500000e-001 W_a=55427648 goalΔ=+2.003160e-001 actualΔ=+1.219805e-001 u_a/u_g=+3.030852e+000
gc 137 @71.920s 9%: 0.10+92+0.22 ms clock, 0.10+47/32/0+0.22 ms cpu, 70->75->59 MB, 78 MB goal, 1 P
pacer: sweep done at heap size 66MB; allocated 6MB of spans; swept 9634 pages at +2.196872e-004 pages/byte
pacer: assist ratio=+5.324114e+000 (scan 90 MB in 102->119 MB) workers=0+1
pacer: H_m_prev=62800688 h_t=+7.149895e-001 H_T=107702523 h_a=+7.917768e-001 H_a=112524816 h_g=+1.000000e+000 H_g=125601376 u_a=+6.707533e-001 u_g=+2.500000e-001 W_a=38641280 goalΔ=+2.850105e-001 actualΔ=+7.678726e-002 u_a/u_g=+2.683013e+000
gc 138 @72.572s 9%: 0.11+65+0.30 ms clock, 0.11+27/25/0+0.30 ms cpu, 102->107->41 MB, 119 MB goal, 1 P
pacer: sweep done at heap size 58MB; allocated 16MB of spans; swept 13764 pages at +4.301724e-004 pages/byte
pacer: assist ratio=+6.321807e+000 (scan 64 MB in 73->83 MB) workers=0+1
pacer: H_m_prev=43798208 h_t=+7.544842e-001 H_T=76843261 h_a=+8.183878e-001 H_a=79642128 h_g=+1.000000e+000 H_g=87596416 u_a=+3.989860e-001 u_g=+2.500000e-001 W_a=44948344 goalΔ=+2.455158e-001 actualΔ=+6.390367e-002 u_a/u_g=+1.595944e+000
gc 139 @72.807s 9%: 0.17+74+0.20 ms clock, 0.17+11/24/31+0.20 ms cpu, 73->75->48 MB, 83 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 3MB of spans; swept 9750 pages at +2.375308e-004 pages/byte
pacer: assist ratio=+9.295556e+000 (scan 78 MB in 88->97 MB) workers=0+1
pacer: H_m_prev=50948200 h_t=+8.262487e-001 H_T=93044086 h_a=+9.074511e-001 H_a=97181200 h_g=+1.000000e+000 H_g=101896400 u_a=+8.496326e-001 u_g=+2.500000e-001 W_a=41870552 goalΔ=+1.737513e-001 actualΔ=+8.120236e-002 u_a/u_g=+3.398530e+000
gc 140 @73.619s 9%: 0.11+71+0.20 ms clock, 0.11+43/16/0+0.20 ms cpu, 88->92->45 MB, 97 MB goal, 1 P
pacer: sweep done at heap size 47MB; allocated 2MB of spans; swept 11891 pages at +3.327343e-004 pages/byte
pacer: assist ratio=+6.982736e+000 (scan 71 MB in 80->90 MB) workers=0+1
pacer: H_m_prev=47456968 h_t=+7.751400e-001 H_T=84242763 h_a=+8.860306e-001 H_a=89505296 h_g=+1.000000e+000 H_g=94913936 u_a=+2.640225e-001 u_g=+2.500000e-001 W_a=37463880 goalΔ=+2.248600e-001 actualΔ=+1.108906e-001 u_a/u_g=+1.056090e+000
gc 141 @74.084s 9%: 0.20+65+0.19 ms clock, 0.20+0.92/15/36+0.19 ms cpu, 80->85->40 MB, 90 MB goal, 1 P
pacer: sweep done at heap size 42MB; allocated 1MB of spans; swept 10954 pages at +3.207238e-004 pages/byte
pacer: assist ratio=+9.463190e+000 (scan 65 MB in 74->80 MB) workers=0+1
pacer: H_m_prev=42463144 h_t=+8.290148e-001 H_T=77665718 h_a=+8.996739e-001 H_a=80666128 h_g=+1.000000e+000 H_g=84926288 u_a=+7.948582e-001 u_g=+2.500000e-001 W_a=34768456 goalΔ=+1.709852e-001 actualΔ=+7.065914e-002 u_a/u_g=+3.179433e+000
gc 142 @75.179s 9%: 0.14+83+0.52 ms clock, 0.14+45/22/0+0.52 ms cpu, 74->76->37 MB, 80 MB goal, 1 P
Higher latency than expected at iteration 750.  Tick was delayed 35.662618ms
pacer: sweep done at heap size 41MB; allocated 3MB of spans; swept 9875 pages at +3.229750e-004 pages/byte
pacer: assist ratio=+8.056163e+000 (scan 59 MB in 67->75 MB) workers=0+1
pacer: H_m_prev=39422232 h_t=+8.021794e-001 H_T=71045934 h_a=+9.028455e-001 H_a=75014416 h_g=+1.000000e+000 H_g=78844464 u_a=+8.206787e-001 u_g=+2.500000e-001 W_a=35942624 goalΔ=+1.978206e-001 actualΔ=+1.006661e-001 u_a/u_g=+3.282715e+000
gc 143 @75.658s 9%: 0.27+106+0.21 ms clock, 0.27+61/26/0+0.21 ms cpu, 67->71->38 MB, 75 MB goal, 1 P
Higher latency than expected at iteration 755.  Tick was delayed 66.891266ms
pacer: sweep done at heap size 66MB; allocated 27MB of spans; swept 9183 pages at +3.173614e-004 pages/byte
pacer: assist ratio=+5.812511e+000 (scan 59 MB in 67->77 MB) workers=0+1
pacer: H_m_prev=40746896 h_t=+7.358607e-001 H_T=70730935 h_a=+9.748814e-001 H_a=80470288 h_g=+1.000000e+000 H_g=81493792 u_a=+7.257321e-001 u_g=+2.500000e-001 W_a=64733656 goalΔ=+2.641393e-001 actualΔ=+2.390207e-001 u_a/u_g=+2.902928e+000
gc 144 @75.863s 9%: 0.13+120+0.21 ms clock, 0.13+57/35/0+0.21 ms cpu, 67->76->69 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 70MB; allocated 0MB of spans; swept 9849 pages at +2.651290e-004 pages/byte
pacer: assist ratio=+2.808730e+000 (scan 94 MB in 106->139 MB) workers=0+1
Higher latency than expected at iteration 761.  Tick was delayed 22.567233ms
pacer: H_m_prev=73313832 h_t=+5.210003e-001 H_T=111510362 h_a=+7.396652e-001 H_a=127541520 h_g=+1.000000e+000 H_g=146627664 u_a=+4.415526e-001 u_g=+2.500000e-001 W_a=58486976 goalΔ=+4.789997e-001 actualΔ=+2.186648e-001 u_a/u_g=+1.766210e+000
gc 145 @76.344s 10%: 0.13+114+0.19 ms clock, 0.13+21/30/18+0.19 ms cpu, 106->121->63 MB, 139 MB goal, 1 P
pacer: sweep done at heap size 65MB; allocated 2MB of spans; swept 15595 pages at +4.270243e-004 pages/byte
pacer: assist ratio=+3.205707e+000 (scan 87 MB in 98->126 MB) workers=0+1
pacer: H_m_prev=66212560 h_t=+5.673961e-001 H_T=103781308 h_a=+6.096332e-001 H_a=106577936 h_g=+1.000000e+000 H_g=132425120 u_a=+2.746051e-001 u_g=+2.500000e-001 W_a=42468056 goalΔ=+4.326039e-001 actualΔ=+4.223711e-002 u_a/u_g=+1.098421e+000
gc 146 @76.778s 9%: 0.10+70+0.19 ms clock, 0.10+1.7/30/31+0.19 ms cpu, 98->101->45 MB, 126 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 6MB of spans; swept 13039 pages at +3.666571e-004 pages/byte
pacer: assist ratio=+6.501728e+000 (scan 71 MB in 80->91 MB) workers=0+1
pacer: H_m_prev=48139864 h_t=+7.605010e-001 H_T=84750278 h_a=+8.480448e-001 H_a=88964624 h_g=+1.000000e+000 H_g=96279728 u_a=+3.220166e-001 u_g=+2.500000e-001 W_a=41572840 goalΔ=+2.394990e-001 actualΔ=+8.754378e-002 u_a/u_g=+1.288066e+000
gc 147 @77.399s 9%: 0.13+74+0.20 ms clock, 0.13+5.4/19/37+0.20 ms cpu, 80->84->44 MB, 91 MB goal, 1 P
pacer: sweep done at heap size 46MB; allocated 1MB of spans; swept 10888 pages at +2.882570e-004 pages/byte
pacer: assist ratio=+9.160106e+000 (scan 72 MB in 81->89 MB) workers=0+1
pacer: H_m_prev=47119640 h_t=+8.238694e-001 H_T=85940069 h_a=+9.165705e-001 H_a=90308112 h_g=+1.000000e+000 H_g=94239280 u_a=+8.579179e-001 u_g=+2.500000e-001 W_a=46306816 goalΔ=+1.761306e-001 actualΔ=+9.270110e-002 u_a/u_g=+3.431672e+000
gc 148 @77.934s 9%: 0.18+78+0.19 ms clock, 0.18+47/18/0+0.19 ms cpu, 81->86->50 MB, 89 MB goal, 1 P
Higher latency than expected at iteration 777.  Tick was delayed 32.07223ms
pacer: sweep done at heap size 50MB; allocated 0MB of spans; swept 11052 pages at +2.873575e-004 pages/byte
pacer: assist ratio=+6.271551e+000 (scan 77 MB in 87->100 MB) workers=0+1
pacer: H_m_prev=52478016 h_t=+7.528748e-001 H_T=91987394 h_a=+7.794286e-001 H_a=93380880 h_g=+1.000000e+000 H_g=104956032 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=31355936 goalΔ=+2.471252e-001 actualΔ=+2.655371e-002 u_a/u_g=+1.000000e+000
gc 149 @78.784s 9%: 0.12+51+0.19 ms clock, 0.12+0/19/28+0.19 ms cpu, 87->89->33 MB, 100 MB goal, 1 P
pacer: sweep done at heap size 33MB; allocated 0MB of spans; swept 11425 pages at +3.853109e-004 pages/byte
pacer: assist ratio=+1.205114e+001 (scan 55 MB in 63->67 MB) workers=0+1
Higher latency than expected at iteration 788.  Tick was delayed 27.580278ms
pacer: H_m_prev=35566912 h_t=+8.631606e-001 H_T=66266867 h_a=+9.895674e-001 H_a=70762768 h_g=+1.000000e+000 H_g=71133824 u_a=+7.838054e-001 u_g=+2.500000e-001 W_a=56767800 goalΔ=+1.368394e-001 actualΔ=+1.264068e-001 u_a/u_g=+3.135222e+000
gc 150 @79.034s 9%: 0.10+96+0.21 ms clock, 0.10+51/32/0+0.21 ms cpu, 63->67->61 MB, 67 MB goal, 1 P
pacer: sweep done at heap size 66MB; allocated 5MB of spans; swept 8664 pages at +1.878336e-004 pages/byte
pacer: assist ratio=+5.753570e+000 (scan 94 MB in 106->122 MB) workers=0+1
pacer: H_m_prev=64320952 h_t=+7.334236e-001 H_T=111495455 h_a=+7.402650e-001 H_a=111935504 h_g=+1.000000e+000 H_g=128641904 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=34189792 goalΔ=+2.665764e-001 actualΔ=+6.841447e-003 u_a/u_g=+1.000000e+000
gc 151 @79.989s 9%: 0.16+56+0.18 ms clock, 0.16+0/15/39+0.18 ms cpu, 106->106->36 MB, 122 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 1MB of spans; swept 13693 pages at +4.222409e-004 pages/byte
pacer: assist ratio=+1.205749e+001 (scan 60 MB in 68->73 MB) workers=0+1
pacer: H_m_prev=38779424 h_t=+8.632911e-001 H_T=72257354 h_a=+9.307761e-001 H_a=74874384 h_g=+1.000000e+000 H_g=77558848 u_a=+8.797222e-001 u_g=+2.500000e-001 W_a=33592592 goalΔ=+1.367089e-001 actualΔ=+6.748500e-002 u_a/u_g=+3.518889e+000
gc 152 @80.867s 9%: 0.13+64+0.19 ms clock, 0.13+40/15/0+0.19 ms cpu, 68->71->36 MB, 73 MB goal, 1 P
pacer: sweep done at heap size 40MB; allocated 4MB of spans; swept 9168 pages at +3.064427e-004 pages/byte
pacer: assist ratio=+8.575898e+000 (scan 58 MB in 65->72 MB) workers=0+1
pacer: H_m_prev=38092896 h_t=+8.129094e-001 H_T=69058970 h_a=+8.591221e-001 H_a=70819344 h_g=+1.000000e+000 H_g=76185792 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=51479872 goalΔ=+1.870906e-001 actualΔ=+4.621266e-002 u_a/u_g=+1.000000e+000
gc 153 @81.025s 9%: 0.11+94+0.23 ms clock, 0.11+0/33/55+0.23 ms cpu, 65->67->55 MB, 72 MB goal, 1 P
pacer: sweep done at heap size 55MB; allocated 0MB of spans; swept 8673 pages at +1.717691e-004 pages/byte
pacer: assist ratio=+1.429717e+001 (scan 92 MB in 104->111 MB) workers=0+1
pacer: H_m_prev=58347072 h_t=+8.833484e-001 H_T=109887863 h_a=+9.262962e-001 H_a=112393744 h_g=+1.000000e+000 H_g=116694144 u_a=+8.378024e-001 u_g=+2.500000e-001 W_a=37588232 goalΔ=+1.166516e-001 actualΔ=+4.294783e-002 u_a/u_g=+3.351210e+000
gc 154 @81.974s 9%: 0.10+62+0.18 ms clock, 0.10+36/18/0+0.18 ms cpu, 104->107->40 MB, 111 MB goal, 1 P
pacer: sweep done at heap size 42MB; allocated 1MB of spans; swept 13748 pages at +3.817208e-004 pages/byte
pacer: assist ratio=+1.269425e+001 (scan 67 MB in 75->81 MB) workers=0+1
pacer: H_m_prev=42616968 h_t=+8.697106e-001 H_T=79681396 h_a=+9.179985e-001 H_a=81739280 h_g=+1.000000e+000 H_g=85233936 u_a=+5.879685e-001 u_g=+2.500000e-001 W_a=35679768 goalΔ=+1.302894e-001 actualΔ=+4.828789e-002 u_a/u_g=+2.351874e+000
gc 155 @82.593s 9%: 0.11+63+0.19 ms clock, 0.11+21/22/12+0.19 ms cpu, 75->77->38 MB, 81 MB goal, 1 P
pacer: sweep done at heap size 40MB; allocated 1MB of spans; swept 10006 pages at +2.902229e-004 pages/byte
pacer: assist ratio=+1.363394e+001 (scan 64 MB in 72->77 MB) workers=0+1
pacer: H_m_prev=40458568 h_t=+8.780718e-001 H_T=75984094 h_a=+9.403415e-001 H_a=78503440 h_g=+1.000000e+000 H_g=80917136 u_a=+8.672140e-001 u_g=+2.500000e-001 W_a=36362928 goalΔ=+1.219282e-001 actualΔ=+6.226976e-002 u_a/u_g=+3.468856e+000
gc 156 @82.965s 9%: 0.11+61+0.46 ms clock, 0.11+38/16/0+0.46 ms cpu, 72->74->39 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 41MB; allocated 2MB of spans; swept 9611 pages at +2.893601e-004 pages/byte
pacer: assist ratio=+9.588010e+000 (scan 63 MB in 71->78 MB) workers=0+1
pacer: H_m_prev=41229680 h_t=+8.310335e-001 H_T=75492924 h_a=+9.288881e-001 H_a=79527440 h_g=+1.000000e+000 H_g=82459360 u_a=+6.759668e-001 u_g=+2.500000e-001 W_a=40642624 goalΔ=+1.689665e-001 actualΔ=+9.785464e-002 u_a/u_g=+2.703867e+000
gc 157 @83.407s 9%: 0.24+77+0.72 ms clock, 0.24+33/32/0+0.72 ms cpu, 71->75->43 MB, 78 MB goal, 1 P
pacer: sweep done at heap size 53MB; allocated 9MB of spans; swept 9736 pages at +2.779127e-004 pages/byte
pacer: assist ratio=+7.273994e+000 (scan 69 MB in 78->87 MB) workers=0+1
pacer: H_m_prev=46067504 h_t=+7.832238e-001 H_T=82148667 h_a=+9.107296e-001 H_a=88022544 h_g=+1.000000e+000 H_g=92135008 u_a=+6.882909e-001 u_g=+2.500000e-001 W_a=57953640 goalΔ=+2.167762e-001 actualΔ=+1.275059e-001 u_a/u_g=+2.753164e+000
gc 158 @83.620s 9%: 0.12+102+0.26 ms clock, 0.12+44/25/15+0.26 ms cpu, 78->83->62 MB, 87 MB goal, 1 P
pacer: sweep done at heap size 62MB; allocated 0MB of spans; swept 10773 pages at +2.343613e-004 pages/byte
pacer: assist ratio=+5.348956e+000 (scan 95 MB in 107->125 MB) workers=0+1
pacer: H_m_prev=65656680 h_t=+7.160896e-001 H_T=112672747 h_a=+8.044197e-001 H_a=118472208 h_g=+1.000000e+000 H_g=131313360 u_a=+6.648918e-001 u_g=+2.500000e-001 W_a=42458640 goalΔ=+2.839104e-001 actualΔ=+8.833009e-002 u_a/u_g=+2.659567e+000
gc 159 @84.874s 9%: 0.11+73+0.20 ms clock, 0.11+30/17/9.7+0.20 ms cpu, 107->112->45 MB, 125 MB goal, 1 P
pacer: sweep done at heap size 47MB; allocated 1MB of spans; swept 14490 pages at +4.189696e-004 pages/byte
pacer: assist ratio=+5.936691e+000 (scan 70 MB in 79->91 MB) workers=0+1
pacer: H_m_prev=48115248 h_t=+7.405849e-001 H_T=83748675 h_a=+7.422386e-001 H_a=83828240 h_g=+1.000000e+000 H_g=96230496 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=39449200 goalΔ=+2.594151e-001 actualΔ=+1.653633e-003 u_a/u_g=+1.000000e+000
gc 160 @85.274s 9%: 0.16+63+0.17 ms clock, 0.16+0/14/47+0.17 ms cpu, 79->79->42 MB, 91 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 0MB of spans; swept 10261 pages at +2.711163e-004 pages/byte
pacer: assist ratio=+1.266504e+001 (scan 70 MB in 79->85 MB) workers=0+1
pacer: H_m_prev=44735296 h_t=+8.694656e-001 H_T=83631098 h_a=+9.084825e-001 H_a=85376528 h_g=+1.000000e+000 H_g=89470592 u_a=+5.990427e-001 u_g=+2.500000e-001 W_a=39290992 goalΔ=+1.305344e-001 actualΔ=+3.901682e-002 u_a/u_g=+2.396171e+000
gc 161 @85.896s 9%: 0.11+69+0.25 ms clock, 0.11+24/29/10+0.25 ms cpu, 79->81->42 MB, 85 MB goal, 1 P
Higher latency than expected at iteration 857.  Tick was delayed 27.721726ms
pacer: sweep done at heap size 42MB; allocated 0MB of spans; swept 10450 pages at +2.713618e-004 pages/byte
pacer: assist ratio=+1.490550e+001 (scan 70 MB in 80->84 MB) workers=0+1
pacer: H_m_prev=44547984 h_t=+8.879873e-001 H_T=84106029 h_a=+9.639684e-001 H_a=87490832 h_g=+1.000000e+000 H_g=89095968 u_a=+7.838437e-001 u_g=+2.500000e-001 W_a=51957064 goalΔ=+1.120127e-001 actualΔ=+7.598104e-002 u_a/u_g=+3.135375e+000
gc 162 @86.198s 9%: 0.13+89+0.20 ms clock, 0.13+47/31/0+0.20 ms cpu, 80->83->56 MB, 84 MB goal, 1 P
Higher latency than expected at iteration 860.  Tick was delayed 20.60584ms
pacer: sweep done at heap size 57MB; allocated 0MB of spans; swept 10706 pages at +2.252941e-004 pages/byte
pacer: assist ratio=+9.220963e+000 (scan 90 MB in 102->112 MB) workers=0+1
pacer: H_m_prev=58879752 h_t=+8.248791e-001 H_T=107448431 h_a=+8.347254e-001 H_a=108028176 h_g=+1.000000e+000 H_g=117759504 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=35750424 goalΔ=+1.751209e-001 actualΔ=+9.846243e-003 u_a/u_g=+1.000000e+000
gc 163 @86.828s 9%: 0.11+54+0.24 ms clock, 0.11+0/18/34+0.24 ms cpu, 102->103->38 MB, 112 MB goal, 1 P
pacer: sweep done at heap size 48MB; allocated 10MB of spans; swept 13213 pages at +3.696215e-004 pages/byte
pacer: assist ratio=+1.827125e+001 (scan 65 MB in 73->77 MB) workers=0+1
pacer: H_m_prev=40545768 h_t=+9.075165e-001 H_T=77341719 h_a=+9.589994e-001 H_a=79429136 h_g=+1.000000e+000 H_g=81091536 u_a=+9.098219e-001 u_g=+2.500000e-001 W_a=42032208 goalΔ=+9.248355e-002 actualΔ=+5.148297e-002 u_a/u_g=+3.639287e+000
gc 164 @87.209s 9%: 0.13+72+0.22 ms clock, 0.13+47/17/0+0.22 ms cpu, 73->75->45 MB, 77 MB goal, 1 P
pacer: sweep done at heap size 50MB; allocated 4MB of spans; swept 9724 pages at +2.435002e-004 pages/byte
pacer: assist ratio=+1.176380e+001 (scan 74 MB in 84->90 MB) workers=0+1
pacer: H_m_prev=47650160 h_t=+8.600776e-001 H_T=88632993 h_a=+9.125960e-001 H_a=91135504 h_g=+1.000000e+000 H_g=95300320 u_a=+8.631986e-001 u_g=+2.500000e-001 W_a=31485848 goalΔ=+1.399224e-001 actualΔ=+5.251840e-002 u_a/u_g=+3.452794e+000
gc 165 @88.547s 9%: 0.14+59+0.21 ms clock, 0.14+36/15/0+0.21 ms cpu, 84->86->34 MB, 90 MB goal, 1 P
pacer: sweep done at heap size 55MB; allocated 21MB of spans; swept 11153 pages at +3.855920e-004 pages/byte
pacer: assist ratio=+1.012689e+001 (scan 55 MB in 62->68 MB) workers=0+1
pacer: H_m_prev=35708792 h_t=+8.393712e-001 H_T=65681722 h_a=+9.520468e-001 H_a=69705232 h_g=+1.000000e+000 H_g=71417584 u_a=+8.394946e-001 u_g=+2.500000e-001 W_a=46633464 goalΔ=+1.606288e-001 actualΔ=+1.126756e-001 u_a/u_g=+3.357978e+000
gc 166 @88.763s 9%: 0.11+83+0.20 ms clock, 0.11+49/22/0+0.20 ms cpu, 62->66->50 MB, 68 MB goal, 1 P
Higher latency than expected at iteration 886.  Tick was delayed 32.709532ms
pacer: sweep done at heap size 65MB; allocated 15MB of spans; swept 8537 pages at +2.272982e-004 pages/byte
pacer: assist ratio=+5.680190e+000 (scan 77 MB in 87->100 MB) workers=0+1
pacer: H_m_prev=52850008 h_t=+7.305045e-001 H_T=91457174 h_a=+7.884495e-001 H_a=94519568 h_g=+1.000000e+000 H_g=105700016 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=69450464 goalΔ=+2.694955e-001 actualΔ=+5.794499e-002 u_a/u_g=+1.000000e+000
gc 167 @88.946s 9%: 0.11+113+0.21 ms clock, 0.11+0/39/65+0.21 ms cpu, 87->90->75 MB, 100 MB goal, 1 P
pacer: sweep done at heap size 75MB; allocated 0MB of spans; swept 11564 pages at +1.785822e-004 pages/byte
pacer: assist ratio=+9.923553e+000 (scan 121 MB in 137->150 MB) workers=0+1
pacer: H_m_prev=78685488 h_t=+8.362797e-001 H_T=144488567 h_a=+8.733613e-001 H_a=147406352 h_g=+1.000000e+000 H_g=157370976 u_a=+4.807805e-001 u_g=+2.500000e-001 W_a=32805808 goalΔ=+1.637203e-001 actualΔ=+3.708161e-002 u_a/u_g=+1.923122e+000
gc 168 @90.226s 9%: 0.13+62+0.39 ms clock, 0.13+14/18/21+0.39 ms cpu, 137->140->35 MB, 150 MB goal, 1 P
pacer: sweep done at heap size 35MB; allocated 0MB of spans; swept 18022 pages at +5.670747e-004 pages/byte
pacer: assist ratio=+1.417385e+001 (scan 59 MB in 66->70 MB) workers=0+1
pacer: H_m_prev=37200944 h_t=+8.824836e-001 H_T=70030168 h_a=+9.435554e-001 H_a=72302096 h_g=+1.000000e+000 H_g=74401888 u_a=+8.515088e-001 u_g=+2.500000e-001 W_a=33806096 goalΔ=+1.175164e-001 actualΔ=+6.107177e-002 u_a/u_g=+3.406035e+000
gc 169 @90.979s 9%: 0.17+61+0.20 ms clock, 0.17+37/16/0+0.20 ms cpu, 66->68->36 MB, 70 MB goal, 1 P
pacer: sweep done at heap size 38MB; allocated 2MB of spans; swept 8854 pages at +2.851699e-004 pages/byte
pacer: assist ratio=+9.981228e+000 (scan 59 MB in 67->73 MB) workers=0+1
pacer: H_m_prev=38336560 h_t=+8.372355e-001 H_T=70433290 h_a=+9.180358e-001 H_a=73530896 h_g=+1.000000e+000 H_g=76673120 u_a=+7.995101e-001 u_g=+2.500000e-001 W_a=33261208 goalΔ=+1.627645e-001 actualΔ=+8.080031e-002 u_a/u_g=+3.198041e+000
gc 170 @91.780s 9%: 0.15+58+0.18 ms clock, 0.15+32/17/0+0.18 ms cpu, 67->70->35 MB, 73 MB goal, 1 P
Higher latency than expected at iteration 916.  Tick was delayed 23.675607ms
pacer: sweep done at heap size 45MB; allocated 9MB of spans; swept 9004 pages at +3.134596e-004 pages/byte
pacer: assist ratio=+7.516462e+000 (scan 56 MB in 64->71 MB) workers=0+1
pacer: H_m_prev=37715416 h_t=+7.894164e-001 H_T=67488585 h_a=+8.851347e-001 H_a=71098640 h_g=+1.000000e+000 H_g=75430832 u_a=+6.874473e-001 u_g=+2.500000e-001 W_a=40351936 goalΔ=+2.105836e-001 actualΔ=+9.571828e-002 u_a/u_g=+2.749789e+000
gc 171 @92.188s 9%: 0.12+69+0.19 ms clock, 0.12+30/28/0+0.19 ms cpu, 64->67->43 MB, 71 MB goal, 1 P
Higher latency than expected at iteration 920.  Tick was delayed 26.930353ms
pacer: sweep done at heap size 48MB; allocated 5MB of spans; swept 8705 pages at +2.571166e-004 pages/byte
pacer: assist ratio=+6.582386e+000 (scan 67 MB in 76->87 MB) workers=0+1
pacer: H_m_prev=45740464 h_t=+7.631057e-001 H_T=80645271 h_a=+8.617238e-001 H_a=85156112 h_g=+1.000000e+000 H_g=91480928 u_a=+6.605036e-001 u_g=+2.500000e-001 W_a=46920728 goalΔ=+2.368943e-001 actualΔ=+9.861817e-002 u_a/u_g=+2.642014e+000
gc 172 @92.546s 9%: 0.16+82+0.23 ms clock, 0.16+33/29/6.3+0.23 ms cpu, 76->81->50 MB, 87 MB goal, 1 P
pacer: sweep done at heap size 52MB; allocated 1MB of spans; swept 10421 pages at +2.678994e-004 pages/byte
pacer: assist ratio=+6.230059e+000 (scan 78 MB in 88->101 MB) workers=0+1
pacer: H_m_prev=53172760 h_t=+7.512775e-001 H_T=93120259 h_a=+8.626226e-001 H_a=99040784 h_g=+1.000000e+000 H_g=106345520 u_a=+8.119139e-001 u_g=+2.500000e-001 W_a=44394368 goalΔ=+2.487225e-001 actualΔ=+1.113451e-001 u_a/u_g=+3.247656e+000
gc 173 @93.405s 9%: 0.15+78+0.23 ms clock, 0.15+44/18/0+0.23 ms cpu, 88->94->47 MB, 101 MB goal, 1 P
pacer: sweep done at heap size 48MB; allocated 0MB of spans; swept 12118 pages at +3.574038e-004 pages/byte
pacer: assist ratio=+4.911762e+000 (scan 71 MB in 81->95 MB) workers=0+1
Higher latency than expected at iteration 938.  Tick was delayed 31.323586ms
pacer: H_m_prev=50305872 h_t=+6.948335e-001 H_T=85260078 h_a=+8.365579e-001 H_a=92389648 h_g=+1.000000e+000 H_g=100611744 u_a=+7.126264e-001 u_g=+2.500000e-001 W_a=48615992 goalΔ=+3.051665e-001 actualΔ=+1.417244e-001 u_a/u_g=+2.850506e+000
gc 174 @94.034s 9%: 0.13+88+0.22 ms clock, 0.13+40/27/0+0.22 ms cpu, 81->88->52 MB, 95 MB goal, 1 P
pacer: sweep done at heap size 68MB; allocated 16MB of spans; swept 11304 pages at +3.276409e-004 pages/byte
pacer: assist ratio=+4.105306e+000 (scan 76 MB in 86->105 MB) workers=0+1
pacer: H_m_prev=55079736 h_t=+6.454237e-001 H_T=90629502 h_a=+6.552146e-001 H_a=91168784 h_g=+1.000000e+000 H_g=110159472 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=31490664 goalΔ=+3.545763e-001 actualΔ=+9.790928e-003 u_a/u_g=+1.000000e+000
gc 175 @94.644s 9%: 0.16+51+0.20 ms clock, 0.16+0/16/34+0.20 ms cpu, 86->86->34 MB, 105 MB goal, 1 P
pacer: sweep done at heap size 50MB; allocated 16MB of spans; swept 11158 pages at +3.961442e-004 pages/byte
pacer: assist ratio=+8.830146e+000 (scan 54 MB in 61->68 MB) workers=0+1
pacer: H_m_prev=35723288 h_t=+8.178164e-001 H_T=64938378 h_a=+9.258003e-001 H_a=68795920 h_g=+1.000000e+000 H_g=71446576 u_a=+8.621462e-001 u_g=+2.500000e-001 W_a=37309360 goalΔ=+1.821836e-001 actualΔ=+1.079840e-001 u_a/u_g=+3.448585e+000
gc 176 @94.962s 9%: 0.18+66+0.19 ms clock, 0.18+40/15/0+0.19 ms cpu, 61->65->40 MB, 68 MB goal, 1 P
pacer: sweep done at heap size 43MB; allocated 3MB of spans; swept 8426 pages at +2.854491e-004 pages/byte
pacer: assist ratio=+5.495782e+000 (scan 61 MB in 69->80 MB) workers=0+1
pacer: H_m_prev=42294800 h_t=+7.227123e-001 H_T=72861770 h_a=+7.797883e-001 H_a=75275792 h_g=+1.000000e+000 H_g=84589600 u_a=+4.525819e-001 u_g=+2.500000e-001 W_a=35632128 goalΔ=+2.772877e-001 actualΔ=+5.707608e-002 u_a/u_g=+1.810327e+000
gc 177 @95.304s 9%: 0.13+58+0.19 ms clock, 0.13+11/25/14+0.19 ms cpu, 69->71->38 MB, 80 MB goal, 1 P
Higher latency than expected at iteration 951.  Tick was delayed 22.98218ms
pacer: sweep done at heap size 38MB; allocated 0MB of spans; swept 9217 pages at +2.910755e-004 pages/byte
pacer: assist ratio=+8.410700e+000 (scan 61 MB in 69->77 MB) workers=0+1
pacer: H_m_prev=40402848 h_t=+8.096929e-001 H_T=73116748 h_a=+9.237745e-001 H_a=77725968 h_g=+1.000000e+000 H_g=80805696 u_a=+6.917493e-001 u_g=+2.500000e-001 W_a=41646672 goalΔ=+1.903071e-001 actualΔ=+1.140815e-001 u_a/u_g=+2.766997e+000
gc 178 @95.891s 9%: 0.11+72+0.22 ms clock, 0.11+31/27/0+0.22 ms cpu, 69->74->45 MB, 77 MB goal, 1 P
Higher latency than expected at iteration 957.  Tick was delayed 35.324977ms
pacer: sweep done at heap size 49MB; allocated 4MB of spans; swept 9514 pages at +2.780917e-004 pages/byte
pacer: assist ratio=+6.108809e+000 (scan 69 MB in 78->90 MB) workers=0+1
pacer: H_m_prev=47201632 h_t=+7.470148e-001 H_T=82461949 h_a=+8.995469e-001 H_a=89661712 h_g=+1.000000e+000 H_g=94403264 u_a=+7.674588e-001 u_g=+2.500000e-001 W_a=56196680 goalΔ=+2.529852e-001 actualΔ=+1.525321e-001 u_a/u_g=+3.069835e+000
gc 179 @96.227s 9%: 0.16+98+0.21 ms clock, 0.16+50/27/0+0.21 ms cpu, 78->85->60 MB, 90 MB goal, 1 P
pacer: sweep done at heap size 70MB; allocated 9MB of spans; swept 10971 pages at +2.766578e-004 pages/byte
pacer: assist ratio=+4.020497e+000 (scan 88 MB in 99->121 MB) workers=0+1
pacer: H_m_prev=63661448 h_t=+6.393833e-001 H_T=104365511 h_a=+7.710247e-001 H_a=112746000 h_g=+1.000000e+000 H_g=127322896 u_a=+7.235583e-001 u_g=+2.500000e-001 W_a=45259400 goalΔ=+3.606167e-001 actualΔ=+1.316415e-001 u_a/u_g=+2.894233e+000
gc 180 @97.259s 9%: 0.17+81+0.20 ms clock, 0.17+38/21/0+0.20 ms cpu, 99->107->48 MB, 121 MB goal, 1 P
pacer: sweep done at heap size 51MB; allocated 2MB of spans; swept 13791 pages at +4.418458e-004 pages/byte
pacer: assist ratio=+3.887122e+000 (scan 70 MB in 79->97 MB) workers=0+1
pacer: H_m_prev=51273496 h_t=+6.291910e-001 H_T=83534320 h_a=+7.894217e-001 H_a=91749904 h_g=+1.000000e+000 H_g=102546992 u_a=+6.884309e-001 u_g=+2.500000e-001 W_a=44741880 goalΔ=+3.708090e-001 actualΔ=+1.602306e-001 u_a/u_g=+2.753724e+000
gc 181 @97.655s 9%: 0.21+79+0.19 ms clock, 0.21+34/23/0+0.19 ms cpu, 79->87->48 MB, 97 MB goal, 1 P
pacer: sweep done at heap size 49MB; allocated 1MB of spans; swept 11228 pages at +3.863812e-004 pages/byte
pacer: assist ratio=+3.471529e+000 (scan 68 MB in 77->96 MB) workers=0+1
pacer: H_m_prev=50688504 h_t=+5.939801e-001 H_T=80796466 h_a=+7.213468e-001 H_a=87252496 h_g=+1.000000e+000 H_g=101377008 u_a=+4.750406e-001 u_g=+2.500000e-001 W_a=45342736 goalΔ=+4.060199e-001 actualΔ=+1.273667e-001 u_a/u_g=+1.900162e+000
gc 182 @97.977s 9%: 0.14+77+0.27 ms clock, 0.14+17/26/16+0.27 ms cpu, 77->83->48 MB, 96 MB goal, 1 P
pacer: sweep done at heap size 49MB; allocated 0MB of spans; swept 10679 pages at +3.170603e-004 pages/byte
pacer: assist ratio=+4.576662e+000 (scan 72 MB in 82->97 MB) workers=0+1
pacer: H_m_prev=51376960 h_t=+6.759813e-001 H_T=86106825 h_a=+8.006468e-001 H_a=92511760 h_g=+1.000000e+000 H_g=102753920 u_a=+7.585352e-001 u_g=+2.500000e-001 W_a=34850192 goalΔ=+3.240187e-001 actualΔ=+1.246655e-001 u_a/u_g=+3.034141e+000
gc 183 @98.483s 9%: 0.17+67+0.19 ms clock, 0.17+34/15/0+0.19 ms cpu, 82->88->37 MB, 97 MB goal, 1 P
Higher latency than expected at iteration 983.  Tick was delayed 20.226485ms
pacer: sweep done at heap size 40MB; allocated 2MB of spans; swept 11321 pages at +4.605659e-004 pages/byte
pacer: assist ratio=+4.152185e+000 (scan 54 MB in 62->75 MB) workers=0+1
pacer: H_m_prev=39498560 h_t=+6.488643e-001 H_T=65127765 h_a=+8.817468e-001 H_a=74326288 h_g=+1.000000e+000 H_g=78997120 u_a=+5.787007e-001 u_g=+2.500000e-001 W_a=54293848 goalΔ=+3.511357e-001 actualΔ=+2.328825e-001 u_a/u_g=+2.314803e+000
gc 184 @98.718s 9%: 0.13+98+0.22 ms clock, 0.13+32/27/13+0.22 ms cpu, 62->70->58 MB, 75 MB goal, 1 P
pacer: sweep done at heap size 58MB; allocated 0MB of spans; swept 9099 pages at +2.750932e-004 pages/byte
pacer: assist ratio=+3.089526e+000 (scan 80 MB in 91->117 MB) workers=0+1
pacer: H_m_prev=61497624 h_t=+5.548936e-001 H_T=95622263 h_a=+5.950293e-001 H_a=98090512 h_g=+1.000000e+000 H_g=122995248 u_a=+2.500000e-001 u_g=+2.500000e-001 W_a=50456864 goalΔ=+4.451064e-001 actualΔ=+4.013567e-002 u_a/u_g=+1.000000e+000
gc 185 @99.181s 9%: 0.13+83+0.20 ms clock, 0.13+0/33/44+0.20 ms cpu, 91->93->54 MB, 117 MB goal, 1 P
pacer: sweep done at heap size 59MB; allocated 4MB of spans; swept 12002 pages at +2.839869e-004 pages/byte
pacer: assist ratio=+6.406749e+000 (scan 84 MB in 95->109 MB) workers=0+1
pacer: H_m_prev=57185488 h_t=+7.573790e-001 H_T=100496574 h_a=+8.303365e-001 H_a=104668688 h_g=+1.000000e+000 H_g=114370976 u_a=+6.565708e-001 u_g=+2.500000e-001 W_a=43198424 goalΔ=+2.426210e-001 actualΔ=+7.295756e-002 u_a/u_g=+2.626283e+000
gc 186 @99.604s 9%: 0.12+72+0.19 ms clock, 0.12+29/31/0+0.19 ms cpu, 95->99->46 MB, 109 MB goal, 1 P
Higher latency than expected at iteration 994.  Tick was delayed 35.896994ms
pacer: sweep done at heap size 52MB; allocated 5MB of spans; swept 12805 pages at +3.434658e-004 pages/byte
  0.0% -64.359857ms
  1.0% -41.943823ms
  5.0% -19.403262ms
  50.0% 121.887µs
  95.0% 20.226485ms
  99.0% 40.27582ms
  100.0% 75.602625ms