runtime: low throughput after GC events when the heap size is large #19393
Labels
Milestone
Comments
|
Some questions.
1. Did you modify GOMAXPROCS? If not then I will assume that you have a 48
HW thread machine.
2. Is it a single CPU machine or are we dealing with multiple CPUs in the
same machine? Could we get some more information about the machine being
used?
3. Is there anything else running on the machine at the time that might be
using any of these HW threads?
4. The GC will assume that it has access 25% of the CPU resources. If you
reduce the HW available to 32 HW threads by setting GOMAXPROCS to 32 what
does the throughput look like?
5. How much RAM does this machine have?
6. What does happen when you set GOGC to 10?
I am trying to eliminate whether this is expected GC behaviour and the
server is simply overloaded or whether this is the GC doing something
strange.
…On Fri, Mar 3, 2017 at 9:10 PM, Pavel Paulau ***@***.***> wrote:
What version of Go are you using (go version)?
go1.8 linux/amd64
What operating system and processor architecture are you using (go env)?
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GORACE=""
GOROOT="/opt/go1.8"
GOTOOLDIR="/opt/go1.8/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build895013427=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
What did you do?
We recently upgraded our tools for data import from Go 1.7 to Go 1.8. In
one of the use cases we read a large ZIP archive (33GB) and import its
content (JSON documents) into database.
What did you expect to see?
No negative impact on overall performance after upgrade from Go 1.7 to Go
1.8.
What did you see instead?
Even before upgrade we experienced long pauses during GC. The rate of
insert operations looked like this:
Throughput ^
│ ───┐ ┌──────────┐ ┌──────────┐ ┌──────
│ │ │ │ │ │ │
│ │ │ │ │ │ │
│ │ │ │ │ │ │
│ │ │ │ │ │ │
│ │ │ │ │ │ │
│ │ │ │ │ │ │
│ └─────┘ └─────┘ └─────┘
│ gc gc gc
─────────────────────────────────────────────────────> Time
[image: ops_1 7]
<https://cloud.githubusercontent.com/assets/833001/23574908/836fd92a-0039-11e7-8b48-f990673f74fc.png>
gctrace=1 output:
gc 1 @0.082s 1%: 0.10+164+0.34 ms clock, 0.20+164/0.38/164+0.68 ms cpu, 458->458->458 MB, 459 MB goal, 48 P
gc 2 @0.250s 1%: 0.078+209+0.12 ms clock, 0.54+0.036/211/0.85+0.84 ms cpu, 459->459->459 MB, 916 MB goal, 48 P
gc 3 @0.807s 2%: 0.62+238+0.36 ms clock, 6.8+0/864/437+4.0 ms cpu, 688->726->693 MB, 919 MB goal, 48 P
gc 4 @1.669s 3%: 0.064+243+0.35 ms clock, 2.0+243/1323/626+11 ms cpu, 1183->1183->1109 MB, 1386 MB goal, 48 P
gc 5 @3.084s 2%: 0.094+373+0.41 ms clock, 3.0+0/1257/398+13 ms cpu, 2056->2069->1935 MB, 2218 MB goal, 48 P
gc 6 @5.733s 3%: 0.20+741+0.36 ms clock, 6.5+741/7094/13469+11 ms cpu, 3717->3718->3473 MB, 3870 MB goal, 48 P
gc 7 @10.699s 3%: 0.18+2227+0.40 ms clock, 6.0+891/7184/7489+13 ms cpu, 6772->6773->6323 MB, 6946 MB goal, 48 P
gc 8 @20.610s 2%: 0.15+6227+1.1 ms clock, 4.9+1506/10733/2669+35 ms cpu, 12330->12332->11513 MB, 12646 MB goal, 48 P
gc 9 @47.029s 2%: 0.32+3818+0.45 ms clock, 10+0.48/29625/18879+14 ms cpu, 22451->22478->20360 MB, 23026 MB goal, 48 P
gc 10 @92.357s 2%: 1.8+5410+3.0 ms clock, 26+5553/64292/156786+43 ms cpu, 39702->39703->20341 MB, 40720 MB goal, 48 P
gc 11 @117.508s 3%: 0.52+4498+1.1 ms clock, 12+4981/53815/153530+28 ms cpu, 39666->39675->20352 MB, 40683 MB goal, 48 P
gc 12 @141.335s 4%: 0.34+4694+1.3 ms clock, 9.2+91099/56035/55798+36 ms cpu, 39687->40261->20920 MB, 40705 MB goal, 48 P
scvg0: inuse: 34180, idle: 6630, sys: 40811, released: 0, consumed: 40811 (MB)
gc 13 @163.135s 6%: 1.8+6147+1.6 ms clock, 59+123746/72613/53733+54 ms cpu, 40545->41271->21063 MB, 41841 MB goal, 48 P
gc 14 @186.391s 7%: 3.8+5586+1.3 ms clock, 104+103560/66352/60417+37 ms cpu, 40496->41446->21279 MB, 42127 MB goal, 48 P
gc 15 @205.964s 7%: 1.4+6081+1.4 ms clock, 24+5794/71869/182871+23 ms cpu, 40513->40887->20708 MB, 42558 MB goal, 48 P
gc 16 @224.782s 7%: 1.9+5342+1.4 ms clock, 51+5300/63566/158060+38 ms cpu, 40226->40381->20495 MB, 41417 MB goal, 48 P
gc 17 @243.849s 8%: 2.2+6021+1.4 ms clock, 61+126438/71451/55718+40 ms cpu, 39965->40541->20914 MB, 40990 MB goal, 48 P
gc 18 @264.107s 8%: 1.7+6260+1.3 ms clock, 56+12836/73910/177573+44 ms cpu, 40497->40832->20671 MB, 41828 MB goal, 48 P
gc 19 @284.692s 9%: 1.6+4422+1.4 ms clock, 43+91007/52899/52201+40 ms cpu, 40309->40885->20918 MB, 41342 MB goal, 48 P
scvg1: inuse: 35822, idle: 6169, sys: 41991, released: 0, consumed: 41991 (MB)
gc 20 @303.352s 9%: 1.7+5947+1.5 ms clock, 51+8195/70575/180327+45 ms cpu, 40521->40844->20663 MB, 41836 MB goal, 48 P
gc 21 @322.032s 9%: 1.4+5867+1.6 ms clock, 27+5939/69373/176578+31 ms cpu, 40293->40699->20741 MB, 41326 MB goal, 48 P
gc 22 @340.860s 9%: 1.4+4969+1.1 ms clock, 27+5037/59340/168148+21 ms cpu, 40445->40459->20359 MB, 41482 MB goal, 48 P
gc 23 @358.277s 8%: 1.4+4512+1.0 ms clock, 47+7928/53932/150443+35 ms cpu, 39701->39722->20369 MB, 40718 MB goal, 48 P
gc 24 @375.043s 9%: 1.6+4365+1.2 ms clock, 35+87815/51731/50729+25 ms cpu, 39721->40310->20926 MB, 40739 MB goal, 48 P
gc 25 @391.945s 9%: 1.4+4834+1.0 ms clock, 44+7305/57666/142869+34 ms cpu, 40520->40541->20371 MB, 41853 MB goal, 48 P
gc 26 @409.145s 9%: 1.7+4657+1.2 ms clock, 29+5189/55527/141509+21 ms cpu, 39724->39729->20348 MB, 40743 MB goal, 48 P
gc 27 @426.175s 9%: 2.0+4619+1.0 ms clock, 54+12398/55275/149757+28 ms cpu, 39680->39718->20395 MB, 40697 MB goal, 48 P
gc 28 @443.167s 9%: 1.7+6128+1.0 ms clock, 56+125765/72669/64172+33 ms cpu, 39770->40387->20949 MB, 40790 MB goal, 48 P
scvg2: inuse: 40931, idle: 1059, sys: 41991, released: 0, consumed: 41991 (MB)
gc 29 @461.814s 10%: 1.5+5837+1.1 ms clock, 31+116942/69358/58310+22 ms cpu, 40516->41295->21107 MB, 41898 MB goal, 48 P
gc 30 @480.092s 10%: 1.0+4610+1.5 ms clock, 25+87733/55006/51349+37 ms cpu, 40471->41453->21310 MB, 42215 MB goal, 48 P
...
This is how throughput looks after upgrade to Go 1.8:
Throughput ^
│ ───┐ ─┐ ─┐ ─┐
│ │ ╱ │ ╱ │ ╱ │
│ │ ╱ │ ╱ │ ╱ │
│ │ ╱ │ ╱ │ ╱ │
│ │ ╱ │ ╱ │ ╱ │
│ │ ╱ │ ╱ │ ╱ │ ╱
│ │ ╱ │ ╱ │ ╱ │ ╱
│ │╱ │╱ │╱ │╱
│ gc gc gc gc
─────────────────────────────────────────────────────> Time
[image: ops_1 8]
<https://cloud.githubusercontent.com/assets/833001/23574917/923b4796-0039-11e7-9f52-4e5990900cb6.png>
The corresponding gctrace=1 output:
gc 1 @0.081s 4%: 0.066+28+0.19 ms clock, 0.20+20/225/190+0.57 ms cpu, 458->459->458 MB, 459 MB goal, 48 P
gc 2 @0.113s 6%: 0.018+19+0.18 ms clock, 0.60+0.36/188/291+5.7 ms cpu, 459->460->460 MB, 917 MB goal, 48 P
gc 3 @0.442s 4%: 0.020+44+0.15 ms clock, 0.66+0.54/500/408+5.0 ms cpu, 689->700->667 MB, 921 MB goal, 48 P
gc 4 @1.095s 3%: 0.017+81+0.18 ms clock, 0.54+0.95/972/605+5.9 ms cpu, 1159->1176->1105 MB, 1335 MB goal, 48 P
gc 5 @2.345s 3%: 0.039+171+0.14 ms clock, 1.2+2.1/2024/4162+4.6 ms cpu, 2051->2066->1930 MB, 2211 MB goal, 48 P
gc 6 @4.818s 3%: 0.035+430+0.10 ms clock, 1.1+10/5155/14761+3.3 ms cpu, 3709->3761->3516 MB, 3861 MB goal, 48 P
gc 7 @9.317s 2%: 0.017+335+0.11 ms clock, 0.54+4.3/4009/11489+3.5 ms cpu, 6846->6886->6424 MB, 7032 MB goal, 48 P
gc 8 @16.969s 2%: 0.029+1035+0.14 ms clock, 0.95+15/12397/35702+4.7 ms cpu, 12527->12631->11793 MB, 12849 MB goal, 48 P
gc 9 @42.287s 2%: 0.090+1417+0.17 ms clock, 2.8+41/16813/47691+5.4 ms cpu, 22997->23042->20377 MB, 23586 MB goal, 48 P
gc 10 @74.810s 1%: 0.18+1772+1.0 ms clock, 5.8+2429/21242/41207+32 ms cpu, 39735->40353->20953 MB, 40754 MB goal, 48 P
gc 11 @103.522s 1%: 0.43+1827+0.34 ms clock, 10+6079/21912/39221+8.6 ms cpu, 40859->41530->21007 MB, 41906 MB goal, 48 P
gc 12 @142.775s 1%: 0.55+1584+0.42 ms clock, 13+11725/18986/27677+10 ms cpu, 40964->41637->21008 MB, 42014 MB goal, 48 P
scvg0: inuse: 28958, idle: 13217, sys: 42176, released: 0, consumed: 42176 (MB)
gc 13 @189.143s 1%: 0.48+1283+0.38 ms clock, 12+9164/15402/20974+9.6 ms cpu, 40946->41637->21023 MB, 42016 MB goal, 48 P
gc 14 @240.052s 1%: 2.6+1327+0.32 ms clock, 66+8041/15875/21378+8.1 ms cpu, 40961->41663->21033 MB, 42047 MB goal, 48 P
gc 15 @293.330s 1%: 2.2+1339+0.51 ms clock, 57+10027/15979/20900+13 ms cpu, 40995->41687->21021 MB, 42067 MB goal, 48 P
scvg1: inuse: 28672, idle: 13555, sys: 42228, released: 0, consumed: 42228 (MB)
gc 16 @346.514s 1%: 1.7+1335+0.57 ms clock, 24+9041/16011/20929+8.0 ms cpu, 40946->41655->21038 MB, 42042 MB goal, 48 P
gc 17 @403.872s 1%: 2.0+1354+0.45 ms clock, 54+11019/16254/20220+12 ms cpu, 40973->41689->21050 MB, 42077 MB goal, 48 P
scvg2: inuse: 35781, idle: 6449, sys: 42231, released: 0, consumed: 42231 (MB)
gc 18 @466.799s 1%: 3.8+1382+0.36 ms clock, 105+10880/16582/20816+9.7 ms cpu, 40948->41694->21081 MB, 42100 MB goal, 48 P
...
Clearly, Go 1.8 minimizes GC pauses and the total time spent in GC.
Unfortunately, the average throughput dropped by 60-70% due to slowdowns
after GC events.
Although it's possible to mitigate this issue by setting GOGC to 10 or 20,
I still wonder why Go 1.8 introduces such a weird behavior.
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
<#19393>, or mute the thread
<https://github.com/notifications/unsubscribe-auth/AA7Wn3Xgz7ZxQslrhIGxO6sihH75sVdsks5riMf_gaJpZM4MS8AZ>
.
|
|
Here are the answers.
|
|
Thanks, this rules out issues like co-tenancy and CPU availability.
Have you looked at the pprof graphs. The GC sweeps the heap during
allocation between GCs and if that is the cause of the problem then the
pprof graphs should make it clear. Comparing pprof graphs might also show
which routine is responsible for the speedup when you move to GOGC=10 or
when you reduce GOMAXPROCS.
…On Mon, Mar 6, 2017 at 12:55 PM, Pavel Paulau ***@***.***> wrote:
Here are the answers.
1.
I didn't modify GOMAXPROCS.
2.
I am using a bare metal machine with 2 hyper-threaded Intel E5-2680 v3
CPUs.
# uname -a
Linux 172-23-100-213 4.4.0-57-generic #78-Ubuntu SMP Fri Dec 9 23:50:32 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
1.
There is nothing else running on this machine. The data is being
transferred to the remote database.
2.
I ran a few experiments with the number of client threads and
GOMAXPROCS last week. I found out that reducing GOMAXPROCS improves the
throughput. I will share the details later.
3.
128GB.
4.
Throughput with GOGC=10:
[image: ops_1 8_gogc10]
<https://cloud.githubusercontent.com/assets/833001/23622108/387fd152-0252-11e7-8d61-8238e39378bd.png>
gc 1 @0.002s 0%: 0.12+0.48+0.10 ms clock, 0.48+0.14/0.15/0.40+0.42 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 2 @0.003s 1%: 0.064+0.21+0.12 ms clock, 0.51+0.11/0.26/0.22+1.0 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 3 @0.004s 3%: 0.49+0.12+0.13 ms clock, 4.9+0/0.25/1.1+1.3 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 4 @0.005s 4%: 0.075+0.36+0.30 ms clock, 0.82+0.044/0.30/0.29+3.4 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 5 @0.006s 5%: 0.055+0.35+0.27 ms clock, 0.72+0.072/0.77/0.35+3.5 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 6 @0.007s 5%: 0.078+0.46+0.16 ms clock, 1.2+0.069/0.77/0.29+2.6 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 7 @0.008s 6%: 0.071+0.38+0.31 ms clock, 1.2+0.085/0.98/0.46+5.3 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 8 @0.009s 7%: 0.083+0.37+0.13 ms clock, 1.5+0.068/1.3/0.38+2.4 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 9 @0.010s 7%: 0.11+0.35+0.14 ms clock, 2.3+0.028/1.4/0.43+2.9 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 10 @0.011s 10%: 0.52+0.090+0.15 ms clock, 12+0/1.4/0.50+3.5 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 11 @0.012s 10%: 0.077+0.34+0.14 ms clock, 1.9+0.056/1.1/0.52+3.5 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 12 @0.013s 11%: 0.093+0.44+0.29 ms clock, 2.5+0.083/1.7/0.29+7.8 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 13 @0.014s 11%: 0.071+0.46+0.15 ms clock, 1.4+0.026/1.4/0.45+3.2 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 14 @0.015s 11%: 0.054+0.49+0.12 ms clock, 1.7+0.14/0.80/0.47+4.0 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 15 @0.016s 11%: 0.019+0.41+0.15 ms clock, 0.60+0.12/1.5/0.53+4.7 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 16 @0.019s 10%: 0.021+0.50+0.20 ms clock, 0.69+0.066/1.5/0.17+6.6 ms cpu, 0->0->0 MB, 1 MB goal, 48 P
gc 17 @0.094s 6%: 0.017+30+0.14 ms clock, 0.55+24/243/136+4.6 ms cpu, 458->459->459 MB, 459 MB goal, 48 P
gc 18 @0.125s 9%: 0.11+25+0.22 ms clock, 2.4+0.007/294/110+4.9 ms cpu, 459->464->463 MB, 504 MB goal, 48 P
gc 19 @0.201s 8%: 0.021+23+0.17 ms clock, 0.70+0.18/269/130+5.5 ms cpu, 484->488->484 MB, 510 MB goal, 48 P
gc 20 @0.299s 8%: 0.027+29+0.18 ms clock, 0.87+0.80/307/186+5.8 ms cpu, 517->521->516 MB, 532 MB goal, 48 P
gc 21 @0.406s 7%: 0.016+31+0.20 ms clock, 0.53+0.74/360/250+6.4 ms cpu, 557->562->555 MB, 567 MB goal, 48 P
gc 22 @0.539s 7%: 0.020+46+0.21 ms clock, 0.66+0.80/409/252+6.7 ms cpu, 603->612->605 MB, 611 MB goal, 48 P
gc 23 @0.692s 7%: 0.020+35+0.26 ms clock, 0.65+0.99/403/353+8.5 ms cpu, 655->661->652 MB, 665 MB goal, 48 P
gc 24 @0.806s 7%: 0.016+30+0.18 ms clock, 0.53+0.88/352/586+5.9 ms cpu, 709->712->703 MB, 717 MB goal, 48 P
gc 25 @0.965s 6%: 0.019+36+0.20 ms clock, 0.61+1.0/407/655+6.6 ms cpu, 768->773->763 MB, 774 MB goal, 48 P
gc 26 @1.135s 6%: 0.020+41+0.17 ms clock, 0.64+6.0/457/866+5.7 ms cpu, 834->840->829 MB, 840 MB goal, 48 P
gc 27 @1.316s 6%: 0.017+43+0.23 ms clock, 0.55+1.0/485/934+7.5 ms cpu, 905->911->899 MB, 912 MB goal, 48 P
gc 28 @1.511s 6%: 0.015+45+0.18 ms clock, 0.49+2.5/531/921+5.8 ms cpu, 982->989->976 MB, 989 MB goal, 48 P
gc 29 @1.719s 6%: 0.018+50+0.20 ms clock, 0.58+1.0/594/939+6.4 ms cpu, 1067->1072->1059 MB, 1074 MB goal, 48 P
gc 30 @1.940s 6%: 0.022+61+0.20 ms clock, 0.72+7.9/721/942+6.4 ms cpu, 1158->1163->1148 MB, 1164 MB goal, 48 P
gc 31 @2.175s 6%: 0.015+59+0.22 ms clock, 0.50+16/694/1161+7.0 ms cpu, 1256->1263->1247 MB, 1263 MB goal, 48 P
gc 32 @2.438s 6%: 0.015+82+0.16 ms clock, 0.51+24/984/1111+5.2 ms cpu, 1364->1372->1354 MB, 1372 MB goal, 48 P
gc 33 @2.742s 6%: 0.016+94+0.19 ms clock, 0.53+13/1105/1299+6.3 ms cpu, 1482->1488->1469 MB, 1490 MB goal, 48 P
gc 34 @3.068s 6%: 0.016+88+0.15 ms clock, 0.53+17/1049/1499+5.0 ms cpu, 1608->1616->1596 MB, 1616 MB goal, 48 P
gc 35 @3.386s 6%: 0.021+97+0.13 ms clock, 0.70+3.4/1131/2224+4.4 ms cpu, 1746->1755->1732 MB, 1755 MB goal, 48 P
gc 36 @3.776s 6%: 0.018+90+0.19 ms clock, 0.58+52/1075/1948+6.2 ms cpu, 1896->1906->1881 MB, 1906 MB goal, 48 P
gc 37 @4.136s 7%: 0.022+190+0.16 ms clock, 0.71+25/2282/4724+5.1 ms cpu, 2059->2067->2042 MB, 2069 MB goal, 48 P
gc 38 @4.685s 7%: 0.018+172+0.18 ms clock, 0.59+104/2051/4740+5.9 ms cpu, 2236->2245->2217 MB, 2246 MB goal, 48 P
gc 39 @5.170s 7%: 0.018+162+0.13 ms clock, 0.60+68/1945/5017+4.2 ms cpu, 2428->2438->2408 MB, 2439 MB goal, 48 P
gc 40 @5.683s 7%: 0.023+186+0.16 ms clock, 0.73+104/2231/5644+5.1 ms cpu, 2637->2649->2616 MB, 2649 MB goal, 48 P
gc 41 @6.309s 7%: 0.066+135+0.15 ms clock, 2.1+8.3/1559/3919+4.8 ms cpu, 2864->2876->2840 MB, 2878 MB goal, 48 P
gc 42 @6.926s 7%: 0.015+141+0.18 ms clock, 0.49+47/1686/4252+6.0 ms cpu, 3110->3124->3086 MB, 3124 MB goal, 48 P
gc 43 @7.610s 7%: 0.021+193+0.12 ms clock, 0.67+95/2312/5833+4.0 ms cpu, 3379->3394->3352 MB, 3394 MB goal, 48 P
gc 44 @8.370s 7%: 0.037+160+0.16 ms clock, 1.1+3.9/1912/4467+5.2 ms cpu, 3670->3687->3642 MB, 3688 MB goal, 48 P
gc 45 @9.054s 6%: 0.019+181+0.14 ms clock, 0.61+20/2112/5799+4.6 ms cpu, 3987->4001->3952 MB, 4006 MB goal, 48 P
gc 46 @9.785s 6%: 0.020+205+0.11 ms clock, 0.64+43/2459/6036+3.6 ms cpu, 4327->4347->4294 MB, 4347 MB goal, 48 P
gc 47 @10.754s 6%: 0.029+217+0.11 ms clock, 0.93+80/2599/5747+3.7 ms cpu, 4701->4723->4665 MB, 4723 MB goal, 48 P
gc 48 @11.683s 6%: 0.018+224+0.13 ms clock, 0.59+5.7/2627/6522+4.1 ms cpu, 5107->5123->5060 MB, 5131 MB goal, 48 P
gc 49 @12.776s 6%: 0.017+249+0.11 ms clock, 0.56+49/2987/8065+3.5 ms cpu, 5540->5565->5497 MB, 5566 MB goal, 48 P
gc 50 @13.872s 6%: 0.017+355+0.11 ms clock, 0.55+114/4232/11618+3.8 ms cpu, 6019->6043->5968 MB, 6046 MB goal, 48 P
gc 51 @15.121s 6%: 0.018+341+0.12 ms clock, 0.59+9.1/4082/11237+4.0 ms cpu, 6535->6561->6480 MB, 6565 MB goal, 48 P
gc 52 @16.556s 6%: 0.016+357+0.14 ms clock, 0.51+12/4240/11389+4.6 ms cpu, 7095->7120->7032 MB, 7128 MB goal, 48 P
gc 53 @18.105s 6%: 0.027+432+0.12 ms clock, 0.87+103/5118/13958+4.0 ms cpu, 7701->7732->7637 MB, 7736 MB goal, 48 P
gc 54 @19.857s 6%: 0.023+400+0.11 ms clock, 0.75+8.7/4775/12978+3.5 ms cpu, 8363->8397->8293 MB, 8401 MB goal, 48 P
gc 55 @21.731s 6%: 0.021+499+0.14 ms clock, 0.69+9.1/5947/16610+4.5 ms cpu, 9081->9113->9001 MB, 9122 MB goal, 48 P
gc 56 @23.585s 6%: 0.028+491+0.12 ms clock, 0.90+121/5881/15095+4.0 ms cpu, 9856->9900->9778 MB, 9901 MB goal, 48 P
gc 57 @25.643s 6%: 0.018+521+0.12 ms clock, 0.58+31/6243/17397+3.8 ms cpu, 10707->10755->10622 MB, 10756 MB goal, 48 P
gc 58 @27.937s 6%: 0.022+662+0.10 ms clock, 0.72+143/7940/22109+3.4 ms cpu, 11631->11677->11533 MB, 11684 MB goal, 48 P
gc 59 @30.359s 6%: 0.017+568+0.15 ms clock, 0.57+9.6/6781/19217+4.9 ms cpu, 12628->12684->12528 MB, 12686 MB goal, 48 P
gc 60 @33.045s 6%: 0.018+634+0.11 ms clock, 0.59+127/7552/20875+3.5 ms cpu, 13718->13781->13610 MB, 13781 MB goal, 48 P
gc 61 @35.995s 6%: 0.027+605+0.11 ms clock, 0.89+46/7013/19962+3.8 ms cpu, 14903->14967->14781 MB, 14971 MB goal, 48 P
gc 62 @38.909s 6%: 0.018+634+0.11 ms clock, 0.58+23/7580/21045+3.7 ms cpu, 16186->16241->16040 MB, 16260 MB goal, 48 P
gc 63 @42.116s 6%: 0.016+688+0.13 ms clock, 0.53+21/8193/23386+4.1 ms cpu, 17564->17632->17416 MB, 17644 MB goal, 48 P
gc 64 @45.570s 6%: 0.032+1030+0.11 ms clock, 1.0+310/12345/35017+3.7 ms cpu, 19071->19157->18930 MB, 19158 MB goal, 48 P
gc 65 @52.406s 6%: 0.025+1359+0.11 ms clock, 0.82+21/16203/46297+3.7 ms cpu, 20727->20758->20363 MB, 20823 MB goal, 48 P
gc 66 @68.770s 5%: 0.036+1128+0.16 ms clock, 1.1+46/13267/36872+5.1 ms cpu, 22297->22339->20374 MB, 22399 MB goal, 48 P
gc 67 @80.193s 5%: 0.21+1186+0.29 ms clock, 2.1+25639/14226/13833+2.9 ms cpu, 22310->22410->20436 MB, 22412 MB goal, 48 P
gc 68 @83.302s 6%: 0.21+1017+0.28 ms clock, 2.7+22494/12204/9573+3.7 ms cpu, 22288->22471->20518 MB, 22480 MB goal, 48 P
gc 69 @86.928s 6%: 0.92+1131+0.30 ms clock, 22+16357/13559/16206+7.2 ms cpu, 22212->22554->20675 MB, 22569 MB goal, 48 P
gc 70 @90.292s 6%: 0.30+1219+0.28 ms clock, 4.9+12525/14615/17182+4.5 ms cpu, 22182->22721->20870 MB, 22743 MB goal, 48 P
gc 71 @93.197s 7%: 0.15+1374+0.50 ms clock, 4.8+11370/16370/19463+16 ms cpu, 22170->22926->21094 MB, 22957 MB goal, 48 P
gc 72 @96.205s 7%: 0.57+1450+0.28 ms clock, 18+1210/17393/21098+9.2 ms cpu, 22160->23111->21278 MB, 23204 MB goal, 48 P
gc 73 @99.239s 7%: 0.37+1304+0.41 ms clock, 12+2572/15573/21684+13 ms cpu, 22367->23284->21242 MB, 23406 MB goal, 48 P
gc 74 @101.962s 7%: 0.39+1321+0.38 ms clock, 10+4679/15807/19327+10 ms cpu, 22314->23320->21330 MB, 23366 MB goal, 48 P
gc 75 @104.797s 7%: 0.31+1417+0.85 ms clock, 10+2955/16963/19122+27 ms cpu, 22281->23313->21358 MB, 23463 MB goal, 48 P
gc 76 @107.682s 8%: 0.70+1358+0.44 ms clock, 18+2476/16241/15810+11 ms cpu, 22296->23391->21429 MB, 23494 MB goal, 48 P
gc 77 @110.549s 8%: 0.31+1373+0.42 ms clock, 8.2+3122/16457/16268+11 ms cpu, 22338->23493->21482 MB, 23572 MB goal, 48 P
gc 78 @113.373s 8%: 0.99+1377+0.38 ms clock, 25+2437/16481/16771+9.9 ms cpu, 22323->23559->21558 MB, 23630 MB goal, 48 P
gc 79 @116.175s 8%: 0.31+1443+0.64 ms clock, 8.1+1406/17280/14765+16 ms cpu, 22347->23631->21605 MB, 23714 MB goal, 48 P
gc 80 @119.097s 8%: 0.69+1442+0.41 ms clock, 17+1105/17290/14228+10 ms cpu, 22386->23685->21624 MB, 23766 MB goal, 48 P
gc 81 @122.066s 8%: 0.33+1420+0.37 ms clock, 8.8+1322/16999/15103+9.7 ms cpu, 22404->23724->21645 MB, 23786 MB goal, 48 P
gc 82 @124.987s 8%: 0.15+1414+0.42 ms clock, 4.9+1457/16811/14419+13 ms cpu, 22406->23727->21643 MB, 23810 MB goal, 48 P
gc 83 @127.793s 8%: 0.17+1471+3.5 ms clock, 5.7+1008/17603/14763+112 ms cpu, 22388->23719->21653 MB, 23807 MB goal, 48 P
gc 84 @130.739s 9%: 0.61+1471+0.34 ms clock, 16+1237/17650/14058+8.8 ms cpu, 22405->23758->21675 MB, 23819 MB goal, 48 P
gc 85 @133.730s 9%: 0.36+1414+0.34 ms clock, 9.4+1781/16951/15601+9.0 ms cpu, 22410->23786->21700 MB, 23842 MB goal, 48 P
gc 86 @136.531s 9%: 0.39+1445+0.40 ms clock, 10+700/17310/13588+10 ms cpu, 22392->23799->21725 MB, 23870 MB goal, 48 P
gc 87 @139.372s 9%: 0.28+1485+0.38 ms clock, 6.2+351/17799/13391+8.4 ms cpu, 22425->23799->21690 MB, 23897 MB goal, 48 P
gc 88 @142.414s 9%: 0.43+1485+0.36 ms clock, 13+865/17635/13980+11 ms cpu, 22425->23802->21695 MB, 23859 MB goal, 48 P
gc 89 @145.326s 9%: 0.40+1437+0.30 ms clock, 10+1091/17086/13184+7.8 ms cpu, 22426->23800->21694 MB, 23865 MB goal, 48 P
gc 90 @148.237s 9%: 0.30+1423+0.30 ms clock, 7.7+1489/17057/14249+7.5 ms cpu, 22413->23798->21707 MB, 23863 MB goal, 48 P
scvg0: inuse: 24134, idle: 5, sys: 24139, released: 0, consumed: 24139 (MB)
gc 91 @151.133s 9%: 0.88+1520+0.36 ms clock, 23+846/18193/12921+9.5 ms cpu, 22399->23796->21718 MB, 23878 MB goal, 48 P
gc 92 @154.284s 9%: 0.64+1466+0.43 ms clock, 16+678/17544/14022+11 ms cpu, 22419->23816->21715 MB, 23890 MB goal, 48 P
gc 93 @157.114s 9%: 0.32+1485+0.31 ms clock, 8.4+3126/17818/11359+8.0 ms cpu, 22426->23820->21717 MB, 23886 MB goal, 48 P
gc 94 @160.124s 9%: 0.38+1496+0.42 ms clock, 9.9+823/17925/12972+11 ms cpu, 22339->23746->21726 MB, 23888 MB goal, 48 P
gc 95 @163.036s 9%: 0.67+1504+0.38 ms clock, 21+288/17941/12772+12 ms cpu, 22388->23815->21744 MB, 23899 MB goal, 48 P
gc 96 @166.100s 9%: 0.59+1491+0.36 ms clock, 15+716/17838/11803+9.4 ms cpu, 22437->23853->21736 MB, 23919 MB goal, 48 P
gc 97 @168.942s 10%: 0.19+1441+0.48 ms clock, 6.2+830/17129/14548+15 ms cpu, 22433->23814->21700 MB, 23910 MB goal, 48 P
gc 98 @171.852s 10%: 0.19+1457+0.65 ms clock, 6.2+1330/17468/14005+20 ms cpu, 22410->23795->21704 MB, 23870 MB goal, 48 P
gc 99 @174.768s 10%: 1.1+1462+0.36 ms clock, 30+1378/17499/13514+9.5 ms cpu, 22400->23719->21644 MB, 23875 MB goal, 48 P
gc 100 @177.778s 10%: 0.43+1435+0.41 ms clock, 11+964/17180/13351+10 ms cpu, 22364->23738->21696 MB, 23809 MB goal, 48 P
gc 101 @180.549s 10%: 0.35+1441+0.40 ms clock, 9.1+392/17221/12455+10 ms cpu, 22415->23788->21691 MB, 23866 MB goal, 48 P
gc 102 @183.415s 10%: 0.17+1441+0.42 ms clock, 5.4+940/17156/13726+13 ms cpu, 22433->23795->21682 MB, 23860 MB goal, 48 P
gc 103 @186.331s 10%: 0.79+1457+0.41 ms clock, 20+513/17479/12600+10 ms cpu, 22419->23753->21653 MB, 23850 MB goal, 48 P
gc 104 @189.404s 10%: 0.61+1444+0.30 ms clock, 15+2047/17329/12572+8.0 ms cpu, 22418->23764->21669 MB, 23819 MB goal, 48 P
gc 105 @192.214s 10%: 0.33+1452+0.30 ms clock, 8.6+880/17421/13403+7.9 ms cpu, 22382->23766->21707 MB, 23835 MB goal, 48 P
gc 106 @195.184s 10%: 0.37+1488+0.53 ms clock, 9.7+547/17840/13309+13 ms cpu, 22422->23806->21704 MB, 23878 MB goal, 48 P
gc 107 @198.096s 10%: 0.60+1467+0.40 ms clock, 15+759/17572/13157+10 ms cpu, 22433->23780->21669 MB, 23875 MB goal, 48 P
gc 108 @201.119s 10%: 0.36+1431+0.34 ms clock, 9.6+911/17150/15778+9.0 ms cpu, 22415->23775->21679 MB, 23836 MB goal, 48 P
gc 109 @203.914s 10%: 0.34+1429+0.42 ms clock, 8.9+1121/17104/14204+11 ms cpu, 22420->23786->21685 MB, 23847 MB goal, 48 P
gc 110 @206.820s 10%: 0.44+1471+0.36 ms clock, 11+825/17634/12291+9.5 ms cpu, 22412->23766->21679 MB, 23854 MB goal, 48 P
gc 111 @209.642s 10%: 0.57+1472+0.38 ms clock, 15+492/17606/13385+9.9 ms cpu, 22418->23755->21653 MB, 23846 MB goal, 48 P
gc 112 @212.666s 10%: 0.18+1405+0.33 ms clock, 6.0+1506/16843/15875+10 ms cpu, 22419->23755->21657 MB, 23819 MB goal, 48 P
gc 113 @215.416s 10%: 0.37+1436+0.32 ms clock, 9.6+1398/17217/12314+8.3 ms cpu, 22395->23764->21694 MB, 23822 MB goal, 48 P
gc 114 @218.307s 10%: 0.29+1433+0.35 ms clock, 7.2+531/17087/15868+8.8 ms cpu, 22407->23670->21583 MB, 23863 MB goal, 48 P
gc 115 @221.164s 10%: 0.48+1439+0.38 ms clock, 15+1781/17243/13953+12 ms cpu, 22369->23672->21623 MB, 23741 MB goal, 48 P
gc 116 @224.085s 10%: 0.25+1421+0.36 ms clock, 8.1+1546/17006/13605+11 ms cpu, 22378->23727->21668 MB, 23785 MB goal, 48 P
gc 117 @226.838s 10%: 0.28+1426+0.39 ms clock, 7.1+719/17088/15151+9.8 ms cpu, 22392->23748->21676 MB, 23835 MB goal, 48 P
gc 118 @229.776s 10%: 0.17+1471+0.45 ms clock, 5.6+1076/17487/14342+14 ms cpu, 22415->23784->21688 MB, 23844 MB goal, 48 P
gc 119 @232.636s 10%: 0.60+1447+0.32 ms clock, 15+407/17369/12792+8.4 ms cpu, 22416->23782->21686 MB, 23857 MB goal, 48 P
gc 120 @235.627s 10%: 0.33+1430+0.41 ms clock, 8.6+1970/17119/13811+10 ms cpu, 22435->23790->21675 MB, 23854 MB goal, 48 P
gc 121 @238.467s 10%: 0.37+1474+0.35 ms clock, 9.3+824/17654/13241+8.9 ms cpu, 22378->23769->21710 MB, 23842 MB goal, 48 P
gc 122 @241.477s 10%: 0.34+1428+0.44 ms clock, 8.9+383/17086/14953+11 ms cpu, 22419->23722->21623 MB, 23881 MB goal, 48 P
gc 123 @244.288s 10%: 0.43+1408+0.35 ms clock, 13+632/16765/14618+11 ms cpu, 22394->23680->21609 MB, 23785 MB goal, 48 P
gc 124 @247.246s 10%: 0.16+1395+0.31 ms clock, 5.3+1464/16719/16192+10 ms cpu, 22408->23708->21620 MB, 23770 MB goal, 48 P
gc 125 @250.045s 11%: 0.34+1431+0.39 ms clock, 8.9+1688/17174/12435+10 ms cpu, 22394->23741->21671 MB, 23782 MB goal, 48 P
gc 126 @252.946s 11%: 0.35+1441+0.43 ms clock, 9.2+755/17261/14827+11 ms cpu, 22401->23703->21621 MB, 23838 MB goal, 48 P
gc 127 @255.794s 11%: 2.7+1450+0.29 ms clock, 86+986/17377/14938+9.3 ms cpu, 22388->23710->21641 MB, 23783 MB goal, 48 P
gc 128 @258.771s 11%: 0.22+1390+0.42 ms clock, 7.1+1299/16602/15870+13 ms cpu, 22408->23724->21636 MB, 23805 MB goal, 48 P
gc 129 @261.625s 11%: 0.34+1401+0.26 ms clock, 8.9+2364/16769/14686+6.9 ms cpu, 22392->23741->21675 MB, 23800 MB goal, 48 P
gc 130 @264.537s 11%: 0.39+1504+0.46 ms clock, 10+703/18009/12669+12 ms cpu, 22366->23762->21718 MB, 23842 MB goal, 48 P
gc 131 @267.471s 11%: 0.44+1509+0.41 ms clock, 14+401/18006/13320+13 ms cpu, 22424->23825->21721 MB, 23890 MB goal, 48 P
gc 132 @270.639s 11%: 0.33+1440+0.34 ms clock, 8.7+1633/17277/14596+9.0 ms cpu, 22444->23830->21704 MB, 23893 MB goal, 48 P
gc 133 @273.462s 11%: 0.19+1442+0.49 ms clock, 6.1+446/17251/14751+15 ms cpu, 22392->23807->21733 MB, 23874 MB goal, 48 P
gc 134 @276.452s 11%: 0.95+1428+0.40 ms clock, 30+176/17105/13688+13 ms cpu, 22438->23760->21642 MB, 23907 MB goal, 48 P
gc 135 @279.300s 11%: 0.51+1451+0.30 ms clock, 13+810/17396/12895+7.9 ms cpu, 22410->23751->21662 MB, 23806 MB goal, 48 P
gc 136 @282.238s 11%: 0.35+1367+0.41 ms clock, 9.1+1273/16379/16225+10 ms cpu, 22427->23673->21571 MB, 23828 MB goal, 48 P
gc 137 @285.029s 11%: 0.40+1410+0.37 ms clock, 10+1735/16904/15110+9.7 ms cpu, 22362->23678->21638 MB, 23728 MB goal, 48 P
gc 138 @287.930s 11%: 0.72+1465+0.44 ms clock, 23+531/17568/14445+14 ms cpu, 22389->23718->21648 MB, 23802 MB goal, 48 P
gc 139 @290.840s 11%: 0.55+1421+0.33 ms clock, 13+1246/17023/12879+8.4 ms cpu, 22422->23746->21649 MB, 23813 MB goal, 48 P
gc 140 @293.744s 11%: 0.29+1409+0.27 ms clock, 9.3+893/16850/15944+8.8 ms cpu, 22407->23754->21665 MB, 23814 MB goal, 48 P
gc 141 @296.577s 11%: 0.16+1429+0.36 ms clock, 5.2+1819/17092/13990+11 ms cpu, 22418->23762->21666 MB, 23832 MB goal, 48 P
scvg1: inuse: 23111, idle: 1078, sys: 24189, released: 0, consumed: 24189 (MB)
gc 142 @299.580s 11%: 0.94+1460+0.40 ms clock, 24+404/17495/13247+10 ms cpu, 22383->23722->21657 MB, 23832 MB goal, 48 P
gc 143 @302.395s 11%: 0.56+1422+0.43 ms clock, 16+1283/17030/12248+12 ms cpu, 22414->23753->21658 MB, 23823 MB goal, 48 P
gc 144 @305.327s 11%: 0.32+1384+0.41 ms clock, 8.5+810/16557/15487+10 ms cpu, 22399->23684->21605 MB, 23824 MB goal, 48 P
gc 145 @308.126s 11%: 0.29+1400+0.37 ms clock, 9.5+1806/16732/15571+12 ms cpu, 22383->23707->21644 MB, 23766 MB goal, 48 P
gc 146 @311.145s 11%: 0.71+1503+0.41 ms clock, 22+522/17963/12419+13 ms cpu, 22381->23751->21692 MB, 23808 MB goal, 48 P
gc 147 @314.033s 11%: 0.44+1425+0.39 ms clock, 11+1024/17043/14759+10 ms cpu, 22440->23791->21672 MB, 23862 MB goal, 48 P
gc 148 @317.012s 11%: 0.39+1399+0.35 ms clock, 12+995/16746/15070+11 ms cpu, 22413->23768->21673 MB, 23839 MB goal, 48 P
gc 149 @319.810s 11%: 0.35+1441+0.48 ms clock, 9.2+1339/17237/14358+12 ms cpu, 22410->23750->21662 MB, 23840 MB goal, 48 P
gc 150 @322.895s 11%: 0.78+1468+0.29 ms clock, 20+1303/17582/13580+7.7 ms cpu, 22392->23753->21685 MB, 23828 MB goal, 48 P
gc 151 @325.743s 11%: 0.40+1475+0.41 ms clock, 10+1089/17657/12172+10 ms cpu, 22403->23796->21718 MB, 23854 MB goal, 48 P
gc 152 @328.657s 11%: 0.26+1441+0.31 ms clock, 8.6+1671/17281/14435+10 ms cpu, 22424->23810->21705 MB, 23890 MB goal, 48 P
gc 153 @331.466s 11%: 0.35+1499+0.57 ms clock, 9.3+1157/17882/14150+14 ms cpu, 22383->23776->21715 MB, 23875 MB goal, 48 P
gc 154 @334.519s 11%: 0.65+1514+0.40 ms clock, 16+584/18154/12144+10 ms cpu, 22399->23810->21732 MB, 23887 MB goal, 48 P
gc 155 @337.450s 11%: 0.44+1453+0.36 ms clock, 11+936/17437/14214+9.4 ms cpu, 22432->23825->21713 MB, 23906 MB goal, 48 P
gc 156 @340.497s 11%: 0.17+1454+0.41 ms clock, 5.7+1289/17296/14143+13 ms cpu, 22415->23817->21718 MB, 23884 MB goal, 48 P
gc 157 @343.339s 11%: 0.32+1413+0.28 ms clock, 8.3+534/16944/14988+7.3 ms cpu, 22403->23667->21586 MB, 23890 MB goal, 48 P
gc 158 @346.403s 11%: 0.58+1437+0.37 ms clock, 15+1199/17193/15249+9.6 ms cpu, 22357->23680->21644 MB, 23745 MB goal, 48 P
gc 159 @349.277s 11%: 0.31+1410+0.58 ms clock, 8.1+2463/16914/15184+15 ms cpu, 22404->23730->21644 MB, 23809 MB goal, 48 P
gc 160 @352.311s 11%: 0.38+1411+0.30 ms clock, 9.9+840/16916/15690+7.9 ms cpu, 22347->23664->21636 MB, 23808 MB goal, 48 P
gc 161 @355.113s 11%: 0.36+1390+0.38 ms clock, 9.5+494/16686/13986+9.9 ms cpu, 22379->23609->21551 MB, 23800 MB goal, 48 P
gc 162 @358.085s 11%: 0.66+1413+0.46 ms clock, 17+1069/16910/15843+12 ms cpu, 22368->23648->21603 MB, 23707 MB goal, 48 P
gc 163 @360.892s 11%: 0.31+1384+0.30 ms clock, 8.0+1785/16570/15049+7.8 ms cpu, 22410->23703->21611 MB, 23763 MB goal, 48 P
gc 164 @363.705s 11%: 0.34+1399+0.29 ms clock, 8.9+1615/16787/15640+7.5 ms cpu, 22379->23727->21671 MB, 23772 MB goal, 48 P
gc 165 @366.465s 11%: 0.34+1466+0.42 ms clock, 9.0+614/17575/13609+11 ms cpu, 22399->23714->21640 MB, 23838 MB goal, 48 P
gc 166 @369.518s 11%: 0.64+1444+0.39 ms clock, 16+786/17310/14806+10 ms cpu, 22405->23738->21652 MB, 23804 MB goal, 48 P
gc 167 @372.382s 11%: 0.32+1424+0.30 ms clock, 8.5+1246/17047/12909+7.9 ms cpu, 22421->23757->21659 MB, 23818 MB goal, 48 P
gc 168 @375.277s 11%: 0.35+1425+0.32 ms clock, 9.1+1838/17058/14244+8.4 ms cpu, 22410->23762->21676 MB, 23825 MB goal, 48 P
gc 169 @378.026s 11%: 4.0+1486+0.39 ms clock, 128+820/17789/13559+12 ms cpu, 22387->23715->21648 MB, 23844 MB goal, 48 P
gc 170 @381.081s 11%: 0.64+1477+0.48 ms clock, 16+2084/17724/11762+12 ms cpu, 22392->23760->21692 MB, 23813 MB goal, 48 P
gc 171 @383.937s 11%: 0.30+1435+0.47 ms clock, 8.0+1379/17209/13034+12 ms cpu, 22383->23767->21710 MB, 23862 MB goal, 48 P
gc 172 @386.864s 11%: 0.30+1469+0.37 ms clock, 7.9+578/17603/13939+9.8 ms cpu, 22393->23787->21713 MB, 23881 MB goal, 48 P
gc 173 @389.726s 11%: 0.40+1481+0.40 ms clock, 10+1022/17730/12346+10 ms cpu, 22420->23777->21679 MB, 23884 MB goal, 48 P
gc 174 @392.830s 11%: 0.56+1468+0.32 ms clock, 17+836/17487/14813+10 ms cpu, 22400->23776->21694 MB, 23847 MB goal, 48 P
gc 175 @395.665s 11%: 0.30+1456+0.31 ms clock, 9.8+2024/17463/11128+10 ms cpu, 22419->23830->21730 MB, 23864 MB goal, 48 P
gc 176 @398.606s 11%: 0.34+1467+0.40 ms clock, 8.8+430/17598/13307+10 ms cpu, 22390->23773->21701 MB, 23903 MB goal, 48 P
gc 177 @401.506s 11%: 1.0+1447+0.37 ms clock, 27+425/17321/14895+9.8 ms cpu, 22409->23719->21630 MB, 23872 MB goal, 48 P
gc 178 @404.610s 11%: 0.72+1440+1.4 ms clock, 23+699/17182/14923+45 ms cpu, 22395->23744->21668 MB, 23793 MB goal, 48 P
gc 179 @407.434s 11%: 0.41+1356+0.38 ms clock, 10+896/16248/14795+9.8 ms cpu, 22432->23658->21551 MB, 23835 MB goal, 48 P
gc 180 @410.250s 11%: 0.16+1394+0.42 ms clock, 5.4+1937/16604/16100+13 ms cpu, 22365->23647->21606 MB, 23706 MB goal, 48 P
gc 181 @413.116s 11%: 0.93+1604+0.33 ms clock, 24+1179/19228/16805+8.5 ms cpu, 22378->23684->21630 MB, 23767 MB goal, 48 P
gc 182 @416.322s 11%: 0.63+1568+0.43 ms clock, 16+1293/18783/17626+11 ms cpu, 22404->23749->21667 MB, 23793 MB goal, 48 P
gc 183 @419.268s 11%: 0.32+1500+0.41 ms clock, 5.8+1751/17941/19310+7.5 ms cpu, 22418->23757->21656 MB, 23834 MB goal, 48 P
gc 184 @422.198s 11%: 0.30+1456+0.31 ms clock, 8.0+1258/17474/13268+8.2 ms cpu, 22381->23786->21726 MB, 23822 MB goal, 48 P
gc 185 @425.075s 11%: 0.45+1449+0.41 ms clock, 14+885/17337/13916+13 ms cpu, 22419->23742->21647 MB, 23898 MB goal, 48 P
gc 186 @427.973s 11%: 0.22+1417+0.44 ms clock, 7.3+986/16952/14349+14 ms cpu, 22383->23722->21663 MB, 23812 MB goal, 48 P
gc 187 @430.725s 11%: 0.22+1375+0.38 ms clock, 7.0+1829/16472/14100+12 ms cpu, 22405->23764->21681 MB, 23829 MB goal, 48 P
gc 188 @433.700s 11%: 0.33+1438+0.37 ms clock, 8.6+688/17234/14878+9.8 ms cpu, 22382->23685->21624 MB, 23849 MB goal, 48 P
gc 189 @436.562s 11%: 0.63+1435+0.34 ms clock, 16+670/17200/13668+9.0 ms cpu, 22379->23716->21659 MB, 23787 MB goal, 48 P
gc 190 @439.632s 11%: 0.33+1402+0.30 ms clock, 8.7+2130/16795/14709+7.8 ms cpu, 22424->23763->21663 MB, 23825 MB goal, 48 P
gc 191 @442.402s 11%: 0.18+1449+0.42 ms clock, 5.7+181/17245/13853+13 ms cpu, 22374->23749->21692 MB, 23829 MB goal, 48 P
gc 192 @445.350s 11%: 0.29+1427+0.32 ms clock, 7.5+684/17128/14522+8.4 ms cpu, 22437->23712->21596 MB, 23861 MB goal, 48 P
gc 193 @448.200s 11%: 0.70+1441+0.31 ms clock, 18+1380/17258/14283+8.1 ms cpu, 22386->23688->21623 MB, 23756 MB goal, 48 P
scvg2: inuse: 24024, idle: 165, sys: 24189, released: 0, consumed: 24189 (MB)
gc 194 @451.136s 11%: 0.24+1419+0.29 ms clock, 7.8+951/16997/14710+9.5 ms cpu, 22397->23728->21649 MB, 23786 MB goal, 48 P
gc 195 @454.002s 11%: 0.32+1405+0.40 ms clock, 8.4+724/16842/13215+10 ms cpu, 22415->23757->21661 MB, 23814 MB goal, 48 P
gc 196 @456.885s 11%: 0.33+1410+0.41 ms clock, 8.6+493/16899/14653+10 ms cpu, 22428->23668->21561 MB, 23828 MB goal, 48 P
gc 197 @459.720s 11%: 0.50+1408+0.38 ms clock, 16+1342/16887/13751+12 ms cpu, 22385->23659->21601 MB, 23717 MB goal, 48 P
gc 198 @462.774s 11%: 0.30+1397+0.33 ms clock, 7.9+2236/16739/15155+8.6 ms cpu, 22405->23700->21613 MB, 23761 MB goal, 48 P
gc 199 @465.579s 12%: 0.39+1423+0.30 ms clock, 10+1342/17070/13936+7.8 ms cpu, 22361->23717->21681 MB, 23774 MB goal, 48 P
gc 200 @468.495s 12%: 0.32+1473+0.42 ms clock, 8.2+897/17648/13982+10 ms cpu, 22406->23762->21678 MB, 23849 MB goal, 48 P
gc 201 @471.332s 12%: 0.67+1489+0.29 ms clock, 17+587/17855/13645+7.7 ms cpu, 22413->23793->21699 MB, 23846 MB goal, 48 P
gc 202 @474.389s 12%: 0.39+1418+0.35 ms clock, 10+1814/16986/14614+9.2 ms cpu, 22438->23792->21676 MB, 23868 MB goal, 48 P
gc 203 @477.183s 12%: 0.31+1433+0.42 ms clock, 8.1+1215/17159/14623+10 ms cpu, 22380->23780->21721 MB, 23843 MB goal, 48 P
gc 204 @480.145s 12%: 0.36+1435+0.44 ms clock, 9.3+855/17206/14428+11 ms cpu, 22409->23683->21599 MB, 23893 MB goal, 48 P
gc 205 @482.986s 12%: 0.55+1464+0.42 ms clock, 14+1113/17515/14649+10 ms cpu, 22356->23718->21684 MB, 23759 MB goal, 48 P
gc 206 @485.977s 12%: 0.35+1424+0.40 ms clock, 8.8+1171/17044/14069+10 ms cpu, 22421->23783->21681 MB, 23852 MB goal, 48 P
gc 207 @488.744s 12%: 0.34+1469+0.37 ms clock, 8.9+1134/17573/12314+9.8 ms cpu, 22406->23810->21726 MB, 23850 MB goal, 48 P
gc 208 @491.718s 12%: 0.25+1398+0.36 ms clock, 8.2+193/16774/14086+11 ms cpu, 22427->23674->21567 MB, 23899 MB goal, 48 P
gc 209 @494.572s 12%: 0.61+1429+0.40 ms clock, 16+1834/17142/12915+10 ms cpu, 22367->23665->21623 MB, 23723 MB goal, 48 P
gc 210 @497.681s 12%: 0.42+1419+0.32 ms clock, 11+1040/17007/13219+8.3 ms cpu, 22385->23727->21661 MB, 23785 MB goal, 48 P
gc 211 @500.482s 12%: 0.40+1422+0.37 ms clock, 10+1814/17052/13481+9.7 ms cpu, 22413->23748->21659 MB, 23827 MB goal, 48 P
gc 212 @503.519s 12%: 0.82+1468+0.36 ms clock, 21+1123/17601/12362+9.6 ms cpu, 22379->23747->21687 MB, 23825 MB goal, 48 P
gc 213 @506.405s 12%: 0.58+1471+0.31 ms clock, 15+907/17617/14360+8.1 ms cpu, 22404->23777->21693 MB, 23856 MB goal, 48 P
gc 214 @509.372s 12%: 0.34+1433+0.34 ms clock, 9.0+1965/17143/14064+8.9 ms cpu, 22414->23797->21709 MB, 23862 MB goal, 48 P
gc 215 @512.160s 12%: 0.36+1439+0.43 ms clock, 9.5+1325/17214/14621+11 ms cpu, 22384->23758->21698 MB, 23880 MB goal, 48 P
gc 216 @515.128s 12%: 0.65+1497+0.44 ms clock, 21+1199/17909/12571+14 ms cpu, 22380->23758->21702 MB, 23867 MB goal, 48 P
gc 217 @518.013s 12%: 0.61+1500+0.42 ms clock, 15+607/17981/13649+11 ms cpu, 22393->23788->21715 MB, 23872 MB goal, 48 P
gc 218 @521.050s 12%: 0.33+1452+0.36 ms clock, 8.2+1376/17406/13688+9.0 ms cpu, 22426->23821->21713 MB, 23887 MB goal, 48 P
gc 219 @523.913s 12%: 0.31+1449+0.43 ms clock, 8.2+875/17390/14373+11 ms cpu, 22401->23722->21643 MB, 23885 MB goal, 48 P
gc 220 @526.952s 12%: 0.76+1472+0.42 ms clock, 16+645/17621/13291+8.9 ms cpu, 22377->23744->21685 MB, 23808 MB goal, 48 P
gc 221 @529.824s 12%: 0.24+1439+0.36 ms clock, 7.8+848/17106/14339+11 ms cpu, 22427->23784->21678 MB, 23853 MB goal, 48 P
gc 222 @532.727s 12%: 0.37+1408+0.42 ms clock, 9.8+1579/16802/16441+11 ms cpu, 22420->23770->21668 MB, 23845 MB goal, 48 P
gc 223 @535.525s 12%: 0.32+1466+0.47 ms clock, 8.3+897/17577/14562+12 ms cpu, 22385->23757->21690 MB, 23835 MB goal, 48 P
gc 224 @538.481s 12%: 0.75+1495+0.32 ms clock, 16+472/17866/12297+7.0 ms cpu, 22412->23792->21698 MB, 23859 MB goal, 48 P
gc 225 @541.418s 12%: 0.35+1458+0.44 ms clock, 9.3+565/17443/12691+11 ms cpu, 22435->23805->21688 MB, 23868 MB goal, 48 P
gc 226 @544.330s 12%: 0.20+1431+0.31 ms clock, 6.4+1159/17106/14216+10 ms cpu, 22434->23800->21688 MB, 23857 MB goal, 48 P
gc 227 @547.185s 12%: 0.32+1460+0.39 ms clock, 8.3+939/17498/13782+10 ms cpu, 22417->23735->21640 MB, 23857 MB goal, 48 P
gc 228 @550.187s 12%: 0.51+1425+0.40 ms clock, 16+1010/17010/16266+12 ms cpu, 22393->23651->21583 MB, 23804 MB goal, 48 P
gc 229 @553.042s 12%: 0.36+1411+0.30 ms clock, 9.4+1305/16922/14867+7.9 ms cpu, 22374->23686->21633 MB, 23742 MB goal, 48 P
gc 230 @555.980s 12%: 0.31+1421+0.45 ms clock, 8.3+2112/17024/15258+11 ms cpu, 22402->23738->21657 MB, 23796 MB goal, 48 P
gc 231 @558.840s 12%: 0.23+1504+0.39 ms clock, 7.4+511/17999/13014+12 ms cpu, 22373->23720->21666 MB, 23822 MB goal, 48 P
gc 232 @561.856s 12%: 0.49+1476+0.39 ms clock, 15+556/17661/14098+12 ms cpu, 22415->23770->21675 MB, 23833 MB goal, 48 P
gc 233 @564.753s 12%: 0.25+1409+0.32 ms clock, 8.0+1028/16872/15002+10 ms cpu, 22434->23775->21660 MB, 23842 MB goal, 48 P
gc 234 @567.584s 12%: 0.33+1415+0.42 ms clock, 8.7+1520/16898/14309+11 ms cpu, 22412->23754->21667 MB, 23826 MB goal, 48 P
gc 235 @570.439s 12%: 0.18+1429+0.39 ms clock, 5.8+52/16995/15743+12 ms cpu, 22395->23653->21579 MB, 23834 MB goal, 48 P
gc 236 @573.501s 12%: 0.68+1430+0.39 ms clock, 17+1532/17122/15028+10 ms cpu, 22392->23662->21590 MB, 23736 MB goal, 48 P
gc 237 @576.303s 12%: 0.34+1385+0.41 ms clock, 8.9+1492/16587/16429+10 ms cpu, 22384->23686->21622 MB, 23749 MB goal, 48 P
gc 238 @579.235s 12%: 0.35+1435+0.39 ms clock, 9.3+1193/17164/14733+10 ms cpu, 22390->23722->21654 MB, 23784 MB goal, 48 P
gc 239 @582.102s 12%: 0.37+1470+0.48 ms clock, 9.7+554/17598/12874+12 ms cpu, 22407->23738->21652 MB, 23819 MB goal, 48 P
gc 240 @585.109s 12%: 0.72+1461+0.52 ms clock, 18+634/17529/14389+13 ms cpu, 22426->23780->21675 MB, 23818 MB goal, 48 P
gc 241 @587.975s 12%: 0.34+1396+0.26 ms clock, 9.0+1611/16716/15509+6.9 ms cpu, 22443->23779->21657 MB, 23842 MB goal, 48 P
gc 242 @590.882s 12%: 0.36+1418+0.33 ms clock, 9.4+2113/16970/13767+8.6 ms cpu, 22392->23764->21691 MB, 23823 MB goal, 48 P
gc 243 @593.749s 12%: 1.1+1495+0.41 ms clock, 30+961/17891/11587+10 ms cpu, 22371->23778->21727 MB, 23860 MB goal, 48 P
gc 244 @596.827s 12%: 2.0+1446+0.35 ms clock, 53+323/17330/12958+9.2 ms cpu, 22412->23697->21609 MB, 23900 MB goal, 48 P
scvg3: inuse: 23061, idle: 1127, sys: 24189, released: 0, consumed: 24189 (MB)
gc 245 @599.661s 12%: 0.30+1407+0.30 ms clock, 8.0+1719/16823/14526+7.9 ms cpu, 22379->23704->21648 MB, 23770 MB goal, 48 P
gc 246 @602.552s 12%: 0.17+1396+0.40 ms clock, 5.7+1289/16583/14727+13 ms cpu, 22385->23746->21681 MB, 23813 MB goal, 48 P
gc 247 @605.441s 12%: 0.38+1465+0.45 ms clock, 9.9+246/17553/12132+11 ms cpu, 22401->23743->21661 MB, 23849 MB goal, 48 P
gc 248 @608.368s 12%: 0.62+1464+0.31 ms clock, 16+706/17489/14146+8.1 ms cpu, 22423->23765->21662 MB, 23827 MB goal, 48 P
gc 249 @611.266s 12%: 0.33+1413+0.32 ms clock, 8.5+2440/16939/14733+8.4 ms cpu, 22429->23770->21665 MB, 23829 MB goal, 48 P
gc 250 @614.064s 12%: 0.35+1446+0.53 ms clock, 9.1+1604/17334/14121+13 ms cpu, 22364->23756->21716 MB, 23831 MB goal, 48 P
gc 251 @616.899s 12%: 0.19+1478+0.48 ms clock, 6.1+414/17661/14709+15 ms cpu, 22390->23735->21665 MB, 23887 MB goal, 48 P
gc 252 @619.843s 12%: 0.71+1486+0.27 ms clock, 18+987/17836/11949+7.2 ms cpu, 22398->23806->21730 MB, 23832 MB goal, 48 P
gc 253 @622.757s 12%: 0.32+1436+0.42 ms clock, 8.5+1732/17183/15856+10 ms cpu, 22439->23801->21684 MB, 23903 MB goal, 48 P
gc 254 @625.631s 12%: 0.37+1459+0.40 ms clock, 9.6+828/17477/14518+10 ms cpu, 22375->23736->21681 MB, 23853 MB goal, 48 P
gc 255 @628.568s 12%: 1.1+1487+0.30 ms clock, 28+1468/17773/13205+7.7 ms cpu, 22397->23763->21688 MB, 23849 MB goal, 48 P
gc 256 @631.537s 12%: 1.3+1496+0.31 ms clock, 34+1360/17939/14312+8.0 ms cpu, 22391->23782->21712 MB, 23857 MB goal, 48 P
gc 257 @634.491s 12%: 0.33+1464+0.28 ms clock, 8.7+1257/17572/12070+7.4 ms cpu, 22401->23822->21739 MB, 23884 MB goal, 48 P
gc 258 @637.364s 12%: 0.29+1489+0.43 ms clock, 7.7+1009/17812/13839+11 ms cpu, 22409->23811->21720 MB, 23913 MB goal, 48 P
gc 259 @640.291s 12%: 0.75+1543+0.36 ms clock, 19+735/18499/15489+9.6 ms cpu, 22401->23815->21733 MB, 23892 MB goal, 48 P
gc 260 @643.317s 12%: 0.82+1496+0.35 ms clock, 21+1120/17941/14844+9.2 ms cpu, 22424->23838->21735 MB, 23906 MB goal, 48 P
gc 261 @646.291s 12%: 0.37+1468+0.41 ms clock, 9.6+891/17582/12789+10 ms cpu, 22417->23848->21749 MB, 23909 MB goal, 48 P
gc 262 @649.099s 12%: 0.31+1452+0.32 ms clock, 8.3+1141/17410/14693+8.4 ms cpu, 22425->23852->21744 MB, 23924 MB goal, 48 P
gc 263 @652.094s 12%: 1.1+1511+0.38 ms clock, 30+991/18107/13941+10 ms cpu, 22410->23796->21708 MB, 23919 MB goal, 48 P
gc 264 @655.054s 12%: 0.62+1491+0.46 ms clock, 16+1024/17861/13921+12 ms cpu, 22395->23804->21729 MB, 23879 MB goal, 48 P
gc 265 @658.080s 12%: 0.34+1512+0.28 ms clock, 9.0+1084/18109/12595+7.5 ms cpu, 22414->23850->21761 MB, 23902 MB goal, 48 P
gc 266 @661.018s 12%: 0.32+1478+0.40 ms clock, 8.3+1331/17690/14322+10 ms cpu, 22430->23853->21741 MB, 23937 MB goal, 48 P
gc 267 @664.015s 12%: 0.53+1507+0.39 ms clock, 17+345/17906/13393+12 ms cpu, 22398->23771->21690 MB, 23915 MB goal, 48 P
gc 268 @667.002s 12%: 0.54+1468+0.38 ms clock, 14+756/17591/13213+9.8 ms cpu, 22405->23811->21728 MB, 23859 MB goal, 48 P
gc 269 @669.912s 12%: 0.33+1477+0.31 ms clock, 8.2+865/17703/14132+7.8 ms cpu, 22437->23853->21738 MB, 23901 MB goal, 48 P
gc 270 @672.794s 12%: 0.38+1456+0.33 ms clock, 9.8+1310/17452/12901+8.6 ms cpu, 22437->23867->21749 MB, 23912 MB goal, 48 P
gc 271 @675.870s 12%: 0.65+1522+0.29 ms clock, 17+402/18196/11759+7.6 ms cpu, 22417->23857->21760 MB, 23924 MB goal, 48 P
gc 272 @678.845s 12%: 0.35+1427+0.39 ms clock, 8.8+483/17116/13576+9.7 ms cpu, 22446->23791->21665 MB, 23936 MB goal, 48 P
gc 273 @681.696s 12%: 0.18+1459+0.38 ms clock, 5.9+1071/17464/15182+12 ms cpu, 22401->23762->21679 MB, 23832 MB goal, 48 P
gc 274 @684.620s 12%: 2.0+1475+0.39 ms clock, 53+630/17689/13763+10 ms cpu, 22409->23757->21666 MB, 23847 MB goal, 48 P
gc 275 @687.670s 12%: 0.49+1482+0.34 ms clock, 12+914/17761/13915+8.9 ms cpu, 22417->23751->21659 MB, 23833 MB goal, 48 P
gc 276 @690.588s 12%: 0.37+1404+0.28 ms clock, 9.7+1916/16837/15099+7.4 ms cpu, 22416->23761->21668 MB, 23825 MB goal, 48 P
gc 277 @693.426s 12%: 0.31+1443+0.40 ms clock, 8.2+1676/17284/13458+10 ms cpu, 22381->23753->21694 MB, 23835 MB goal, 48 P
gc 278 @696.346s 12%: 3.4+1514+0.40 ms clock, 90+829/18145/11888+10 ms cpu, 22382->23782->21723 MB, 23864 MB goal, 48 P
gc 279 @699.283s 12%: 0.67+1469+0.38 ms clock, 17+489/17625/11028+9.8 ms cpu, 22421->23781->21680 MB, 23895 MB goal, 48 P
gc 280 @702.314s 12%: 0.40+1455+0.54 ms clock, 10+2329/17289/14198+14 ms cpu, 22415->23780->21689 MB, 23848 MB goal, 48 P
gc 281 @705.172s 12%: 0.33+1459+0.44 ms clock, 8.7+800/17446/13684+11 ms cpu, 22367->23771->21721 MB, 23858 MB goal, 48 P
gc 282 @708.106s 12%: 4.3+1488+0.38 ms clock, 138+233/17796/13198+12 ms cpu, 22412->23747->21655 MB, 23893 MB goal, 48 P
gc 283 @711.076s 12%: 0.67+1499+0.28 ms clock, 17+705/17995/13043+7.4 ms cpu, 22408->23766->21678 MB, 23820 MB goal, 48 P
gc 284 @714.052s 12%: 0.38+1392+0.33 ms clock, 10+1598/16659/14794+8.6 ms cpu, 22432->23770->21660 MB, 23846 MB goal, 48 P
gc 285 @716.817s 12%: 0.36+1412+0.40 ms clock, 9.4+1529/16889/14028+10 ms cpu, 22388->23764->21695 MB, 23826 MB goal, 48 P
gc 286 @719.710s 12%: 2.8+1476+0.48 ms clock, 73+632/17683/11667+12 ms cpu, 22393->23756->21684 MB, 23865 MB goal, 48 P
gc 287 @722.604s 12%: 0.55+1445+0.37 ms clock, 14+1462/17309/13934+9.7 ms cpu, 22411->23776->21688 MB, 23852 MB goal, 48 P
gc 288 @725.548s 12%: 0.19+1438+0.31 ms clock, 6.2+1696/17049/13820+9.9 ms cpu, 22396->23787->21711 MB, 23857 MB goal, 48 P
gc 289 @728.341s 12%: 0.33+1469+0.29 ms clock, 8.7+888/17615/13519+7.7 ms cpu, 22386->23819->21751 MB, 23882 MB goal, 48 P
gc 290 @731.273s 12%: 0.71+1515+0.45 ms clock, 18+880/18165/11738+11 ms cpu, 22423->23849->21747 MB, 23926 MB goal, 48 P
gc 291 @734.229s 12%: 0.54+1453+0.42 ms clock, 14+504/17392/13543+10 ms cpu, 22423->23764->21661 MB, 23922 MB goal, 48 P
gc 292 @737.239s 12%: 0.32+1417+0.39 ms clock, 8.3+853/16995/14837+10 ms cpu, 22394->23764->21689 MB, 23827 MB goal, 48 P
gc 293 @740.016s 12%: 0.30+1438+0.37 ms clock, 9.8+1233/17239/14905+12 ms cpu, 22420->23793->21693 MB, 23858 MB goal, 48 P
gc 294 @743.043s 12%: 0.69+1464+0.42 ms clock, 22+311/17535/14910+13 ms cpu, 22408->23726->21636 MB, 23863 MB goal, 48 P
gc 295 @745.931s 12%: 0.53+1448+0.43 ms clock, 13+573/17327/14838+11 ms cpu, 22406->23730->21644 MB, 23800 MB goal, 48 P
scvg4: inuse: 23776, idle: 427, sys: 24203, released: 0, consumed: 24203 (MB)
gc 296 @748.976s 12%: 0.31+1402+0.30 ms clock, 8.2+2489/16815/13913+7.9 ms cpu, 22427->23748->21641 MB, 23809 MB goal, 48 P
gc 297 @751.748s 12%: 0.34+1446+0.45 ms clock, 8.9+1357/17323/13865+11 ms cpu, 22356->23747->21716 MB, 23805 MB goal, 48 P
gc 298 @754.688s 12%: 0.75+1474+0.63 ms clock, 19+521/17634/13182+16 ms cpu, 22408->23771->21681 MB, 23888 MB goal, 48 P
gc 299 @757.585s 12%: 0.39+1452+0.43 ms clock, 12+461/17277/13289+13 ms cpu, 22410->23773->21683 MB, 23850 MB goal, 48 P
gc 300 @760.512s 12%: 0.23+1420+0.45 ms clock, 7.5+1709/17025/13534+14 ms cpu, 22432->23787->21675 MB, 23851 MB goal, 48 P
gc 301 @763.300s 12%: 0.31+1415+0.43 ms clock, 8.1+569/16938/13783+11 ms cpu, 22387->23691->21624 MB, 23842 MB goal, 48 P
gc 302 @766.279s 12%: 0.92+1444+0.39 ms clock, 24+651/17332/13301+10 ms cpu, 22388->23705->21638 MB, 23786 MB goal, 48 P
gc 303 @769.167s 12%: 0.52+1396+0.33 ms clock, 13+1323/16672/14221+8.7 ms cpu, 22419->23732->21632 MB, 23802 MB goal, 48 P
gc 304 @772.027s 12%: 0.17+1416+0.39 ms clock, 5.6+1384/16824/14706+12 ms cpu, 22396->23723->21646 MB, 23795 MB goal, 48 P
gc 305 @774.823s 12%: 0.31+1433+0.41 ms clock, 8.0+865/17155/13995+10 ms cpu, 22392->23736->21661 MB, 23810 MB goal, 48 P
gc 306 @777.890s 12%: 0.84+1498+0.36 ms clock, 22+789/17921/13063+9.3 ms cpu, 22411->23775->21687 MB, 23827 MB goal, 48 P
gc 307 @780.811s 12%: 0.35+1507+0.42 ms clock, 9.2+1063/18057/13882+11 ms cpu, 22435->23860->22664 MB, 23856 MB goal, 48 P
gc 308 @783.837s 12%: 0.34+1428+0.37 ms clock, 8.5+1592/17092/14745+9.4 ms cpu, 23399->24706->21633 MB, 24930 MB goal, 48 P
gc 309 @786.659s 12%: 0.34+1461+0.43 ms clock, 9.0+734/17468/13365+11 ms cpu, 22384->23740->21677 MB, 23796 MB goal, 48 P
gc 310 @789.665s 12%: 0.57+1458+0.31 ms clock, 18+570/17406/13330+10 ms cpu, 22429->23786->21678 MB, 23845 MB goal, 48 P
gc 311 @792.526s 12%: 0.44+1405+0.45 ms clock, 11+1485/16837/14656+11 ms cpu, 22438->23789->21676 MB, 23846 MB goal, 48 P
gc 312 @795.421s 12%: 0.34+1441+0.30 ms clock, 8.5+1313/17262/14384+7.6 ms cpu, 22405->23767->21682 MB, 23844 MB goal, 48 P
gc 313 @798.236s 12%: 0.37+1452+0.41 ms clock, 9.7+934/17363/13010+10 ms cpu, 22398->23716->21644 MB, 23851 MB goal, 48 P
gc 314 @801.226s 12%: 0.64+1472+0.35 ms clock, 20+350/17628/14048+11 ms cpu, 22390->23736->21665 MB, 23808 MB goal, 48 P
gc 315 @804.155s 12%: 0.29+1425+0.48 ms clock, 7.7+1164/17078/14675+12 ms cpu, 22435->23751->21637 MB, 23832 MB goal, 48 P
gc 316 @807.158s 12%: 0.38+1421+0.33 ms clock, 9.9+2117/16972/13639+8.7 ms cpu, 22401->23733->21657 MB, 23800 MB goal, 48 P
gc 317 @809.986s 12%: 0.18+1507+0.35 ms clock, 5.8+765/18039/12404+11 ms cpu, 22373->23753->21702 MB, 23823 MB goal, 48 P
gc 318 @812.990s 12%: 0.43+1465+0.36 ms clock, 14+1130/17404/14146+11 ms cpu, 22425->23804->21698 MB, 23872 MB goal, 48 P
gc 319 @815.844s 12%: 0.36+1417+0.16 ms clock, 9.5+1601/16982/15006+4.3 ms cpu, 22411->23807->21719 MB, 23867 MB goal, 48 P
gc 320 @818.687s 12%: 0.39+1438+0.39 ms clock, 10+570/17196/13233+10 ms cpu, 22398->23753->21678 MB, 23891 MB goal, 48 P
gc 321 @821.515s 12%: 0.33+1480+0.34 ms clock, 8.7+771/17746/12905+9.0 ms cpu, 22402->23788->21707 MB, 23846 MB goal, 48 P
gc 322 @824.590s 12%: 0.65+1469+0.41 ms clock, 16+324/17626/13912+10 ms cpu, 22431->23798->21685 MB, 23878 MB goal, 48 P
gc 323 @827.456s 12%: 0.32+1418+0.39 ms clock, 8.5+1600/16990/14309+10 ms cpu, 22435->23783->21673 MB, 23853 MB goal, 48 P
gc 324 @830.430s 12%: 0.34+1447+0.47 ms clock, 8.9+1381/17335/13694+12 ms cpu, 22395->23776->21699 MB, 23841 MB goal, 48 P
gc 325 @833.317s 12%: 1.4+1468+0.43 ms clock, 36+947/17567/13527+11 ms cpu, 22399->23714->21639 MB, 23868 MB goal, 48 P
gc 326 @836.346s 12%: 2.9+1447+0.36 ms clock, 75+1223/17317/13185+9.6 ms cpu, 22379->23731->21677 MB, 23803 MB goal, 48 P
gc 327 @839.153s 12%: 0.31+1427+0.33 ms clock, 8.2+783/17104/14597+8.7 ms cpu, 22406->23781->21693 MB, 23844 MB goal, 48 P
gc 328 @842.092s 12%: 0.30+1441+0.38 ms clock, 8.0+799/17277/14255+10 ms cpu, 22423->23790->21686 MB, 23862 MB goal, 48 P
gc 329 @845.012s 12%: 0.83+1484+0.42 ms clock, 21+698/17751/12469+10 ms cpu, 22421->23802->21697 MB, 23855 MB goal, 48 P
gc 330 @848.179s 12%: 0.67+1451+0.37 ms clock, 17+707/17387/13169+9.6 ms cpu, 22432->23799->21688 MB, 23867 MB goal, 48 P
gc 331 @851.063s 12%: 0.35+1435+0.47 ms clock, 9.3+1411/17193/14413+12 ms cpu, 22429->23797->21693 MB, 23857 MB goal, 48 P
gc 332 @853.919s 12%: 3.7+1461+0.48 ms clock, 98+1476/17537/12075+12 ms cpu, 22407->23793->21711 MB, 23862 MB goal, 48 P
gc 333 @856.850s 12%: 0.61+1496+0.28 ms clock, 15+1082/17849/12352+7.4 ms cpu, 22402->23799->21722 MB, 23882 MB goal, 48 P
gc 334 @859.811s 12%: 0.39+1478+0.36 ms clock, 10+894/17722/13443+9.5 ms cpu, 22413->23814->21724 MB, 23894 MB goal, 48 P
gc 335 @862.728s 12%: 0.18+1483+0.48 ms clock, 6.0+1135/17764/14166+15 ms cpu, 22420->23824->21723 MB, 23896 MB goal, 48 P
gc 336 @865.757s 12%: 0.18+1463+0.40 ms clock, 5.9+708/17393/14702+12 ms cpu, 22410->23730->21640 MB, 23896 MB goal, 48 P
gc 337 @868.674s 12%: 0.77+1473+0.42 ms clock, 20+1261/17638/14316+11 ms cpu, 22380->23737->21681 MB, 23804 MB goal, 48 P
gc 338 @871.586s 12%: 0.35+1463+0.28 ms clock, 9.2+1042/17531/13897+7.2 ms cpu, 22408->23787->21699 MB, 23849 MB goal, 48 P
gc 339 @874.495s 12%: 0.36+1464+0.43 ms clock, 9.1+786/17539/13162+10 ms cpu, 22417->23825->21731 MB, 23869 MB goal, 48 P
gc 340 @877.536s 12%: 0.33+1451+0.39 ms clock, 8.7+825/17413/14285+10 ms cpu, 22441->23732->21617 MB, 23905 MB goal, 48 P
gc 341 @880.415s 12%: 0.66+1114+0.35 ms clock, 17+766/13368/21791+9.3 ms cpu, 22378->22812->20776 MB, 23779 MB goal, 48 P
gc 342 @884.288s 12%: 0.26+1132+0.37 ms clock, 8.5+40/13561/24707+11 ms cpu, 21959->22340->20716 MB, 22853 MB goal, 48 P
gc 343 @888.958s 12%: 0.24+1128+0.60 ms clock, 7.9+217/13510/26115+19 ms cpu, 22151->22517->20701 MB, 22787 MB goal, 48 P
gc 344 @894.106s 12%: 0.74+1112+0.30 ms clock, 23+95/13325/25704+9.8 ms cpu, 22268->22636->20703 MB, 22771 MB goal, 48 P
scvg5: inuse: 22842, idle: 1361, sys: 24203, released: 0, consumed: 24203 (MB)
gc 345 @899.539s 12%: 0.24+1170+0.39 ms clock, 7.8+540/14017/24699+12 ms cpu, 22336->22742->20741 MB, 22774 MB goal, 48 P
gc 346 @905.101s 12%: 1.2+1125+0.38 ms clock, 40+472/13484/27924+12 ms cpu, 22385->22684->20633 MB, 22815 MB goal, 48 P
gc 347 @910.983s 12%: 0.72+1112+0.47 ms clock, 18+345/13344/29243+12 ms cpu, 22329->22523->20530 MB, 22697 MB goal, 48 P
gc 348 @917.979s 12%: 1.0+1153+0.33 ms clock, 33+436/13630/31369+10 ms cpu, 22301->22460->20494 MB, 22583 MB goal, 48 P
gc 349 @925.457s 12%: 1.8+1087+0.33 ms clock, 49+919/12998/27356+8.6 ms cpu, 22322->22537->20551 MB, 22544 MB goal, 48 P
gc 350 @933.081s 12%: 1.2+1108+0.38 ms clock, 32+1223/13263/27904+10 ms cpu, 22380->22572->20528 MB, 22607 MB goal, 48 P
gc 351 @939.190s 12%: 4.7+1093+0.63 ms clock, 122+1463/13102/28369+16 ms cpu, 22362->22540->20514 MB, 22581 MB goal, 48 P
gc 352 @946.328s 12%: 1.3+1081+0.29 ms clock, 35+4436/12970/26646+7.6 ms cpu, 22358->22555->20532 MB, 22566 MB goal, 48 P
gc 353 @953.351s 11%: 1.2+1101+0.29 ms clock, 32+3587/13156/26959+7.6 ms cpu, 22350->22555->20541 MB, 22585 MB goal, 48 P
gc 354 @959.638s 11%: 1.0+1115+0.33 ms clock, 26+355/13326/27959+8.8 ms cpu, 22347->22576->20566 MB, 22595 MB goal, 48 P
gc 355 @966.942s 11%: 1.0+1114+0.43 ms clock, 33+1000/13211/29237+13 ms cpu, 22380->22561->20517 MB, 22623 MB goal, 48 P
gc 356 @974.349s 11%: 0.67+1104+0.31 ms clock, 21+7123/13203/25375+10 ms cpu, 22351->22563->20548 MB, 22569 MB goal, 48 P
gc 357 @981.600s 11%: 1.1+1138+0.32 ms clock, 36+578/13434/29749+10 ms cpu, 22330->22531->20537 MB, 22602 MB goal, 48 P
gc 358 @988.807s 11%: 0.59+1094+0.54 ms clock, 18+5534/12922/25797+17 ms cpu, 22350->22580->20566 MB, 22590 MB goal, 48 P
gc 359 @995.760s 11%: 1.5+1139+0.32 ms clock, 50+477/13578/29517+10 ms cpu, 22339->22576->20572 MB, 22623 MB goal, 48 P
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#19393 (comment)>, or mute
the thread
<https://github.com/notifications/unsubscribe-auth/AA7Wn33hi94Ah7G0o3R8_HVt89IV8IXEks5rjEh3gaJpZM4MS8AZ>
.
|
|
I captured this profile during the period of time when the throughput is slowly growing after GC:
|
|
This graph illustrates the throughput with GOMAXPROCS=16
GOMAXPROCS=32 and GOMAXPROCS=24 have similar but less noticeable impact. GOMAXPROCS < 16 hurts performance. GOGC=20 + GOMAXPROCS=16 deliver nearly the best average throughput:
|
|
Thanks, this is great information. Large object allocation appears to use a
O(number of spans) algorithm under a lock. If this is the problem it would
explain most of what we are seeing. Reducing the number of spans with
GOGC=10 could help by reducing the number of spans. Reducing GOMAXPROCS
could reduce the lock contention.
We will dig further into it but I think we have all we need for now.
The only clue (guess) I can give for a temporary workaround would be to
look at how slices are used and if providing a capacity when they are first
created would help reduce the number of large object allocations.
Again thanks for the help.
…On Mon, Mar 6, 2017 at 7:54 PM, Pavel Paulau ***@***.***> wrote:
This graph illustrates the throughput with GOMAXPROCS=16
[image: ops_1 8_gomaxprocs16]
<https://cloud.githubusercontent.com/assets/833001/23636611/37c1926c-028b-11e7-953a-a3323d0085b3.png>
GOMAXPROCS=32 and GOMAXPROCS=24 have similar but less noticeable impact.
GOMAXPROCS < 16 hurts performance.
GOGC=20 + GOMAXPROCS=16 deliver nearly the best average throughput:
[image: ops_1 8_gogc20_gomaxprocs16]
<https://cloud.githubusercontent.com/assets/833001/23636854/cf17a93e-028c-11e7-806e-c272a0fea2e3.png>
gc 1 @0.003s 3%: 0.58+0.59+0.28 ms clock, 1.1+0/1.4/0.84+0.57 ms cpu, 0->1->0 MB, 1 MB goal, 16 P
gc 2 @0.006s 5%: 0.12+0.46+0.098 ms clock, 0.98+0.067/0.87/0.47+0.79 ms cpu, 0->0->0 MB, 1 MB goal, 16 P
gc 3 @0.007s 10%: 0.50+0.057+0.13 ms clock, 5.5+0/0.90/0.85+1.4 ms cpu, 0->0->0 MB, 1 MB goal, 16 P
gc 4 @0.087s 7%: 0.054+24+0.11 ms clock, 0.65+17/98/245+1.4 ms cpu, 458->459->458 MB, 459 MB goal, 16 P
gc 5 @0.112s 10%: 0.010+24+0.11 ms clock, 0.17+0.45/95/252+1.8 ms cpu, 459->463->463 MB, 550 MB goal, 16 P
gc 6 @0.223s 8%: 0.013+35+0.11 ms clock, 0.21+0.80/140/303+1.8 ms cpu, 507->516->509 MB, 556 MB goal, 16 P
gc 7 @0.390s 7%: 0.013+38+0.14 ms clock, 0.21+0.60/151/400+2.2 ms cpu, 579->589->578 MB, 611 MB goal, 16 P
gc 8 @0.601s 6%: 0.013+42+0.16 ms clock, 0.20+0.62/170/466+2.5 ms cpu, 670->682->668 MB, 694 MB goal, 16 P
gc 9 @0.825s 6%: 0.011+54+0.12 ms clock, 0.18+0.83/199/547+1.9 ms cpu, 780->792->774 MB, 801 MB goal, 16 P
gc 10 @1.085s 6%: 0.016+80+0.11 ms clock, 0.26+24/302/721+1.7 ms cpu, 910->929->908 MB, 929 MB goal, 16 P
gc 11 @1.386s 6%: 0.021+83+0.14 ms clock, 0.34+0.88/329/873+2.2 ms cpu, 1067->1087->1062 MB, 1090 MB goal, 16 P
gc 12 @1.741s 6%: 0.013+94+0.10 ms clock, 0.21+14/375/1002+1.6 ms cpu, 1249->1275->1245 MB, 1275 MB goal, 16 P
gc 13 @2.142s 6%: 0.011+109+0.085 ms clock, 0.18+24/433/1173+1.3 ms cpu, 1464->1495->1460 MB, 1495 MB goal, 16 P
gc 14 @2.572s 6%: 0.015+130+0.11 ms clock, 0.24+1.6/520/1414+1.8 ms cpu, 1716->1750->1710 MB, 1752 MB goal, 16 P
gc 15 @3.141s 7%: 0.019+205+0.049 ms clock, 0.31+30/823/2260+0.79 ms cpu, 2010->2052->2005 MB, 2052 MB goal, 16 P
gc 16 @3.854s 7%: 0.018+232+0.25 ms clock, 0.30+60/930/2551+4.0 ms cpu, 2356->2406->2352 MB, 2406 MB goal, 16 P
gc 17 @4.731s 7%: 0.020+378+0.091 ms clock, 0.33+148/1508/1270+1.4 ms cpu, 2763->2823->2760 MB, 2823 MB goal, 16 P
gc 18 @5.825s 7%: 0.016+258+0.071 ms clock, 0.27+7.2/1032/2797+1.1 ms cpu, 3238->3307->3234 MB, 3312 MB goal, 16 P
gc 19 @6.954s 7%: 0.028+263+0.054 ms clock, 0.46+8.5/1051/2852+0.87 ms cpu, 3796->3881->3794 MB, 3881 MB goal, 16 P
gc 20 @8.148s 7%: 0.019+285+0.11 ms clock, 0.31+5.3/1119/3060+1.8 ms cpu, 4454->4533->4431 MB, 4553 MB goal, 16 P
gc 21 @9.483s 7%: 0.015+324+0.091 ms clock, 0.24+25/1296/3533+1.4 ms cpu, 5213->5302->5184 MB, 5317 MB goal, 16 P
gc 22 @11.060s 6%: 0.015+434+0.056 ms clock, 0.25+16/1732/4747+0.90 ms cpu, 6107->6220->6082 MB, 6221 MB goal, 16 P
gc 23 @13.019s 7%: 0.019+609+0.059 ms clock, 0.31+90/2436/6676+0.94 ms cpu, 7165->7299->7135 MB, 7299 MB goal, 16 P
gc 24 @15.393s 6%: 0.018+581+0.069 ms clock, 0.29+83/2319/6363+1.1 ms cpu, 8403->8562->8371 MB, 8563 MB goal, 16 P
gc 25 @18.208s 6%: 0.015+635+0.060 ms clock, 0.24+37/2537/6965+0.96 ms cpu, 9855->10045->9821 MB, 10045 MB goal, 16 P
gc 26 @21.284s 6%: 0.019+778+0.11 ms clock, 0.30+19/3112/8544+1.8 ms cpu, 11560->11772->11509 MB, 11785 MB goal, 16 P
gc 27 @24.958s 6%: 0.015+1028+0.049 ms clock, 0.24+184/4112/11269+0.79 ms cpu, 13553->13811->13502 MB, 13811 MB goal, 16 P
gc 28 @29.218s 6%: 0.017+1107+0.057 ms clock, 0.28+84/4426/12156+0.92 ms cpu, 15894->16202->15840 MB, 16203 MB goal, 16 P
gc 29 @34.173s 6%: 0.019+1347+0.069 ms clock, 0.31+73/4837/13287+1.1 ms cpu, 18642->19003->18580 MB, 19008 MB goal, 16 P
gc 30 @48.648s 5%: 0.036+1768+0.086 ms clock, 0.58+48/7038/19319+1.3 ms cpu, 21868->22050->20515 MB, 22297 MB goal, 16 P
gc 31 @66.704s 5%: 0.15+1908+0.54 ms clock, 1.4+11914/7629/7565+4.8 ms cpu, 24279->24601->20653 MB, 24618 MB goal, 16 P
gc 32 @72.932s 6%: 0.16+1920+0.18 ms clock, 1.5+10758/7672/7214+1.6 ms cpu, 24199->24720->20848 MB, 24784 MB goal, 16 P
gc 33 @78.985s 7%: 0.15+2228+0.33 ms clock, 1.4+10687/8912/8022+3.0 ms cpu, 24091->24919->21150 MB, 25018 MB goal, 16 P
gc 34 @84.757s 8%: 0.75+2445+0.13 ms clock, 12+7636/9751/9053+2.2 ms cpu, 23987->25233->21562 MB, 25380 MB goal, 16 P
gc 35 @89.530s 9%: 0.61+2701+0.39 ms clock, 5.5+5727/10795/8482+3.5 ms cpu, 24034->25686->21968 MB, 25875 MB goal, 16 P
gc 36 @95.044s 9%: 0.79+2995+0.094 ms clock, 7.1+3261/11975/9194+0.85 ms cpu, 24136->26115->22285 MB, 26362 MB goal, 16 P
gc 37 @100.016s 10%: 0.41+3119+0.20 ms clock, 3.2+4434/12473/7745+1.6 ms cpu, 24336->26486->22450 MB, 26742 MB goal, 16 P
gc 38 @105.203s 10%: 0.24+3308+0.38 ms clock, 2.1+3175/13219/7516+3.4 ms cpu, 24261->26631->22667 MB, 26940 MB goal, 16 P
gc 39 @110.491s 11%: 0.73+3340+0.18 ms clock, 6.6+3004/13326/7999+1.6 ms cpu, 24364->26869->22796 MB, 27201 MB goal, 16 P
gc 40 @115.677s 11%: 0.34+3255+0.42 ms clock, 3.1+2528/13023/8085+3.8 ms cpu, 24386->27014->22917 MB, 27355 MB goal, 16 P
gc 41 @120.818s 11%: 0.64+3495+0.21 ms clock, 10+1867/13965/9751+3.4 ms cpu, 24431->27149->23005 MB, 27501 MB goal, 16 P
gc 42 @126.220s 11%: 1.5+3338+0.28 ms clock, 13+2889/13348/8570+2.6 ms cpu, 24519->27209->22989 MB, 27606 MB goal, 16 P
gc 43 @131.477s 12%: 1.2+3372+0.13 ms clock, 11+2341/13487/8356+1.2 ms cpu, 24409->27202->23082 MB, 27587 MB goal, 16 P
gc 44 @136.894s 12%: 0.70+3450+0.12 ms clock, 6.3+1834/13771/8558+1.1 ms cpu, 24458->27320->23154 MB, 27698 MB goal, 16 P
gc 45 @142.212s 12%: 0.35+3568+0.22 ms clock, 3.1+1729/14267/9343+2.0 ms cpu, 24534->27405->23163 MB, 27785 MB goal, 16 P
scvg0: inuse: 26937, idle: 892, sys: 27830, released: 0, consumed: 27830 (MB)
gc 46 @147.641s 12%: 2.8+3506+0.11 ms clock, 25+1782/14024/8193+1.0 ms cpu, 24559->27407->23136 MB, 27795 MB goal, 16 P
gc 47 @153.056s 13%: 0.17+3462+5.1 ms clock, 2.8+2531/13840/8355+82 ms cpu, 24544->27368->23112 MB, 27764 MB goal, 16 P
gc 48 @158.514s 13%: 1.0+3479+0.16 ms clock, 9.1+2053/13902/9021+1.5 ms cpu, 24458->27348->23182 MB, 27734 MB goal, 16 P
gc 49 @163.911s 13%: 0.64+3470+0.10 ms clock, 10+2476/13874/8256+1.6 ms cpu, 24512->27425->23197 MB, 27818 MB goal, 16 P
gc 50 @169.218s 13%: 0.26+3559+0.10 ms clock, 2.3+2383/14227/8397+0.92 ms cpu, 24464->27446->23274 MB, 27836 MB goal, 16 P
gc 51 @174.635s 13%: 0.61+3605+0.18 ms clock, 6.1+1352/14396/8767+1.8 ms cpu, 24491->27518->23309 MB, 27929 MB goal, 16 P
gc 52 @180.066s 13%: 0.31+3555+0.33 ms clock, 2.8+2500/14187/7779+3.0 ms cpu, 24591->27565->23260 MB, 27971 MB goal, 16 P
gc 53 @185.463s 14%: 1.4+3487+0.14 ms clock, 12+1558/13936/7433+1.3 ms cpu, 24482->27516->23320 MB, 27912 MB goal, 16 P
gc 54 @190.718s 14%: 0.13+3274+0.15 ms clock, 1.1+1715/13099/8353+1.4 ms cpu, 24573->27567->23277 MB, 27984 MB goal, 16 P
gc 55 @195.835s 14%: 0.16+3609+0.24 ms clock, 1.4+1540/14437/7409+2.1 ms cpu, 24541->27504->23249 MB, 27933 MB goal, 16 P
gc 56 @201.420s 14%: 0.15+3355+0.13 ms clock, 2.3+1214/13394/8091+2.0 ms cpu, 24567->27491->23214 MB, 27899 MB goal, 16 P
gc 57 @206.741s 14%: 0.34+3365+0.16 ms clock, 3.0+2619/13438/8301+1.5 ms cpu, 24602->27466->23149 MB, 27857 MB goal, 16 P
gc 58 @212.039s 14%: 0.92+3505+0.23 ms clock, 8.3+1645/14020/8647+2.0 ms cpu, 24450->27395->23229 MB, 27779 MB goal, 16 P
gc 59 @217.420s 14%: 0.30+3404+0.20 ms clock, 2.7+2451/13615/7205+1.8 ms cpu, 24554->27483->23213 MB, 27875 MB goal, 16 P
gc 60 @222.532s 14%: 0.22+3545+0.21 ms clock, 2.0+1301/14175/7178+1.9 ms cpu, 24470->27437->23253 MB, 27856 MB goal, 16 P
gc 61 @227.997s 14%: 1.5+3438+0.12 ms clock, 13+1990/13751/7050+1.1 ms cpu, 24585->27495->23208 MB, 27903 MB goal, 16 P
gc 62 @233.204s 14%: 0.30+3429+0.19 ms clock, 2.7+1822/13711/8212+1.7 ms cpu, 24531->27450->23204 MB, 27850 MB goal, 16 P
gc 63 @238.578s 15%: 0.72+3538+0.16 ms clock, 7.2+2447/14146/7236+1.6 ms cpu, 24533->27452->23211 MB, 27845 MB goal, 16 P
gc 64 @243.913s 15%: 0.32+3519+0.23 ms clock, 2.8+3225/14070/7145+2.1 ms cpu, 24484->27449->23251 MB, 27853 MB goal, 16 P
gc 65 @249.286s 15%: 0.88+3651+0.14 ms clock, 7.9+995/14596/9008+1.3 ms cpu, 24389->27486->23383 MB, 27901 MB goal, 16 P
gc 66 @254.819s 15%: 0.61+3454+0.22 ms clock, 5.5+1689/13799/8665+1.9 ms cpu, 24630->27628->23284 MB, 28060 MB goal, 16 P
gc 67 @259.987s 15%: 0.32+3543+0.19 ms clock, 2.9+1865/14169/8552+1.7 ms cpu, 24558->27522->23255 MB, 27941 MB goal, 16 P
gc 68 @265.283s 15%: 0.67+3424+0.13 ms clock, 6.1+1662/13697/7976+1.2 ms cpu, 24541->27502->23244 MB, 27906 MB goal, 16 P
gc 69 @270.475s 15%: 0.25+3376+0.23 ms clock, 2.3+2602/13491/7587+2.0 ms cpu, 24552->27490->23228 MB, 27893 MB goal, 16 P
gc 70 @275.757s 15%: 1.2+3493+0.19 ms clock, 11+1831/13967/8055+1.7 ms cpu, 24454->27472->23301 MB, 27874 MB goal, 16 P
gc 71 @280.942s 15%: 0.61+3542+0.13 ms clock, 5.5+2146/14165/7121+1.1 ms cpu, 24534->27552->23305 MB, 27962 MB goal, 16 P
gc 72 @286.219s 15%: 0.24+3622+0.14 ms clock, 2.1+1876/14480/8151+1.2 ms cpu, 24514->27548->23324 MB, 27966 MB goal, 16 P
gc 73 @291.638s 15%: 0.64+3644+0.21 ms clock, 5.8+1446/14575/7276+1.9 ms cpu, 24547->27587->23330 MB, 27989 MB goal, 16 P
scvg1: inuse: 27565, idle: 487, sys: 28052, released: 0, consumed: 28052 (MB)
gc 74 @297.019s 15%: 2.2+3491+0.22 ms clock, 20+2176/13957/7381+2.0 ms cpu, 24603->27595->23282 MB, 27997 MB goal, 16 P
gc 75 @302.517s 15%: 0.080+3508+0.14 ms clock, 0.64+1501/14019/7687+1.1 ms cpu, 24521->27545->23307 MB, 27939 MB goal, 16 P
gc 76 @307.835s 15%: 0.28+3463+0.26 ms clock, 2.5+2847/13845/6919+2.3 ms cpu, 24581->27552->23268 MB, 27968 MB goal, 16 P
gc 77 @313.048s 15%: 0.28+3546+0.16 ms clock, 2.5+1749/14183/7639+1.5 ms cpu, 24444->27514->23351 MB, 27922 MB goal, 16 P
gc 78 @318.445s 15%: 0.92+3465+0.16 ms clock, 8.3+1949/13862/7204+1.4 ms cpu, 24546->27607->23344 MB, 28022 MB goal, 16 P
gc 79 @323.608s 16%: 0.25+3389+0.18 ms clock, 2.5+2404/13553/7801+1.8 ms cpu, 24530->27602->23358 MB, 28013 MB goal, 16 P
gc 80 @329.019s 16%: 0.91+3623+0.19 ms clock, 14+1714/14478/8874+3.1 ms cpu, 24478->27583->23391 MB, 28030 MB goal, 16 P
gc 81 @334.512s 16%: 2.1+3581+0.19 ms clock, 19+1378/14283/9248+1.7 ms cpu, 24552->27651->23385 MB, 28070 MB goal, 16 P
gc 82 @340.008s 16%: 0.12+3444+0.14 ms clock, 1.1+1536/13772/8455+1.2 ms cpu, 24607->27646->23323 MB, 28063 MB goal, 16 P
gc 83 @345.207s 16%: 0.19+3526+0.18 ms clock, 1.7+1942/14097/8152+1.6 ms cpu, 24580->27575->23278 MB, 27988 MB goal, 16 P
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#19393 (comment)>, or mute
the thread
<https://github.com/notifications/unsubscribe-auth/AA7Wn25PjR3-bKdNyhikHGoVvQbFaSQUks5rjKqwgaJpZM4MS8AZ>
.
|
|
Just for tracking, I also captured heap profiles.
|
|
CL https://golang.org/cl/38732 mentions this issue. |
|
Pavel,
Could you rerun with tip and check that this fixes the problem?
…On Wed, Mar 29, 2017 at 10:18 AM, GopherBot ***@***.***> wrote:
Closed #19393 <#19393> via 6e9ec14
<6e9ec14>
.
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
<#19393 (comment)>, or mute the
thread
<https://github.com/notifications/unsubscribe-auth/AA7Wn6mxS48U6AppJoLZHmB6W5JMBl6Vks5rqmhRgaJpZM4MS8AZ>
.
|
|
Hi Richard, Your fix has certainly helped. Thanks for resolving this issue! |
lparth
pushed a commit
to lparth/go
that referenced
this issue
Apr 13, 2017
Currently for spans with up to 1 MBytes (128 pages) we maintain an array indexed by the number of pages in the span. This is efficient both in terms of space as well as time to insert or remove a span of a particular size. Unfortunately for spans larger than 1 MByte we currently place them on a separate linked list. This results in O(n) behavior. Now that we are seeing heaps approaching 100 GBytes n is large enough to be noticed in real programs. This change replaces the linked list now used with a balanced binary tree structure called a treap. A treap is a probabilistically balanced tree offering O(logN) behavior for inserting and removing spans. To verify that this approach will work we start with noting that only spans with sizes > 1MByte will be put into the treap. This means that to support 1 TByte a treap will need at most 1 million nodes and can ideally be held in a treap with a depth of 20. Experiments with adding and removing randomly sized spans from the treap seem to result in treaps with depths of about twice the ideal or 40. A petabyte would require a tree of only twice again that depth again so this algorithm should last well into the future. Fixes golang#19393 Go1 benchmarks indicate this is basically an overall wash. Tue Mar 28 21:29:21 EDT 2017 name old time/op new time/op delta BinaryTree17-4 2.42s ± 1% 2.42s ± 1% ~ (p=0.980 n=21+21) Fannkuch11-4 3.00s ± 1% 3.18s ± 4% +6.10% (p=0.000 n=22+24) FmtFprintfEmpty-4 40.5ns ± 1% 40.3ns ± 3% ~ (p=0.692 n=22+25) FmtFprintfString-4 65.9ns ± 3% 64.6ns ± 1% -1.98% (p=0.000 n=24+23) FmtFprintfInt-4 69.6ns ± 1% 68.0ns ± 7% -2.30% (p=0.001 n=21+22) FmtFprintfIntInt-4 102ns ± 2% 99ns ± 1% -3.07% (p=0.000 n=23+23) FmtFprintfPrefixedInt-4 126ns ± 0% 125ns ± 0% -0.79% (p=0.000 n=19+17) FmtFprintfFloat-4 206ns ± 2% 205ns ± 1% ~ (p=0.671 n=23+21) FmtManyArgs-4 441ns ± 1% 445ns ± 1% +0.88% (p=0.000 n=22+23) GobDecode-4 5.73ms ± 1% 5.86ms ± 1% +2.37% (p=0.000 n=23+22) GobEncode-4 4.51ms ± 1% 4.89ms ± 1% +8.32% (p=0.000 n=22+22) Gzip-4 197ms ± 0% 202ms ± 1% +2.75% (p=0.000 n=23+24) Gunzip-4 32.9ms ± 8% 32.7ms ± 2% ~ (p=0.466 n=23+24) HTTPClientServer-4 57.3µs ± 1% 56.7µs ± 1% -0.94% (p=0.000 n=21+22) JSONEncode-4 13.8ms ± 1% 13.9ms ± 2% +1.14% (p=0.000 n=22+23) JSONDecode-4 47.4ms ± 1% 48.1ms ± 1% +1.49% (p=0.000 n=23+23) Mandelbrot200-4 3.92ms ± 0% 3.92ms ± 1% +0.21% (p=0.000 n=22+22) GoParse-4 2.89ms ± 1% 2.87ms ± 1% -0.68% (p=0.000 n=21+22) RegexpMatchEasy0_32-4 73.6ns ± 1% 72.0ns ± 2% -2.15% (p=0.000 n=21+22) RegexpMatchEasy0_1K-4 173ns ± 1% 173ns ± 1% ~ (p=0.847 n=22+24) RegexpMatchEasy1_32-4 71.9ns ± 1% 69.8ns ± 1% -2.99% (p=0.000 n=23+20) RegexpMatchEasy1_1K-4 314ns ± 1% 308ns ± 1% -1.91% (p=0.000 n=22+23) RegexpMatchMedium_32-4 106ns ± 0% 105ns ± 1% -0.58% (p=0.000 n=19+21) RegexpMatchMedium_1K-4 34.3µs ± 1% 34.3µs ± 1% ~ (p=0.871 n=23+22) RegexpMatchHard_32-4 1.67µs ± 1% 1.67µs ± 7% ~ (p=0.224 n=22+23) RegexpMatchHard_1K-4 51.5µs ± 1% 50.4µs ± 1% -1.99% (p=0.000 n=22+23) Revcomp-4 383ms ± 1% 415ms ± 0% +8.51% (p=0.000 n=22+22) Template-4 51.5ms ± 1% 51.5ms ± 1% ~ (p=0.555 n=20+23) TimeParse-4 279ns ± 2% 277ns ± 1% -0.95% (p=0.000 n=24+22) TimeFormat-4 294ns ± 1% 296ns ± 1% +0.58% (p=0.003 n=24+23) [Geo mean] 43.7µs 43.8µs +0.32% name old speed new speed delta GobDecode-4 134MB/s ± 1% 131MB/s ± 1% -2.32% (p=0.000 n=23+22) GobEncode-4 170MB/s ± 1% 157MB/s ± 1% -7.68% (p=0.000 n=22+22) Gzip-4 98.7MB/s ± 0% 96.1MB/s ± 1% -2.68% (p=0.000 n=23+24) Gunzip-4 590MB/s ± 7% 593MB/s ± 2% ~ (p=0.466 n=23+24) JSONEncode-4 141MB/s ± 1% 139MB/s ± 2% -1.13% (p=0.000 n=22+23) JSONDecode-4 40.9MB/s ± 1% 40.3MB/s ± 0% -1.47% (p=0.000 n=23+23) GoParse-4 20.1MB/s ± 1% 20.2MB/s ± 1% +0.69% (p=0.000 n=21+22) RegexpMatchEasy0_32-4 435MB/s ± 1% 444MB/s ± 2% +2.21% (p=0.000 n=21+22) RegexpMatchEasy0_1K-4 5.89GB/s ± 1% 5.89GB/s ± 1% ~ (p=0.439 n=22+24) RegexpMatchEasy1_32-4 445MB/s ± 1% 459MB/s ± 1% +3.06% (p=0.000 n=23+20) RegexpMatchEasy1_1K-4 3.26GB/s ± 1% 3.32GB/s ± 1% +1.97% (p=0.000 n=22+23) RegexpMatchMedium_32-4 9.40MB/s ± 1% 9.44MB/s ± 1% +0.43% (p=0.000 n=23+21) RegexpMatchMedium_1K-4 29.8MB/s ± 1% 29.8MB/s ± 1% ~ (p=0.826 n=23+22) RegexpMatchHard_32-4 19.1MB/s ± 1% 19.1MB/s ± 7% ~ (p=0.233 n=22+23) RegexpMatchHard_1K-4 19.9MB/s ± 1% 20.3MB/s ± 1% +2.03% (p=0.000 n=22+23) Revcomp-4 664MB/s ± 1% 612MB/s ± 0% -7.85% (p=0.000 n=22+22) Template-4 37.6MB/s ± 1% 37.7MB/s ± 1% ~ (p=0.558 n=20+23) [Geo mean] 134MB/s 133MB/s -0.76% Tue Mar 28 22:16:54 EDT 2017 Change-Id: I4a4f5c2b53d3fb85ef76c98522d3ed5cf8ae5b7e Reviewed-on: https://go-review.googlesource.com/38732 Reviewed-by: Russ Cox <rsc@golang.org>
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
What version of Go are you using (
go version)?What operating system and processor architecture are you using (
go env)?What did you do?
We recently upgraded our tools for data import from Go 1.7 to Go 1.8. In one of the use cases we read a large ZIP archive (33GB) and import its content (JSON documents) into database.
What did you expect to see?
No negative impact on overall performance after upgrade from Go 1.7 to Go 1.8.
What did you see instead?
Even before upgrade we experienced long pauses during GC. The rate of insert operations looked like this:
gctrace=1 output:
This is how throughput looks after upgrade to Go 1.8:
The corresponding gctrace=1 output:
Clearly, Go 1.8 minimizes GC pauses and the total time spent in GC. Unfortunately, the average throughput dropped by 60-70% due to slowdowns after GC events.
Although it's possible to mitigate this issue by setting GOGC to 10 or 20, I still wonder why Go 1.8 introduces such a weird behavior.
The text was updated successfully, but these errors were encountered: