Hi Dave, Thanks for the insight. I'll look further into the heap creep. I'll also try to get together a log of a run past 8 hours over the next day or so on a machine we're not regularly restarting the go process on to see if it shows anything different.
Thanks again, Evan On Monday, 12 December 2016 14:30:45 UTC-8, Dave Cheney wrote: > > Thanks for posting this. Once your application gets to about 1600-1900mb > goal the GC pauses seem to stabilise at 3.3+3.2. It looks like the anount > of memory in use is creeping up slowly, from around 850 to 950 over the > span of the trace. GC sweep time is proportional to the size of the heap, > so this is expected. > > On Tuesday, 13 December 2016 09:20:07 UTC+11, Evan Digby wrote: >> >> Hi Dave, >> >> Thanks for the reply. Attached is the full GCTRACE for ~8 hours of run. I >> believe it shows the creep, but I'm not terribly familiar with the gctrace >> output. Something that should probably change over the next day or so! (my >> familiarity) >> >> Starts with: >> >> gc 1 @0.116s 0%: 0.079+0.69+0.23 ms clock, 0.55+0.33/1.5/0.63+1.6 ms cpu, >> 17->18->15 MB, 18 MB goal, 40 P >> gc 2 @0.117s 0%: 0.10+1.3+0.52 ms clock, 0.80+0.33/5.5/1.0+4.1 ms cpu, 16 >> ->21->20 MB, 31 MB goal, 40 P >> gc 3 @0.126s 1%: 0.083+5.3+5.5 ms clock, 1.2+0/5.9/6.3+82 ms cpu, 36->49 >> ->35 MB, 40 MB goal, 40 P >> gc 4 @0.230s 1%: 0.090+2.0+0.25 ms clock, 1.5+0.077/7.5/1.4+4.2 ms cpu, >> 39->40->24 MB, 70 MB goal, 40 P >> gc 5 @0.271s 1%: 0.065+2.9+0.24 ms clock, 1.1+0.050/20/20+4.4 ms cpu, 38 >> ->39->31 MB, 49 MB goal, 40 P >> gc 6 @0.348s 1%: 0.082+9.9+0.27 ms clock, 2.4+0.10/57/103+8.3 ms cpu, 55 >> ->56->43 MB, 62 MB goal, 40 P >> gc 7 @0.477s 1%: 0.034+17+0.26 ms clock, 1.1+0.057/85/133+8.6 ms cpu, 80 >> ->83->64 MB, 86 MB goal, 40 P >> gc 8 @0.684s 1%: 0.047+41+0.27 ms clock, 1.5+0/123/2.5+8.8 ms cpu, 122-> >> 123->79 MB, 129 MB goal, 40 P >> gc 9 @0.975s 4%: 0.004+0+37 ms clock, 0.14+0/123/2.5+1188 ms cpu, 126-> >> 126->107 MB, 126 MB goal, 40 P (forced) >> gc 10 @1.071s 4%: 0.035+61+0.26 ms clock, 1.1+17/231/563+8.4 ms cpu, 295 >> ->295->201 MB, 296 MB goal, 40 P >> >> Ends with: >> >> gc 17212 @28778.765s 3%: 3.0+117+3.7 ms clock, 96+1582/1042/546+118 ms >> cpu, 1792->1802->924 MB, 1837 MB goal, 40 P >> gc 17213 @28780.258s 3%: 2.6+119+4.1 ms clock, 83+1544/996/539+133 ms cpu >> , 1803->1815->929 MB, 1848 MB goal, 40 P >> gc 17214 @28781.711s 3%: 2.9+142+3.7 ms clock, 94+1588/1088/370+121 ms >> cpu, 1812->1825->936 MB, 1858 MB goal, 40 P >> gc 17215 @28783.094s 3%: 3.2+107+3.3 ms clock, 104+1723/1061/452+108 ms >> cpu, 1827->1838->945 MB, 1873 MB goal, 40 P >> gc 17216 @28784.500s 3%: 3.0+98+2.9 ms clock, 96+1652/943/463+95 ms cpu, >> 1844->1854->947 MB, 1891 MB goal, 40 P >> gc 17217 @28785.928s 3%: 2.7+118+3.4 ms clock, 87+1558/991/451+110 ms cpu >> , 1848->1861->948 MB, 1895 MB goal, 40 P >> gc 17218 @28787.284s 3%: 2.8+115+4.2 ms clock, 91+1588/932/461+135 ms cpu >> , 1850->1862->960 MB, 1897 MB goal, 40 P >> gc 17219 @28788.667s 3%: 3.1+116+3.3 ms clock, 100+1421/1101/466+107 ms >> cpu, 1873->1888->961 MB, 1921 MB goal, 40 P >> gc 17220 @28790.059s 3%: 3.0+112+3.4 ms clock, 96+1663/1065/505+109 ms >> cpu, 1876->1888->967 MB, 1923 MB goal, 40 P >> gc 17221 @28791.435s 3%: 3.3+99+3.2 ms clock, 105+1685/986/420+104 ms cpu >> , 1886->1897->968 MB, 1934 MB goal, 40 P >> >> >> Thank you! >> >> Evan >> >> On Monday, 12 December 2016 13:42:32 UTC-8, Dave Cheney wrote: >>> >>> Can you try turning on GODEBUG=gctrace=1 and confirming that the pause >>> times are increasing. If you could post the entire output that would be >>> most helpful. >>> >>> Thanks >>> >>> Dave >>> >>> -- You received this message because you are subscribed to the Google Groups "golang-nuts" group. To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
