{"action":"created","issue":{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/issues/6059","labels_url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/issues/6059/labels{/name}","comments_url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/issues/6059/comments","events_url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/issues/6059/events","html_url":"https://github.com/GoogleCloudPlatform/kubernetes/issues/6059","id":64775763,"number":6059,"title":"Scheduling & Kubelet are not responding immediately on work to do","user":{"login":"wojtek-t","id":10743879,"avatar_url":"https://avatars.githubusercontent.com/u/10743879?v=3","gravatar_id":"","url":"https://api.github.com/users/wojtek-t","html_url":"https://github.com/wojtek-t","followers_url":"https://api.github.com/users/wojtek-t/followers","following_url":"https://api.github.com/users/wojtek-t/following{/other_user}","gists_url":"https://api.github.com/users/wojtek-t/gists{/gist_id}","starred_url":"https://api.github.com/users/wojtek-t/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wojtek-t/subscriptions","organizations_url":"https://api.github.com/users/wojtek-t/orgs","repos_url":"https://api.github.com/users/wojtek-t/repos","events_url":"https://api.github.com/users/wojtek-t/events{/privacy}","received_events_url":"https://api.github.com/users/wojtek-t/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/labels/area/performance","name":"area/performance","color":"fef2c0"},{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/labels/misc/perf-1.0","name":"misc/perf-1.0","color":"006b75"},{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/labels/priority/P1","name":"priority/P1","color":"eb6420"},{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/labels/team/master","name":"team/master","color":"d2b48c"}],"state":"open","locked":false,"assignee":{"login":"wojtek-t","id":10743879,"avatar_url":"https://avatars.githubusercontent.com/u/10743879?v=3","gravatar_id":"","url":"https://api.github.com/users/wojtek-t","html_url":"https://github.com/wojtek-t","followers_url":"https://api.github.com/users/wojtek-t/followers","following_url":"https://api.github.com/users/wojtek-t/following{/other_user}","gists_url":"https://api.github.com/users/wojtek-t/gists{/gist_id}","starred_url":"https://api.github.com/users/wojtek-t/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wojtek-t/subscriptions","organizations_url":"https://api.github.com/users/wojtek-t/orgs","repos_url":"https://api.github.com/users/wojtek-t/repos","events_url":"https://api.github.com/users/wojtek-t/events{/privacy}","received_events_url":"https://api.github.com/users/wojtek-t/received_events","type":"User","site_admin":false},"milestone":{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/milestones/6","html_url":"https://github.com/GoogleCloudPlatform/kubernetes/milestones/v1.0","labels_url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/milestones/6/labels","id":969317,"number":6,"title":"v1.0","description":"Issues that need to be resolved for v1.0 of Kubernetes.","creator":{"login":"goltermann","id":9358478,"avatar_url":"https://avatars.githubusercontent.com/u/9358478?v=3","gravatar_id":"","url":"https://api.github.com/users/goltermann","html_url":"https://github.com/goltermann","followers_url":"https://api.github.com/users/goltermann/followers","following_url":"https://api.github.com/users/goltermann/following{/other_user}","gists_url":"https://api.github.com/users/goltermann/gists{/gist_id}","starred_url":"https://api.github.com/users/goltermann/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/goltermann/subscriptions","organizations_url":"https://api.github.com/users/goltermann/orgs","repos_url":"https://api.github.com/users/goltermann/repos","events_url":"https://api.github.com/users/goltermann/events{/privacy}","received_events_url":"https://api.github.com/users/goltermann/received_events","type":"User","site_admin":false},"open_issues":108,"closed_issues":147,"state":"open","created_at":"2015-02-06T20:27:16Z","updated_at":"2015-04-01T23:56:16Z","due_on":null,"closed_at":null},"comments":58,"created_at":"2015-03-27T14:39:35Z","updated_at":"2015-04-02T02:22:58Z","closed_at":null,"body":"While running performance tests (start 30 pods per node in 50 nodes cluster) I faced the following problem. \r\n\r\n1. Create replication controller and resize it to 1500. I saw the following logs:\r\nI0327 14:45:09.036772   14025 density.go:109] Controller my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39b: Found 0 pods out of 1500\r\nI0327 14:45:16.918259   14025 density.go:109] Controller my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39b: Found 835 pods out of 1500\r\nI0327 14:45:24.465116   14025 density.go:129] Controller my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39b: Found 1500 pods out of 1500\r\n\r\n2. However, looking into scheduler logs, the first time when it attempts to schedule any of those pods is related to the log:\r\nI0327 13:45:55.474005    4551 factory.go:166] About to try and schedule pod my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39bfjo6e\r\n\r\nThis is roughly ~45 seconds after the first pod was created. The question is what the scheduler was doing in the meantime - the only logs from that time are:\r\nI0327 13:40:52.230407    4551 iowatcher.go:91] Unexpected EOF during watch stream event decoding: unexpected EOF\r\nE0327 13:40:52.231778    4551 reflector.go:149] watch of *api.Service ended with error: 401: The event in requested index is outdated and cleared (the requested history has been cleared [4053/16]) [\r\n5052]\r\nI0327 13:45:53.272954    4551 iowatcher.go:91] Unexpected EOF during watch stream event decoding: unexpected EOF\r\nI0327 13:45:53.273448    4551 iowatcher.go:91] Unexpected EOF during watch stream event decoding: unexpected EOF\r\nE0327 13:45:53.277590    4551 reflector.go:149] watch of *api.Pod ended with error: 401: The event in requested index is outdated and cleared (the requested history has been cleared [12989/5082]) [1\r\n3988]\r\nE0327 13:45:53.277823    4551 reflector.go:149] watch of *api.Service ended with error: 401: The event in requested index is outdated and cleared (the requested history has been cleared [12989/5082]\r\n) [13988]\r\nI0327 13:45:55.474005    4551 factory.go:166] About to try and schedule pod my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39bfjo6e\r\n\r\n\r\nA very similar thing happened in Kubelet. During the same test, the first pod was bind to minion \"*0jxm\" at:\r\nI0327 13:46:00.291905    4551 factory.go:303] Attempting to bind my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39b7aukl to e2e-test-wojtekt-minion-0jxm.c.groovy-sentry-504.internal\r\n\r\nHowever, Kubelet reacted to it 50 seconds later:\r\nI0327 13:46:50.560684    4712 kubelet.go:1099] No Infra Container for \"my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39b7aukl_default\" found. All containers will be restarted.\r\n\r\nAgain, it seems that nothing was really happening during that 50 seconds. The Kubelet logs from that time are:\r\nI0327 13:44:55.038542    4712 server.go:654] GET /healthz: (886.441µs) 0 [[monit/5.4] 127.0.0.1:37322]\r\nE0327 13:46:43.817523    4712 reflector.go:149] watch of *api.Node ended with error: 401: The event in requested index is outdated and cleared (the requested history has been cleared [17177/7110]) [18176\r\n]\r\nI0327 13:46:46.492099    4712 iowatcher.go:91] Unexpected EOF during watch stream event decoding: unexpected EOF\r\nI0327 13:46:46.492181    4712 iowatcher.go:91] Unexpected EOF during watch stream event decoding: unexpected EOF\r\nE0327 13:46:47.256804    4712 reflector.go:149] watch of *api.Service ended with error: 401: The event in requested index is outdated and cleared (the requested history has been cleared [17354/6384]) [18\r\n353]\r\nE0327 13:46:47.256950    4712 reflector.go:149] watch of *api.Pod ended with error: 401: The event in requested index is outdated and cleared (the requested history has been cleared [17352/8087]) [18351]\r\nI0327 13:46:50.558471    4712 kubelet.go:1099] No Infra Container for \"my-hostname-density30-7bb294b4-d487-11e4-9336-a0481cabf39b8hwgv_default\" found. All containers will be restarted.\r\n...\r\n[and it works since then].\r\n\r\n\r\nInvestigate what is happening during that 45 seconds periods of \"nothing\".\r\n\r\ncc @fgrzadkowski \r\n"},"comment":{"url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/issues/comments/88700390","html_url":"https://github.com/GoogleCloudPlatform/kubernetes/issues/6059#issuecomment-88700390","issue_url":"https://api.github.com/repos/GoogleCloudPlatform/kubernetes/issues/6059","id":88700390,"user":{"login":"timothysc","id":169553,"avatar_url":"https://avatars.githubusercontent.com/u/169553?v=3","gravatar_id":"","url":"https://api.github.com/users/timothysc","html_url":"https://github.com/timothysc","followers_url":"https://api.github.com/users/timothysc/followers","following_url":"https://api.github.com/users/timothysc/following{/other_user}","gists_url":"https://api.github.com/users/timothysc/gists{/gist_id}","starred_url":"https://api.github.com/users/timothysc/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/timothysc/subscriptions","organizations_url":"https://api.github.com/users/timothysc/orgs","repos_url":"https://api.github.com/users/timothysc/repos","events_url":"https://api.github.com/users/timothysc/events{/privacy}","received_events_url":"https://api.github.com/users/timothysc/received_events","type":"User","site_admin":false},"created_at":"2015-04-02T02:22:57Z","updated_at":"2015-04-02T02:22:57Z","body":"@wojtek-t @dchen1107 - Yup we see the same characteristic behavior, the term we've coined in this scenario was \"lumpiness\" where operations will speed ahead then grind to a standstill.  We also see this during draining.  \r\n\r\nFWIW - We also noticed the large number of Node messages being passed around and their overall performance.  https://github.com/GoogleCloudPlatform/kubernetes/issues/6306   The larger the cluster the greater the load on the apiserver due to chatter. "}}