{"action":"created","issue":{"url":"https://api.github.com/repos/golang/go/issues/29287","repository_url":"https://api.github.com/repos/golang/go","labels_url":"https://api.github.com/repos/golang/go/issues/29287/labels{/name}","comments_url":"https://api.github.com/repos/golang/go/issues/29287/comments","events_url":"https://api.github.com/repos/golang/go/issues/29287/events","html_url":"https://github.com/golang/go/issues/29287","id":391415732,"node_id":"MDU6SXNzdWUzOTE0MTU3MzI=","number":29287,"title":"runtime: Livelock in mallocgc","user":{"login":"ewhamilton","id":37344508,"node_id":"MDQ6VXNlcjM3MzQ0NTA4","avatar_url":"https://avatars0.githubusercontent.com/u/37344508?v=4","gravatar_id":"","url":"https://api.github.com/users/ewhamilton","html_url":"https://github.com/ewhamilton","followers_url":"https://api.github.com/users/ewhamilton/followers","following_url":"https://api.github.com/users/ewhamilton/following{/other_user}","gists_url":"https://api.github.com/users/ewhamilton/gists{/gist_id}","starred_url":"https://api.github.com/users/ewhamilton/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ewhamilton/subscriptions","organizations_url":"https://api.github.com/users/ewhamilton/orgs","repos_url":"https://api.github.com/users/ewhamilton/repos","events_url":"https://api.github.com/users/ewhamilton/events{/privacy}","received_events_url":"https://api.github.com/users/ewhamilton/received_events","type":"User","site_admin":false},"labels":[{"id":373402289,"node_id":"MDU6TGFiZWwzNzM0MDIyODk=","url":"https://api.github.com/repos/golang/go/labels/NeedsInvestigation","name":"NeedsInvestigation","color":"ededed","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":5,"created_at":"2018-12-15T22:07:30Z","updated_at":"2018-12-19T20:19:41Z","closed_at":null,"author_association":"NONE","body":"<!-- Please answer these questions before submitting your issue. Thanks! -->\r\n\r\n### What version of Go are you using (`go version`)?\r\n\r\n<pre>\r\nroot@cb464ce07cbb:/repo# go version\r\ngo version go1.11.1 linux/amd64\r\n</pre>\r\n\r\n### Does this issue reproduce with the latest release?\r\nThis is latest major release.  Haven't tried latest minor release yet.\r\n\r\n\r\n### What operating system and processor architecture are you using (`go env`)?\r\n\r\n<details><summary><code>go env</code> Output</summary><br><pre>\r\nNote: Below is go env from container build environment.  Repro is within a Docker container in a Kubernetes deployment with NumCPU=1 and GOMAXPROCS=4 (also seen when GOMAXPROCS defaults to 1).\r\nroot@cb464ce07cbb:/repo# go env\r\nGOARCH=\"amd64\"\r\nGOBIN=\"\"\r\nGOCACHE=\"/root/.cache/go-build\"\r\nGOEXE=\"\"\r\nGOFLAGS=\"\"\r\nGOHOSTARCH=\"amd64\"\r\nGOHOSTOS=\"linux\"\r\nGOOS=\"linux\"\r\nGOPATH=\"/repo/go:/k10/go\"\r\nGOPROXY=\"\"\r\nGORACE=\"\"\r\nGOROOT=\"/usr/local/go\"\r\nGOTMPDIR=\"\"\r\nGOTOOLDIR=\"/usr/local/go/pkg/tool/linux_amd64\"\r\nGCCGO=\"gccgo\"\r\nCC=\"gcc\"\r\nCXX=\"g++\"\r\nCGO_ENABLED=\"1\"\r\nGOMOD=\"\"\r\nCGO_CFLAGS=\"-g -O2\"\r\nCGO_CPPFLAGS=\"\"\r\nCGO_CXXFLAGS=\"-g -O2\"\r\nCGO_FFLAGS=\"-g -O2\"\r\nCGO_LDFLAGS=\"-g -O2\"\r\nPKG_CONFIG=\"pkg-config\"\r\nGOGCCFLAGS=\"-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build291547819=/tmp/go-build -gno-record-gcc-switches\"\r\n</pre></details>\r\n\r\n### What did you do?\r\n\r\n<!--\r\nIf possible, provide a recipe for reproducing the error.\r\nA complete runnable program is good.\r\nA link on play.golang.org is best.\r\n-->\r\nI have captured a trace of our application in which a goroutine calling mallocgc() stalls and blocks subsequent STW requests from GC.  This sounds similar to #28695 but it happens more frequently (often but not always on on workload). Sorry, I don't have a simple test case that repros though there are only a few goroutines involved at the time of failure.\r\n\r\nThe mallocgc was a result of a library allocating an 8MB buffer with `make([]byte, 0, 8 * 1024 * 1024)`. From my reading of runtime code it is headed down the largealloc path, perhaps hitting deductSweepCredit() and the sweeping done in alloc_m().\r\n\r\nI hope that the trace is sufficient to identify the issue.  At the time of the trace I was also collecting logs for GODEBUG=schedtrace=1000,scheddetail=1,gctrace=1,gcpacertrace=1.  Neither the trace nor the logs show any sign of a goroutine not preempting while in user code.\r\n\r\nTrace file is  \r\n[tracefile.23-50-04.gz](https://github.com/golang/go/files/2683100/tracefile.23-50-04.gz)\r\n\r\nLog file is \r\n[trace.log](https://github.com/golang/go/files/2683102/trace.log)\r\n\r\nMore background is at https://groups.google.com/forum/#!topic/golang-nuts/g2gDf12y-Fo\r\n\r\n### What did you expect to see?\r\nExpected timely allocation and garbage collection such that Kubernetes health checks every 10 seconds do not fail repeatedly.\r\n\r\n\r\n### What did you see instead?\r\nApplication hung, stopped responding to health check requests, and after over 30 seconds of STW was sent SIGTERM as part of restarting app.  Observed that the SIGTERM appeared to break out of the livelock, but by then it was too late.\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/golang/go/issues/comments/448730682","html_url":"https://github.com/golang/go/issues/29287#issuecomment-448730682","issue_url":"https://api.github.com/repos/golang/go/issues/29287","id":448730682,"node_id":"MDEyOklzc3VlQ29tbWVudDQ0ODczMDY4Mg==","user":{"login":"mknyszek","id":1248668,"node_id":"MDQ6VXNlcjEyNDg2Njg=","avatar_url":"https://avatars1.githubusercontent.com/u/1248668?v=4","gravatar_id":"","url":"https://api.github.com/users/mknyszek","html_url":"https://github.com/mknyszek","followers_url":"https://api.github.com/users/mknyszek/followers","following_url":"https://api.github.com/users/mknyszek/following{/other_user}","gists_url":"https://api.github.com/users/mknyszek/gists{/gist_id}","starred_url":"https://api.github.com/users/mknyszek/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mknyszek/subscriptions","organizations_url":"https://api.github.com/users/mknyszek/orgs","repos_url":"https://api.github.com/users/mknyszek/repos","events_url":"https://api.github.com/users/mknyszek/events{/privacy}","received_events_url":"https://api.github.com/users/mknyszek/received_events","type":"User","site_admin":false},"created_at":"2018-12-19T20:19:41Z","updated_at":"2018-12-19T20:19:41Z","author_association":"CONTRIBUTOR","body":"That's very weird. And as you point out, the amount of CPU profiling samples is super super low. Assuming you haven't changed the profiling rate, then there's the potential that that goroutine _is_ in fact blocked on a runtime lock for a long time. That would be very bad and in fact a runtime issue.\r\n\r\nCould you please:\r\n1. send your program a SIGQUIT instead of a SIGTERM (and don't handle the SIGQUIT), and\r\n2. set GOTRACEBACK=crash when running your Go binary?\r\n\r\nThis way the program will dump a stack trace of every goroutine that's running and we can see exactly what it's blocked on.\r\n\r\nThank you so much for your help thus far! :)"}}
{"actor":{"display_login":"mknyszek"}}