Hello, The backend of my web server (written in Go) have recently started consuming large amounts of CPU. AFAICT, the CPU seems to be consumed by the garbage collector and I would appreciate any information that would help me track down the root cause.
When I run the web server with gctrace=1, I see the following trace: gc 1 @6.033s 0%: 0.096+0.92+0.053 ms clock, 0.19+0.056/0.51/0.89+0.10 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 2 @19.072s 0%: 0.010+0.89+0.043 ms clock, 0.021+0.015/0.55/0.67+0.086 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 3 @32.111s 0%: 0.031+0.95+0.051 ms clock, 0.062+0/0.80/0.38+0.10 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 4 @45.151s 0%: 0.098+0.80+0.28 ms clock, 0.19+0/0.44/0.77+0.57 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 5 @58.193s 0%: 0.010+1.1+0.045 ms clock, 0.020+0.050/0.33/1.0+0.090 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 6 @71.235s 0%: 0.026+0.73+0.056 ms clock, 0.053+0/0.72/0.42+0.11 ms cpu, 4->4->0 MB, 5 MB goal, 2 P In particular, garbage collection happens every 10-15 seconds. Now when I use a browser to navigate to a page that triggers the odd behavior, I see the following trace: gc 7640 @187.367s 1%: 0.007+0.66+0.23 ms clock, 0.014+0.008/0.35/0.62+0.47 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7641 @187.376s 1%: 0.007+0.56+0.23 ms clock, 0.014+0.008/0.46/0.53+0.46 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7642 @187.386s 1%: 0.008+0.63+0.24 ms clock, 0.016+0.008/0.59/0.35+0.49 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7643 @187.395s 1%: 0.008+0.61+0.28 ms clock, 0.016+0.009/0.37/0.58+0.56 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7644 @187.405s 1%: 0.009+0.55+0.030 ms clock, 0.018+0.009/0.46/0.52+0.060 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7645 @187.414s 2%: 0.008+0.56+0.25 ms clock, 0.017+0.008/0.47/0.52+0.51 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7646 @187.424s 2%: 0.008+0.69+0.017 ms clock, 0.016+0.008/0.66/0.36+0.034 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7647 @187.433s 2%: 0.008+0.61+0.018 ms clock, 0.017+0.008/0.35/0.60+0.037 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7648 @187.442s 2%: 0.008+0.67+0.26 ms clock, 0.017+0.008/0.65/0.38+0.52 ms cpu, 4->4->0 MB, 5 MB goal, 2 P gc 7649 @187.452s 2%: 0.008+0.65+0.24 ms clock, 0.016+0.008/0.36/0.61+0.48 ms cpu, 4->4->0 MB, 5 MB goal, 2 P In particular, garbage collection happens every 10 ms. The page that triggers this behavior periodically fetches and displays some in-memory state from the backend and the excessive GC behavior continues even after the page that triggers the behavior is closed. I should add that the web server backend has multiple goroutines running in the background performing periodic activity, but none of the background activity is triggered or influenced by the incoming HTTP request for the culprit page. Any suggestions as to what steps I can take to investigate this problem further would be greatly appreciated. I am happy to provide more details about the implementation of the web server but I am not sure what else could be relevant. Cheers, -- 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.
