Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tidb-scheduler: implement kube-scheduler extender preempt verb #2510

Merged
merged 4 commits into from
May 25, 2020

Conversation

cofyc
Copy link
Contributor

@cofyc cofyc commented May 20, 2020

What problem does this PR solve?

fixes #1968

What is changed and how does it work?

Check List

Tests

  • Unit test
  • E2E test
  • Stability test
  • Manual test (add detailed scripts or steps below)
  • No code

Code changes

  • Has Go code change
  • Has CI related scripts change
  • Has Terraform scripts change

Side effects

  • Breaking backward compatibility

Related changes

  • Need to cherry-pick to the release branch
  • Need to update the documentation

Does this PR introduce a user-facing change?:

Support preemption in `tidb-scheduler`

@cofyc cofyc changed the title WIP: Implement kube-scheduler extender preempt verb WIP: tidb-scheduler: implement kube-scheduler extender preempt verb May 20, 2020
@cofyc cofyc force-pushed the fix1968 branch 2 times, most recently from 5a9d0c4 to 2cf3f8c Compare May 21, 2020 07:29
@cofyc cofyc changed the title WIP: tidb-scheduler: implement kube-scheduler extender preempt verb tidb-scheduler: implement kube-scheduler extender preempt verb May 21, 2020
@cofyc cofyc force-pushed the fix1968 branch 3 times, most recently from dd41099 to 6e274a7 Compare May 21, 2020 12:44
@cofyc
Copy link
Contributor Author

cofyc commented May 21, 2020

/run-e2e-tests

@cofyc
Copy link
Contributor Author

cofyc commented May 21, 2020

cc @mightyguava
I've added preemption support for the tidb-scheduler. Now invalid nodes that won't pass predicates of tidb-scheduler in the filter phase will not be chosen in the preemption phase.

can you try this patch in your test environment? here are instructions on how to build a custom image:

git clone https://github.com/pingcap/tidb-operator.git
git checkout -b cofyc-fix1968 master
git pull https://github.com/cofyc/tidb-operator.git fix1968
make docker
docker tag localhost:5000/pingcap/tidb-operator:latest <your-repo>/<image>:<tag>
docker push <your-repo>/<image>:<tag>

then you can update the tidb-operator image of tidb-scheduler deployment.

@mightyguava
Copy link
Contributor

I'm still not seeing the low priority pods get preempted. Here are the logs from the current run.

tidb-scheduler.log
I0521 17:19:26.288441       1 version.go:38] Welcome to TiDB Operator.
I0521 17:19:26.288502       1 version.go:39] TiDB Operator Version: version.Info{GitVersion:"v1.1.0-beta.1.334+6e274a7576d106", GitCommit:"6e274a7576d106c6631bfd9b6b240772118b34b8", GitTreeState:"clean", BuildDate:"2020-05-21T16:50:05Z", GoVersion:"go1.13.8", Compiler:"gc", Platform:"linux/amd64"}
I0521 17:19:26.288550       1 main.go:58] FLAG: --V="false"
I0521 17:19:26.288560       1 main.go:58] FLAG: --add_dir_header="false"
I0521 17:19:26.288564       1 main.go:58] FLAG: --alsologtostderr="false"
I0521 17:19:26.288567       1 main.go:58] FLAG: --features="AdvancedStatefulSet=false,AutoScaling=false,StableScheduling=true"
I0521 17:19:26.288580       1 main.go:58] FLAG: --log_backtrace_at=":0"
I0521 17:19:26.288585       1 main.go:58] FLAG: --log_dir=""
I0521 17:19:26.288589       1 main.go:58] FLAG: --log_file=""
I0521 17:19:26.288591       1 main.go:58] FLAG: --log_file_max_size="1800"
I0521 17:19:26.288595       1 main.go:58] FLAG: --logtostderr="true"
I0521 17:19:26.288598       1 main.go:58] FLAG: --port="10262"
I0521 17:19:26.288602       1 main.go:58] FLAG: --skip_headers="false"
I0521 17:19:26.288604       1 main.go:58] FLAG: --skip_log_headers="false"
I0521 17:19:26.288607       1 main.go:58] FLAG: --stderrthreshold="2"
I0521 17:19:26.288611       1 main.go:58] FLAG: --v="2"
I0521 17:19:26.288615       1 main.go:58] FLAG: --version="false"
I0521 17:19:26.288618       1 main.go:58] FLAG: --vmodule=""
I0521 17:19:26.289615       1 mux.go:66] start scheduler extender server, listening on 0.0.0.0:10262
I0521 17:19:52.856046       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-2
I0521 17:19:52.856068       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:19:52.890811       1 ha.go:121] ha: tidbcluster yunchi-test-tidb/tidb component pd replicas 3
I0521 17:19:52.890828       1 ha.go:129] current topology key: kubernetes.io/hostname
I0521 17:19:52.890835       1 ha.go:146] pod tidb-pd-1 is not bind
I0521 17:19:52.890839       1 ha.go:146] pod tidb-pd-2 is not bind
I0521 17:19:52.890844       1 ha.go:208] topology ip-10-136-135-87.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0521 17:19:52.890852       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:19:52.890991       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-2", UID:"d9d0b2b6-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275374", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-135-87.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0521 17:19:52.980836       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-1
I0521 17:19:52.980855       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:19:52.994367       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:19:52.994490       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-1", UID:"d9cd9682-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275357", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod yunchi-test-tidb/tidb-pd-2 scheduling
I0521 17:20:08.285012       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-2
I0521 17:20:08.285029       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:20:08.305413       1 ha.go:121] ha: tidbcluster yunchi-test-tidb/tidb component pd replicas 3
I0521 17:20:08.305430       1 ha.go:129] current topology key: kubernetes.io/hostname
I0521 17:20:08.305437       1 ha.go:146] pod tidb-pd-1 is not bind
I0521 17:20:08.305441       1 ha.go:146] pod tidb-pd-2 is not bind
I0521 17:20:08.305447       1 ha.go:208] topology ip-10-136-135-87.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0521 17:20:08.305455       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:20:08.305564       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-2", UID:"d9d0b2b6-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275374", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-135-87.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0521 17:20:08.394030       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-1
I0521 17:20:08.394061       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:20:08.402724       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:20:08.402904       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-1", UID:"d9cd9682-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275357", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod yunchi-test-tidb/tidb-pd-2 scheduling
I0521 17:20:25.591837       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-2
I0521 17:20:25.591858       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:20:25.608999       1 ha.go:121] ha: tidbcluster yunchi-test-tidb/tidb component pd replicas 3
I0521 17:20:25.609016       1 ha.go:129] current topology key: kubernetes.io/hostname
I0521 17:20:25.609026       1 ha.go:146] pod tidb-pd-1 is not bind
I0521 17:20:25.609029       1 ha.go:146] pod tidb-pd-2 is not bind
I0521 17:20:25.609035       1 ha.go:208] topology ip-10-136-135-87.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0521 17:20:25.609043       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:20:25.609166       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-2", UID:"d9d0b2b6-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275374", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-135-87.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0521 17:20:25.693983       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-1
I0521 17:20:25.694007       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:20:25.702555       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:20:25.702672       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-1", UID:"d9cd9682-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275357", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod yunchi-test-tidb/tidb-pd-2 scheduling
I0521 17:20:58.961399       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-2
I0521 17:20:58.961417       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:20:58.986410       1 ha.go:121] ha: tidbcluster yunchi-test-tidb/tidb component pd replicas 3
I0521 17:20:58.986424       1 ha.go:129] current topology key: kubernetes.io/hostname
I0521 17:20:58.986433       1 ha.go:146] pod tidb-pd-1 is not bind
I0521 17:20:58.986437       1 ha.go:146] pod tidb-pd-2 is not bind
I0521 17:20:58.986442       1 ha.go:208] topology ip-10-136-135-87.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0521 17:20:58.986450       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:20:58.986561       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-2", UID:"d9d0b2b6-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275374", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-135-87.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0521 17:20:59.010789       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-1
I0521 17:20:59.010802       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:20:59.018847       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:20:59.018925       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-1", UID:"d9cd9682-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275357", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod yunchi-test-tidb/tidb-pd-2 scheduling
I0521 17:22:02.306472       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-2
I0521 17:22:02.306494       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:22:02.323857       1 ha.go:121] ha: tidbcluster yunchi-test-tidb/tidb component pd replicas 3
I0521 17:22:02.323871       1 ha.go:129] current topology key: kubernetes.io/hostname
I0521 17:22:02.323878       1 ha.go:146] pod tidb-pd-1 is not bind
I0521 17:22:02.323882       1 ha.go:146] pod tidb-pd-2 is not bind
I0521 17:22:02.323890       1 ha.go:208] topology ip-10-136-135-87.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0521 17:22:02.323900       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:22:02.324000       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-2", UID:"d9d0b2b6-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275374", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-135-87.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0521 17:22:02.393544       1 scheduler.go:124] scheduling pod: yunchi-test-tidb/tidb-pd-1
I0521 17:22:02.393560       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-135-87.us-west-2.compute.internal]
I0521 17:22:02.402296       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0521 17:22:02.402395       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"yunchi-test-tidb", Name:"tidb-pd-1", UID:"d9cd9682-9b86-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802275357", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod yunchi-test-tidb/tidb-pd-2 scheduling
kube-scheduler.log
I0521 17:19:28.390469       1 flags.go:33] FLAG: --address="0.0.0.0"
I0521 17:19:28.390502       1 flags.go:33] FLAG: --algorithm-provider=""
I0521 17:19:28.390505       1 flags.go:33] FLAG: --alsologtostderr="false"
I0521 17:19:28.390509       1 flags.go:33] FLAG: --authentication-kubeconfig=""
I0521 17:19:28.390512       1 flags.go:33] FLAG: --authentication-skip-lookup="false"
I0521 17:19:28.390520       1 flags.go:33] FLAG: --authentication-token-webhook-cache-ttl="10s"
I0521 17:19:28.390524       1 flags.go:33] FLAG: --authentication-tolerate-lookup-failure="true"
I0521 17:19:28.390527       1 flags.go:33] FLAG: --authorization-always-allow-paths="[/healthz]"
I0521 17:19:28.390533       1 flags.go:33] FLAG: --authorization-kubeconfig=""
I0521 17:19:28.390536       1 flags.go:33] FLAG: --authorization-webhook-cache-authorized-ttl="10s"
I0521 17:19:28.390539       1 flags.go:33] FLAG: --authorization-webhook-cache-unauthorized-ttl="10s"
I0521 17:19:28.390542       1 flags.go:33] FLAG: --bind-address="0.0.0.0"
I0521 17:19:28.390547       1 flags.go:33] FLAG: --cert-dir=""
I0521 17:19:28.390550       1 flags.go:33] FLAG: --client-ca-file=""
I0521 17:19:28.390552       1 flags.go:33] FLAG: --config=""
I0521 17:19:28.390555       1 flags.go:33] FLAG: --contention-profiling="false"
I0521 17:19:28.390558       1 flags.go:33] FLAG: --failure-domains="kubernetes.io/hostname,failure-domain.beta.kubernetes.io/zone,failure-domain.beta.kubernetes.io/region"
I0521 17:19:28.390568       1 flags.go:33] FLAG: --feature-gates=""
I0521 17:19:28.390576       1 flags.go:33] FLAG: --hard-pod-affinity-symmetric-weight="1"
I0521 17:19:28.390580       1 flags.go:33] FLAG: --help="false"
I0521 17:19:28.390583       1 flags.go:33] FLAG: --http2-max-streams-per-connection="0"
I0521 17:19:28.390586       1 flags.go:33] FLAG: --kube-api-burst="100"
I0521 17:19:28.390589       1 flags.go:33] FLAG: --kube-api-content-type="application/vnd.kubernetes.protobuf"
I0521 17:19:28.390593       1 flags.go:33] FLAG: --kube-api-qps="50"
I0521 17:19:28.390597       1 flags.go:33] FLAG: --kubeconfig=""
I0521 17:19:28.390600       1 flags.go:33] FLAG: --leader-elect="true"
I0521 17:19:28.390602       1 flags.go:33] FLAG: --leader-elect-lease-duration="15s"
I0521 17:19:28.390605       1 flags.go:33] FLAG: --leader-elect-renew-deadline="10s"
I0521 17:19:28.390609       1 flags.go:33] FLAG: --leader-elect-resource-lock="endpoints"
I0521 17:19:28.390611       1 flags.go:33] FLAG: --leader-elect-retry-period="2s"
I0521 17:19:28.390614       1 flags.go:33] FLAG: --lock-object-name="tidb-scheduler"
I0521 17:19:28.390617       1 flags.go:33] FLAG: --lock-object-namespace="tidb-operator"
I0521 17:19:28.390620       1 flags.go:33] FLAG: --log-backtrace-at=":0"
I0521 17:19:28.390625       1 flags.go:33] FLAG: --log-dir=""
I0521 17:19:28.390628       1 flags.go:33] FLAG: --log-file=""
I0521 17:19:28.390631       1 flags.go:33] FLAG: --log-flush-frequency="5s"
I0521 17:19:28.390634       1 flags.go:33] FLAG: --logtostderr="true"
I0521 17:19:28.390636       1 flags.go:33] FLAG: --master=""
I0521 17:19:28.390639       1 flags.go:33] FLAG: --policy-config-file=""
I0521 17:19:28.390642       1 flags.go:33] FLAG: --policy-configmap="tidb-scheduler-policy"
I0521 17:19:28.390645       1 flags.go:33] FLAG: --policy-configmap-namespace="tidb-operator"
I0521 17:19:28.390648       1 flags.go:33] FLAG: --port="10261"
I0521 17:19:28.390651       1 flags.go:33] FLAG: --profiling="false"
I0521 17:19:28.390654       1 flags.go:33] FLAG: --requestheader-allowed-names="[]"
I0521 17:19:28.390658       1 flags.go:33] FLAG: --requestheader-client-ca-file=""
I0521 17:19:28.390660       1 flags.go:33] FLAG: --requestheader-extra-headers-prefix="[x-remote-extra-]"
I0521 17:19:28.390668       1 flags.go:33] FLAG: --requestheader-group-headers="[x-remote-group]"
I0521 17:19:28.390672       1 flags.go:33] FLAG: --requestheader-username-headers="[x-remote-user]"
I0521 17:19:28.390677       1 flags.go:33] FLAG: --scheduler-name="tidb-scheduler"
I0521 17:19:28.390680       1 flags.go:33] FLAG: --secure-port="10259"
I0521 17:19:28.390682       1 flags.go:33] FLAG: --skip-headers="false"
I0521 17:19:28.390685       1 flags.go:33] FLAG: --stderrthreshold="2"
I0521 17:19:28.390688       1 flags.go:33] FLAG: --tls-cert-file=""
I0521 17:19:28.390691       1 flags.go:33] FLAG: --tls-cipher-suites="[]"
I0521 17:19:28.390694       1 flags.go:33] FLAG: --tls-min-version=""
I0521 17:19:28.390697       1 flags.go:33] FLAG: --tls-private-key-file=""
I0521 17:19:28.390700       1 flags.go:33] FLAG: --tls-sni-cert-key="[]"
I0521 17:19:28.390705       1 flags.go:33] FLAG: --use-legacy-policy-config="false"
I0521 17:19:28.390707       1 flags.go:33] FLAG: --v="4"
I0521 17:19:28.390710       1 flags.go:33] FLAG: --version="false"
I0521 17:19:28.390714       1 flags.go:33] FLAG: --vmodule=""
I0521 17:19:28.390717       1 flags.go:33] FLAG: --write-config-to=""
I0521 17:19:29.988846       1 serving.go:319] Generated self-signed cert in-memory
W0521 17:19:32.296195       1 options.go:300] Neither --kubeconfig nor --master was specified. Using default API client. This might not work.
I0521 17:19:32.296278       1 merged_client_builder.go:122] Using in-cluster configuration
I0521 17:19:32.297904       1 server.go:142] Version: v1.14.9
I0521 17:19:32.297943       1 defaults.go:87] TaintNodesByCondition is enabled, PodToleratesNodeTaints predicate is mandatory
I0521 17:19:32.297950       1 server.go:161] Starting Kubernetes Scheduler version v1.14.9
I0521 17:19:32.379126       1 factory.go:341] Creating scheduler from configuration: {{ } [{NoVolumeZoneConflict <nil>} {MaxEBSVolumeCount <nil>} {MaxAzureDiskVolumeCount <nil>} {NoDiskConflict <nil>} {GeneralPredicates <nil>} {PodToleratesNodeTaints <nil>} {CheckVolumeBinding <nil>} {MaxGCEPDVolumeCount <nil>} {MatchInterPodAffinity <nil>} {CheckVolumeBinding <nil>}] [{SelectorSpreadPriority 1 <nil>} {InterPodAffinityPriority 1 <nil>} {LeastRequestedPriority 1 <nil>} {BalancedResourceAllocation 1 <nil>} {NodePreferAvoidPodsPriority 1 <nil>} {NodeAffinityPriority 1 <nil>} {TaintTolerationPriority 1 <nil>}] [{http://127.0.0.1:10262/scheduler filter   1  false <nil> 30s false [] false}] 0 false}
I0521 17:19:32.379178       1 factory.go:358] Registering predicate: NoVolumeZoneConflict
I0521 17:19:32.379187       1 plugins.go:236] Predicate type NoVolumeZoneConflict already registered, reusing.
I0521 17:19:32.379194       1 factory.go:358] Registering predicate: MaxEBSVolumeCount
I0521 17:19:32.379198       1 plugins.go:236] Predicate type MaxEBSVolumeCount already registered, reusing.
I0521 17:19:32.379203       1 factory.go:358] Registering predicate: MaxAzureDiskVolumeCount
I0521 17:19:32.379207       1 plugins.go:236] Predicate type MaxAzureDiskVolumeCount already registered, reusing.
I0521 17:19:32.379212       1 factory.go:358] Registering predicate: NoDiskConflict
I0521 17:19:32.379217       1 plugins.go:236] Predicate type NoDiskConflict already registered, reusing.
I0521 17:19:32.379222       1 factory.go:358] Registering predicate: GeneralPredicates
I0521 17:19:32.379227       1 plugins.go:236] Predicate type GeneralPredicates already registered, reusing.
I0521 17:19:32.379232       1 factory.go:358] Registering predicate: PodToleratesNodeTaints
I0521 17:19:32.379237       1 plugins.go:236] Predicate type PodToleratesNodeTaints already registered, reusing.
I0521 17:19:32.379241       1 factory.go:358] Registering predicate: CheckVolumeBinding
I0521 17:19:32.379246       1 plugins.go:236] Predicate type CheckVolumeBinding already registered, reusing.
I0521 17:19:32.379251       1 factory.go:358] Registering predicate: MaxGCEPDVolumeCount
I0521 17:19:32.379256       1 plugins.go:236] Predicate type MaxGCEPDVolumeCount already registered, reusing.
I0521 17:19:32.379261       1 factory.go:358] Registering predicate: MatchInterPodAffinity
I0521 17:19:32.379266       1 plugins.go:236] Predicate type MatchInterPodAffinity already registered, reusing.
I0521 17:19:32.379274       1 factory.go:358] Registering predicate: CheckVolumeBinding
I0521 17:19:32.379281       1 plugins.go:236] Predicate type CheckVolumeBinding already registered, reusing.
I0521 17:19:32.379288       1 factory.go:373] Registering priority: SelectorSpreadPriority
I0521 17:19:32.379296       1 plugins.go:348] Priority type SelectorSpreadPriority already registered, reusing.
I0521 17:19:32.379324       1 factory.go:373] Registering priority: InterPodAffinityPriority
I0521 17:19:32.379333       1 plugins.go:348] Priority type InterPodAffinityPriority already registered, reusing.
I0521 17:19:32.379341       1 factory.go:373] Registering priority: LeastRequestedPriority
I0521 17:19:32.379347       1 plugins.go:348] Priority type LeastRequestedPriority already registered, reusing.
I0521 17:19:32.379355       1 factory.go:373] Registering priority: BalancedResourceAllocation
I0521 17:19:32.379364       1 plugins.go:348] Priority type BalancedResourceAllocation already registered, reusing.
I0521 17:19:32.379372       1 factory.go:373] Registering priority: NodePreferAvoidPodsPriority
I0521 17:19:32.379377       1 plugins.go:348] Priority type NodePreferAvoidPodsPriority already registered, reusing.
I0521 17:19:32.379385       1 factory.go:373] Registering priority: NodeAffinityPriority
I0521 17:19:32.379395       1 plugins.go:348] Priority type NodeAffinityPriority already registered, reusing.
I0521 17:19:32.379403       1 factory.go:373] Registering priority: TaintTolerationPriority
I0521 17:19:32.379408       1 plugins.go:348] Priority type TaintTolerationPriority already registered, reusing.
I0521 17:19:32.379417       1 factory.go:382] Creating extender with config {URLPrefix:http://127.0.0.1:10262/scheduler FilterVerb:filter PreemptVerb: PrioritizeVerb: Weight:1 BindVerb: EnableHTTPS:false TLSConfig:<nil> HTTPTimeout:30s NodeCacheCapable:false ManagedResources:[] Ignorable:false}
I0521 17:19:32.379449       1 factory.go:412] Creating scheduler with fit predicates 'map[CheckVolumeBinding:{} GeneralPredicates:{} MatchInterPodAffinity:{} MaxAzureDiskVolumeCount:{} MaxEBSVolumeCount:{} MaxGCEPDVolumeCount:{} NoDiskConflict:{} NoVolumeZoneConflict:{} PodToleratesNodeTaints:{}]' and priority functions 'map[BalancedResourceAllocation:{} InterPodAffinityPriority:{} LeastRequestedPriority:{} NodeAffinityPriority:{} NodePreferAvoidPodsPriority:{} SelectorSpreadPriority:{} TaintTolerationPriority:{}]'
W0521 17:19:32.380078       1 authorization.go:47] Authorization is disabled
W0521 17:19:32.380090       1 authentication.go:55] Authentication is disabled
I0521 17:19:32.380100       1 deprecated_insecure_serving.go:49] Serving healthz insecurely on [::]:10261
I0521 17:19:32.380439       1 secure_serving.go:116] Serving securely on [::]:10259
I0521 17:19:32.380685       1 reflector.go:123] Starting reflector *v1.Pod (0s) from k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:223
I0521 17:19:32.380705       1 reflector.go:161] Listing and watching *v1.Pod from k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:223
I0521 17:19:32.380763       1 reflector.go:123] Starting reflector *v1.PersistentVolumeClaim (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.380781       1 reflector.go:161] Listing and watching *v1.PersistentVolumeClaim from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.380852       1 reflector.go:123] Starting reflector *v1beta1.PodDisruptionBudget (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.380874       1 reflector.go:161] Listing and watching *v1beta1.PodDisruptionBudget from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381284       1 reflector.go:123] Starting reflector *v1.Service (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381306       1 reflector.go:161] Listing and watching *v1.Service from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381363       1 reflector.go:123] Starting reflector *v1.Node (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381366       1 reflector.go:123] Starting reflector *v1.ReplicationController (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381392       1 reflector.go:161] Listing and watching *v1.Node from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381397       1 reflector.go:161] Listing and watching *v1.ReplicationController from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381398       1 reflector.go:123] Starting reflector *v1.ReplicaSet (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381375       1 reflector.go:123] Starting reflector *v1.StorageClass (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381423       1 reflector.go:123] Starting reflector *v1.StatefulSet (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381447       1 reflector.go:161] Listing and watching *v1.StatefulSet from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381427       1 reflector.go:161] Listing and watching *v1.StorageClass from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381422       1 reflector.go:123] Starting reflector *v1.PersistentVolume (0s) from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381514       1 reflector.go:161] Listing and watching *v1.PersistentVolume from k8s.io/client-go/informers/factory.go:133
I0521 17:19:32.381419       1 reflector.go:161] Listing and watching *v1.ReplicaSet from k8s.io/client-go/informers/factory.go:133
I0521 17:19:33.180738       1 shared_informer.go:123] caches populated
I0521 17:19:33.280897       1 shared_informer.go:123] caches populated
I0521 17:19:34.481073       1 shared_informer.go:123] caches populated
I0521 17:19:34.581214       1 shared_informer.go:123] caches populated
I0521 17:19:34.681350       1 shared_informer.go:123] caches populated
I0521 17:19:34.781512       1 shared_informer.go:123] caches populated
I0521 17:19:34.881629       1 shared_informer.go:123] caches populated
I0521 17:19:34.981779       1 shared_informer.go:123] caches populated
I0521 17:19:35.081893       1 shared_informer.go:123] caches populated
I0521 17:19:35.081928       1 controller_utils.go:1027] Waiting for caches to sync for scheduler controller
I0521 17:19:35.182054       1 shared_informer.go:123] caches populated
I0521 17:19:35.182072       1 controller_utils.go:1034] Caches are synced for scheduler controller
I0521 17:19:35.182159       1 leaderelection.go:217] attempting to acquire leader lease  tidb-operator/tidb-scheduler...
I0521 17:19:35.187442       1 leaderelection.go:326] lock is held by tidb-scheduler-5585ccbc7f-hxbd2_621c7166-9b85-11ea-ae7c-0227f9bd39d5 and has not yet expired
I0521 17:19:35.187457       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0521 17:19:37.408949       1 leaderelection.go:326] lock is held by tidb-scheduler-5585ccbc7f-hxbd2_621c7166-9b85-11ea-ae7c-0227f9bd39d5 and has not yet expired
I0521 17:19:37.408963       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0521 17:19:39.846296       1 leaderelection.go:326] lock is held by tidb-scheduler-5585ccbc7f-hxbd2_621c7166-9b85-11ea-ae7c-0227f9bd39d5 and has not yet expired
I0521 17:19:39.846314       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0521 17:19:43.025784       1 leaderelection.go:326] lock is held by tidb-scheduler-5585ccbc7f-hxbd2_621c7166-9b85-11ea-ae7c-0227f9bd39d5 and has not yet expired
I0521 17:19:43.025798       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0521 17:19:46.905895       1 leaderelection.go:326] lock is held by tidb-scheduler-5585ccbc7f-hxbd2_621c7166-9b85-11ea-ae7c-0227f9bd39d5 and has not yet expired
I0521 17:19:46.905909       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0521 17:19:49.510457       1 leaderelection.go:326] lock is held by tidb-scheduler-5585ccbc7f-hxbd2_621c7166-9b85-11ea-ae7c-0227f9bd39d5 and has not yet expired
I0521 17:19:49.510472       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0521 17:19:52.744114       1 leaderelection.go:227] successfully acquired lease tidb-operator/tidb-scheduler
I0521 17:19:52.844332       1 shared_informer.go:123] caches populated
I0521 17:19:52.844374       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-2
I0521 17:19:52.844384       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-2
I0521 17:19:52.845451       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.845473       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.845515       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.845523       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.845529       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.845534       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.848913       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:52.848934       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:52.848974       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.849005       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.849012       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.851973       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:52.851990       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:52.891261       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-2: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:19:52.891315       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:19:52.897722       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:19:52.897737       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:19:52.897742       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:19:52.898136       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898149       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898156       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898167       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898186       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898192       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898201       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898201       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898213       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898214       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898260       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.898265       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.903410       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:19:52.903447       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:19:52.903641       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:52.903670       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:52.903703       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.903744       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.903763       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.904325       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:19:52.904347       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:19:52.907358       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:52.907378       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:52.913059       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-1
I0521 17:19:52.913076       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-1
I0521 17:19:52.913618       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.913639       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.913682       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.913691       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.913697       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.913703       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.916732       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:52.916752       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:52.916779       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.916801       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.916811       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:52.979954       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:52.979974       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:52.994579       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-1: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:19:52.994623       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:19:53.000461       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:19:53.000478       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:19:53.000483       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:19:53.000889       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000910       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000912       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000917       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000949       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000961       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000965       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000964       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000974       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000976       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000974       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.000983       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.004338       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:19:53.004339       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:19:53.004357       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:19:53.004364       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:19:53.004517       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:53.004537       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:19:53.004558       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.004587       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.004598       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:19:53.008132       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:19:53.008163       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.277122       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-2
I0521 17:20:08.277137       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-2
I0521 17:20:08.277718       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.277747       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.277803       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.277813       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.277819       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.277828       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.281132       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.281153       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.281181       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.281210       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.281220       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.284164       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.284181       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.305783       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-2: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:20:08.305828       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:20:08.311459       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:08.311473       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:08.311477       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:08.311907       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.311914       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.311953       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.311967       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.311953       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.312072       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.311909       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.312136       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.312164       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.312173       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.312179       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.312185       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.315186       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:20:08.315205       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:20:08.315474       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.315496       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.315517       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.315542       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.315552       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.318500       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.318518       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.379429       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:20:08.379457       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:20:08.385310       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-1
I0521 17:20:08.385327       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-1
I0521 17:20:08.385935       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.385971       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.386033       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.386046       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.386052       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.386062       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.389856       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.389884       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.389912       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.389947       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.389957       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.393120       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.393142       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.403003       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-1: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:20:08.403050       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:20:08.408152       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:08.408169       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:08.408173       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:08.408609       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408624       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408638       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408650       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408660       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408664       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408670       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408677       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408683       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408611       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408730       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.408752       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.412084       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.412115       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.412150       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.412195       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.412208       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:08.479496       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:08.479524       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:08.479870       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:20:08.479894       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:20:08.480180       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:20:08.480200       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:20:25.583339       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-2
I0521 17:20:25.583359       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-2
I0521 17:20:25.583977       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.584002       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.584050       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.584060       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.584068       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.584074       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.587648       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.587671       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.587707       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.587747       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.587755       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.590905       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.590924       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.609307       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-2: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:20:25.609351       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:20:25.614814       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:25.614830       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:25.614835       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:25.615377       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615415       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615429       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615434       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615448       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615472       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615495       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615504       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615513       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615378       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615972       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.615988       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.618996       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:20:25.619016       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:20:25.619054       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.619070       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.619102       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.619137       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.619145       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.622013       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.622030       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.679517       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:20:25.679544       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:20:25.685794       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-1
I0521 17:20:25.685807       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-1
I0521 17:20:25.686307       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.686328       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.686393       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.686404       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.686411       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.686416       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.689755       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.689778       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.689804       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.689829       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.689837       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.692829       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.692847       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.702773       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-1: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:20:25.702808       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:20:25.708142       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:25.708156       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:25.708161       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:25.708542       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708566       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708566       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708575       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708590       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708590       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708610       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708626       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708629       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708639       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708647       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.708659       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.712499       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.712518       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.712542       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.712568       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.712575       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:25.715551       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:25.715569       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:25.779907       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:20:25.779935       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:20:25.780521       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:20:25.780548       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:20:58.953103       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-2
I0521 17:20:58.953120       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-2
I0521 17:20:58.953674       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.953697       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.953746       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.953756       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.953762       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.953768       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.957318       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:58.957339       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:58.957366       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.957400       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.957411       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.960558       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:58.960575       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:58.986661       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-2: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:20:58.986700       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:20:58.992066       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:58.992081       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:58.992085       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:58.992405       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992417       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992437       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992437       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992444       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992444       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992453       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992456       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992487       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992499       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992509       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.992519       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.995393       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:20:58.995410       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:20:58.995432       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:20:58.995448       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:20:58.995496       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:58.995516       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:58.995542       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.995580       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.995594       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:58.998332       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:58.998352       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:59.004059       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-1
I0521 17:20:59.004071       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-1
I0521 17:20:59.004441       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.004462       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.004500       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.004505       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.004511       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.004516       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.007241       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:59.007261       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:59.007282       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.007306       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.007316       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.009996       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:59.010013       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:59.019018       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-1: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:20:59.019055       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:20:59.024310       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:59.024325       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:59.024332       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:59.024703       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024703       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024721       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024732       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024776       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024788       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024794       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024802       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.024732       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.025500       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.028268       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:20:59.028286       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:20:59.024737       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.028318       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.079095       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:20:59.079114       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:20:59.079769       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:59.079789       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:20:59.079811       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.079836       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.079847       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:20:59.082624       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:20:59.082641       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.298730       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-2
I0521 17:22:02.298746       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-2
I0521 17:22:02.299231       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.299250       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.299291       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.299300       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.299306       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.299315       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.302579       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.302599       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.302624       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.302652       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.302662       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.305610       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.305627       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.324097       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-2: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:22:02.324136       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:22:02.331935       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:22:02.331954       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:22:02.331958       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:22:02.332246       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332255       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332256       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332262       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332289       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332319       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332290       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332404       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332414       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332420       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332292       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.332477       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.335391       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:22:02.335409       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0521 17:22:02.335439       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.335460       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.335489       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.335516       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.335526       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.338172       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.338188       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.379343       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-2", PVC "yunchi-test-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:22:02.379365       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:22:02.386647       1 scheduling_queue.go:908] About to try and schedule pod yunchi-test-tidb/tidb-pd-1
I0521 17:22:02.386660       1 scheduler.go:453] Attempting to schedule pod: yunchi-test-tidb/tidb-pd-1
I0521 17:22:02.386997       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.387013       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.387050       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.387058       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.387065       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.387075       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.389903       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.389920       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.389939       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.389961       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.389967       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.392719       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.392737       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.402487       1 factory.go:647] Unable to schedule yunchi-test-tidb/tidb-pd-1: no fit: 0/26 nodes are available: 2 Insufficient cpu, 23 node(s) didn't match node selector.; waiting
I0521 17:22:02.402522       1 factory.go:742] Updating pod condition for yunchi-test-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0521 17:22:02.411487       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:22:02.411500       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:22:02.411504       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0521 17:22:02.411810       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411816       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411842       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411841       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411852       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411853       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411858       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411866       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411888       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411902       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411908       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.411914       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.414784       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.414804       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.414826       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.414848       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.414860       1 predicates.go:452] PVC yunchi-test-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0521 17:22:02.417506       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0521 17:22:02.417522       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0521 17:22:02.478882       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0521 17:22:02.478907       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0521 17:22:02.479061       1 scheduler_binder.go:697] No matching volumes for Pod "yunchi-test-tidb/tidb-pd-1", PVC "yunchi-test-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0521 17:22:02.479087       1 scheduler_binder.go:752] Provisioning for claims of pod "yunchi-test-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...

Now invalid nodes that won't pass predicates of tidb-scheduler in the filter phase will not be chosen in the preemption phase.

Could you elaborate here? I'm not familiar with the scheduler phases. We want these low priority overprovisioning pods to be preempted so that PD (and other pods) can be scheduled on them. Why would we want to exclude these nodes from preemption?

> kubectl -n overprovisioning-tidb get po -o wide
NAME                                READY   STATUS    RESTARTS   AGE   IP               NODE                                          NOMINATED NODE   READINESS GATES
overprovisioning-5568764c46-6vpnx   1/1     Running   0          16m   10.136.113.244   ip-10-136-100-18.us-west-2.compute.internal   <none>           <none>
overprovisioning-5568764c46-vlqqk   1/1     Running   0          16m   10.136.87.198    ip-10-136-94-171.us-west-2.compute.internal   <none>           <none>

@cofyc
Copy link
Contributor Author

cofyc commented May 22, 2020

@mightyguava I forgot to tell you that scheduler policy tidb-scheduler-policy config map must be updated:

kubectl -n <tidb-operator-ns> edit cm tidb-scheduler-policy 

add "preemptVerb": "preempt", see diff here.

image

Can you update the config map and try again?

@tirsen
Copy link
Contributor

tirsen commented May 22, 2020

I made the config change and it's still not working.

$ kubectl -n overprovisioning-tidb get po -o wide
NAME                                READY   STATUS    RESTARTS   AGE   IP               NODE                                          NOMINATED NODE   READINESS GATES
overprovisioning-5568764c46-8ccx7   1/1     Running   0          27m   10.136.99.6      ip-10-136-100-18.us-west-2.compute.internal   <none>           <none>
overprovisioning-5568764c46-w9grm   1/1     Running   0          27m   10.136.135.102   ip-10-136-135-87.us-west-2.compute.internal   <none>           <none>

There's an error in the kube-scheduler logs below as you can see but there is no more info what the error is about. :-(

configmap/tidb-scheduler-policy
apiVersion: v1
data:
  policy.cfg: |-
    {
      "kind" : "Policy",
      "apiVersion" : "v1",
      "predicates": [
        {"name": "NoVolumeZoneConflict"},
        {"name": "MaxEBSVolumeCount"},
        {"name": "MaxAzureDiskVolumeCount"},
        {"name": "NoDiskConflict"},
        {"name": "GeneralPredicates"},
        {"name": "PodToleratesNodeTaints"},
        {"name": "CheckVolumeBinding"},
        {"name": "MaxGCEPDVolumeCount"},
        {"name": "MatchInterPodAffinity"},
        {"name": "CheckVolumeBinding"}
      ],
      "priorities": [
        {"name": "SelectorSpreadPriority", "weight": 1},
        {"name": "InterPodAffinityPriority", "weight": 1},
        {"name": "LeastRequestedPriority", "weight": 1},
        {"name": "BalancedResourceAllocation", "weight": 1},
        {"name": "NodePreferAvoidPodsPriority", "weight": 1},
        {"name": "NodeAffinityPriority", "weight": 1},
        {"name": "TaintTolerationPriority", "weight": 1}
      ],
      "extenders": [
        {
          "urlPrefix": "http://127.0.0.1:10262/scheduler",
          "filterVerb": "filter",
          "preemptVerb": "preempt",
          "weight": 1,
          "httpTimeout": 30000000000,
          "enableHttps": false
        }
      ]
    }
kind: ConfigMap
tikv-scheduler.log
I0522 02:46:05.905339       1 version.go:38] Welcome to TiDB Operator.
I0522 02:46:05.905372       1 version.go:39] TiDB Operator Version: version.Info{GitVersion:"v0.0.0-master+$Format:%h$", GitCommit:"$Format:%H$", GitTreeState:"", BuildDate:"1970-01-01T00:00:00Z", GoVersion:"go1.13.8", Compiler:"gc", Platform:"linux/amd64"}
I0522 02:46:05.905403       1 main.go:58] FLAG: --V="false"
I0522 02:46:05.905411       1 main.go:58] FLAG: --add_dir_header="false"
I0522 02:46:05.905414       1 main.go:58] FLAG: --alsologtostderr="false"
I0522 02:46:05.905417       1 main.go:58] FLAG: --features="AdvancedStatefulSet=false,AutoScaling=false,StableScheduling=true"
I0522 02:46:05.905430       1 main.go:58] FLAG: --log_backtrace_at=":0"
I0522 02:46:05.905434       1 main.go:58] FLAG: --log_dir=""
I0522 02:46:05.905438       1 main.go:58] FLAG: --log_file=""
I0522 02:46:05.905440       1 main.go:58] FLAG: --log_file_max_size="1800"
I0522 02:46:05.905444       1 main.go:58] FLAG: --logtostderr="true"
I0522 02:46:05.905446       1 main.go:58] FLAG: --port="10262"
I0522 02:46:05.905450       1 main.go:58] FLAG: --skip_headers="false"
I0522 02:46:05.905452       1 main.go:58] FLAG: --skip_log_headers="false"
I0522 02:46:05.905455       1 main.go:58] FLAG: --stderrthreshold="2"
I0522 02:46:05.905458       1 main.go:58] FLAG: --v="2"
I0522 02:46:05.905462       1 main.go:58] FLAG: --version="false"
I0522 02:46:05.905464       1 main.go:58] FLAG: --vmodule=""
I0522 02:46:05.906458       1 mux.go:66] start scheduler extender server, listening on 0.0.0.0:10262
I0522 03:00:33.589188       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-0
I0522 03:00:33.589212       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:33.611541       1 ha.go:334] update PVC: [zzzdemo1-tidb/pd-tidb-pd-0] successfully, TidbCluster: tidb
I0522 03:00:33.611559       1 ha.go:374] ha: set pvc zzzdemo1-tidb/pd-tidb-pd-0 annotation tidb.pingcap.com/pod-scheduling to 2020-05-22T03:00:33Z successfully
I0522 03:00:33.640985       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:00:33.641003       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:00:33.641010       1 ha.go:146] pod tidb-pd-0 is not bind
I0522 03:00:33.641013       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:00:33.641016       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:00:33.641023       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:33.654445       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:00:33.654459       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:33.669313       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:33.669405       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676334", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:33.699811       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:33.699828       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:33.699836       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:33.699842       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:00:33.704286       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:00:33.704300       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:33.716932       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:33.717034       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676342", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:33.733520       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:00:33.733535       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:33.733542       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:33.733547       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:00:33.798521       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-0
I0522 03:00:33.798536       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:34.198311       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:00:34.198327       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:00:34.198333       1 ha.go:146] pod tidb-pd-0 is not bind
I0522 03:00:34.198337       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:00:34.198340       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:00:34.198348       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:34.203577       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:00:34.203590       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:34.593796       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:34.593912       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:34.606205       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:34.606223       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:34.606231       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:34.606236       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:00:34.610563       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:00:34.610596       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:35.193642       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:35.193747       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:35.203527       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:00:35.203541       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:35.203549       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:35.203554       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:00:35.207649       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:00:35.207661       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:35.793889       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:35.794031       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:35.804339       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:35.804354       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:35.804362       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:35.804367       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:00:36.820975       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:00:36.820993       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:36.829902       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:36.830089       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:36.838828       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:00:36.838840       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:36.838847       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:36.838852       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:00:37.820860       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:00:37.820877       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:37.829121       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:37.829210       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:37.837724       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:37.837737       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:37.837744       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:37.837748       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:00:40.273004       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:00:40.273020       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:40.282099       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:40.282200       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-0 scheduling
I0522 03:00:40.296624       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:00:40.296637       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:40.296643       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:40.296648       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:00:42.821879       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:00:42.821939       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:42.840729       1 ha.go:334] update PVC: [zzzdemo1-tidb/pd-tidb-pd-0] successfully, TidbCluster: tidb
I0522 03:00:42.840744       1 ha.go:301] ha: delete pvc zzzdemo1-tidb/pd-tidb-pd-0 annotation tidb.pingcap.com/pod-scheduling successfully
I0522 03:00:42.846094       1 ha.go:334] update PVC: [zzzdemo1-tidb/pd-tidb-pd-1] successfully, TidbCluster: tidb
I0522 03:00:42.846108       1 ha.go:374] ha: set pvc zzzdemo1-tidb/pd-tidb-pd-1 annotation tidb.pingcap.com/pod-scheduling to 2020-05-22T03:00:42Z successfully
I0522 03:00:42.858241       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:00:42.858252       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:00:42.858259       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:00:42.858263       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:00:42.858268       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:00:42.858275       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:42.858370       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:00:42.867827       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:42.867842       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:42.867849       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:42.867855       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:00:44.821692       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:00:44.821710       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:44.830854       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:44.830958       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:00:44.841276       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:00:44.841290       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:44.841296       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:44.841301       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:00:51.822388       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:00:51.822405       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:00:51.838755       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:00:51.838767       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:00:51.838775       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:00:51.838779       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:00:51.838784       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:00:51.838791       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:00:51.838885       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:00:51.847474       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:51.847485       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:51.847492       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:51.847496       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:02:08.510165       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:02:08.510181       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:02:08.518612       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:02:08.518712       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:02:08.527302       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:02:08.527316       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:02:08.527323       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:02:08.527328       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:02:08.531284       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:02:08.531294       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:02:08.546875       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:02:08.546887       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:02:08.546894       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:02:08.546898       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:02:08.546907       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:02:08.546920       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:02:08.547016       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:02:08.599297       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:02:08.599313       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:02:08.599321       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:02:08.599326       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:03:38.510929       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:03:38.510949       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:03:38.525696       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:03:38.525802       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:03:38.538613       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:03:38.538626       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:03:38.538633       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:03:38.538638       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:03:38.542653       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:03:38.542665       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:03:38.562231       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:03:38.562243       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:03:38.562250       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:03:38.562254       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:03:38.562259       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:03:38.562266       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:03:38.562357       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:03:38.599351       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:03:38.599364       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:03:38.599370       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:03:38.599375       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:05:08.511356       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:05:08.511381       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:05:08.522172       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:05:08.522289       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:05:08.536836       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:05:08.536849       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:05:08.536856       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:05:08.536861       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:05:08.540848       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:05:08.540860       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:05:08.557438       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:05:08.557450       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:05:08.557457       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:05:08.557462       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:05:08.557467       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:05:08.557474       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:05:08.557569       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:05:08.601381       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:05:08.601395       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:05:08.601402       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:05:08.601406       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:05:11.254165       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:05:11.254181       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:05:11.262505       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:05:11.262604       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:05:11.277680       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:05:11.277699       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:05:11.277709       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:05:11.277715       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:05:11.281875       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:05:11.281887       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:05:11.298167       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:05:11.298180       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:05:11.298188       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:05:11.298192       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:05:11.298198       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:05:11.298207       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:05:11.298308       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:05:11.307531       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:05:11.307544       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:05:11.307551       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:05:11.307556       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:06:38.511729       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:06:38.511745       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:06:38.519769       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:06:38.519872       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:06:38.528375       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:06:38.528389       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:06:38.528395       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:06:38.528400       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:06:38.532793       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:06:38.532804       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:06:38.550884       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:06:38.550896       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:06:38.550903       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:06:38.550907       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:06:38.550912       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:06:38.550920       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:06:38.551015       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:06:38.603843       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:06:38.603855       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:06:38.603862       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:06:38.603867       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
I0522 03:08:08.511641       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:08:08.511661       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:08:08.520306       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:08:08.520445       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-2", UID:"6745a814-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676377", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' waiting for Pod zzzdemo1-tidb/tidb-pd-1 scheduling
I0522 03:08:08.529809       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-2
I0522 03:08:08.529824       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:08:08.529831       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:08:08.529835       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-2
I0522 03:08:08.533817       1 scheduler.go:124] scheduling pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:08:08.533828       1 scheduler.go:127] entering predicate: HAScheduling, nodes: [ip-10-136-94-171.us-west-2.compute.internal]
I0522 03:08:08.549381       1 ha.go:121] ha: tidbcluster zzzdemo1-tidb/tidb component pd replicas 3
I0522 03:08:08.549393       1 ha.go:129] current topology key: kubernetes.io/hostname
I0522 03:08:08.549400       1 ha.go:146] pod tidb-pd-1 is not bind
I0522 03:08:08.549404       1 ha.go:146] pod tidb-pd-2 is not bind
I0522 03:08:08.549409       1 ha.go:208] topology ip-10-136-94-171.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping
I0522 03:08:08.549416       1 scheduler.go:129] leaving predicate: HAScheduling, nodes: []
I0522 03:08:08.549508       1 event.go:255] Event(v1.ObjectReference{Kind:"Pod", Namespace:"zzzdemo1-tidb", Name:"tidb-pd-1", UID:"6742c90c-9bd8-11ea-92df-06145c0039f6", APIVersion:"v1", ResourceVersion:"802676362", FieldPath:""}): type: 'Warning' reason: 'HAScheduling' unable to schedule to topology: ip-10-136-94-171.us-west-2.compute.internal (1 pd pods), max pods per topology: 1
I0522 03:08:08.557553       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:08:08.557565       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:08:08.557572       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:08:08.557576       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1
kube-scheduler.log
I0522 02:46:06.299552       1 flags.go:33] FLAG: --address="0.0.0.0"
I0522 02:46:06.299586       1 flags.go:33] FLAG: --algorithm-provider=""
I0522 02:46:06.299591       1 flags.go:33] FLAG: --alsologtostderr="false"
I0522 02:46:06.299596       1 flags.go:33] FLAG: --authentication-kubeconfig=""
I0522 02:46:06.299600       1 flags.go:33] FLAG: --authentication-skip-lookup="false"
I0522 02:46:06.299609       1 flags.go:33] FLAG: --authentication-token-webhook-cache-ttl="10s"
I0522 02:46:06.299614       1 flags.go:33] FLAG: --authentication-tolerate-lookup-failure="true"
I0522 02:46:06.299619       1 flags.go:33] FLAG: --authorization-always-allow-paths="[/healthz]"
I0522 02:46:06.299628       1 flags.go:33] FLAG: --authorization-kubeconfig=""
I0522 02:46:06.299632       1 flags.go:33] FLAG: --authorization-webhook-cache-authorized-ttl="10s"
I0522 02:46:06.299636       1 flags.go:33] FLAG: --authorization-webhook-cache-unauthorized-ttl="10s"
I0522 02:46:06.299644       1 flags.go:33] FLAG: --bind-address="0.0.0.0"
I0522 02:46:06.299652       1 flags.go:33] FLAG: --cert-dir=""
I0522 02:46:06.299656       1 flags.go:33] FLAG: --client-ca-file=""
I0522 02:46:06.299661       1 flags.go:33] FLAG: --config=""
I0522 02:46:06.299665       1 flags.go:33] FLAG: --contention-profiling="false"
I0522 02:46:06.299670       1 flags.go:33] FLAG: --failure-domains="kubernetes.io/hostname,failure-domain.beta.kubernetes.io/zone,failure-domain.beta.kubernetes.io/region"
I0522 02:46:06.299683       1 flags.go:33] FLAG: --feature-gates=""
I0522 02:46:06.299689       1 flags.go:33] FLAG: --hard-pod-affinity-symmetric-weight="1"
I0522 02:46:06.299695       1 flags.go:33] FLAG: --help="false"
I0522 02:46:06.299700       1 flags.go:33] FLAG: --http2-max-streams-per-connection="0"
I0522 02:46:06.299706       1 flags.go:33] FLAG: --kube-api-burst="100"
I0522 02:46:06.299711       1 flags.go:33] FLAG: --kube-api-content-type="application/vnd.kubernetes.protobuf"
I0522 02:46:06.299717       1 flags.go:33] FLAG: --kube-api-qps="50"
I0522 02:46:06.299728       1 flags.go:33] FLAG: --kubeconfig=""
I0522 02:46:06.299732       1 flags.go:33] FLAG: --leader-elect="true"
I0522 02:46:06.299737       1 flags.go:33] FLAG: --leader-elect-lease-duration="15s"
I0522 02:46:06.299741       1 flags.go:33] FLAG: --leader-elect-renew-deadline="10s"
I0522 02:46:06.299746       1 flags.go:33] FLAG: --leader-elect-resource-lock="endpoints"
I0522 02:46:06.299754       1 flags.go:33] FLAG: --leader-elect-retry-period="2s"
I0522 02:46:06.299759       1 flags.go:33] FLAG: --lock-object-name="tidb-scheduler"
I0522 02:46:06.299763       1 flags.go:33] FLAG: --lock-object-namespace="tidb-operator"
I0522 02:46:06.299768       1 flags.go:33] FLAG: --log-backtrace-at=":0"
I0522 02:46:06.299779       1 flags.go:33] FLAG: --log-dir=""
I0522 02:46:06.299784       1 flags.go:33] FLAG: --log-file=""
I0522 02:46:06.299789       1 flags.go:33] FLAG: --log-flush-frequency="5s"
I0522 02:46:06.299794       1 flags.go:33] FLAG: --logtostderr="true"
I0522 02:46:06.299799       1 flags.go:33] FLAG: --master=""
I0522 02:46:06.299803       1 flags.go:33] FLAG: --policy-config-file=""
I0522 02:46:06.299807       1 flags.go:33] FLAG: --policy-configmap="tidb-scheduler-policy"
I0522 02:46:06.299816       1 flags.go:33] FLAG: --policy-configmap-namespace="tidb-operator"
I0522 02:46:06.299821       1 flags.go:33] FLAG: --port="10261"
I0522 02:46:06.299825       1 flags.go:33] FLAG: --profiling="false"
I0522 02:46:06.299830       1 flags.go:33] FLAG: --requestheader-allowed-names="[]"
I0522 02:46:06.299835       1 flags.go:33] FLAG: --requestheader-client-ca-file=""
I0522 02:46:06.299839       1 flags.go:33] FLAG: --requestheader-extra-headers-prefix="[x-remote-extra-]"
I0522 02:46:06.299846       1 flags.go:33] FLAG: --requestheader-group-headers="[x-remote-group]"
I0522 02:46:06.299855       1 flags.go:33] FLAG: --requestheader-username-headers="[x-remote-user]"
I0522 02:46:06.299862       1 flags.go:33] FLAG: --scheduler-name="tidb-scheduler"
I0522 02:46:06.299867       1 flags.go:33] FLAG: --secure-port="10259"
I0522 02:46:06.299871       1 flags.go:33] FLAG: --skip-headers="false"
I0522 02:46:06.299876       1 flags.go:33] FLAG: --stderrthreshold="2"
I0522 02:46:06.299880       1 flags.go:33] FLAG: --tls-cert-file=""
I0522 02:46:06.299884       1 flags.go:33] FLAG: --tls-cipher-suites="[]"
I0522 02:46:06.299889       1 flags.go:33] FLAG: --tls-min-version=""
I0522 02:46:06.299894       1 flags.go:33] FLAG: --tls-private-key-file=""
I0522 02:46:06.299898       1 flags.go:33] FLAG: --tls-sni-cert-key="[]"
I0522 02:46:06.299904       1 flags.go:33] FLAG: --use-legacy-policy-config="false"
I0522 02:46:06.299908       1 flags.go:33] FLAG: --v="2"
I0522 02:46:06.299913       1 flags.go:33] FLAG: --version="false"
I0522 02:46:06.299920       1 flags.go:33] FLAG: --vmodule=""
I0522 02:46:06.299925       1 flags.go:33] FLAG: --write-config-to=""
I0522 02:46:07.620946       1 serving.go:319] Generated self-signed cert in-memory
W0522 02:46:08.499435       1 options.go:300] Neither --kubeconfig nor --master was specified. Using default API client. This might not work.
I0522 02:46:08.501183       1 server.go:142] Version: v1.14.9
I0522 02:46:08.501222       1 defaults.go:87] TaintNodesByCondition is enabled, PodToleratesNodeTaints predicate is mandatory
I0522 02:46:08.501231       1 server.go:161] Starting Kubernetes Scheduler version v1.14.9
I0522 02:46:08.509186       1 factory.go:341] Creating scheduler from configuration: {{ } [{NoVolumeZoneConflict <nil>} {MaxEBSVolumeCount <nil>} {MaxAzureDiskVolumeCount <nil>} {NoDiskConflict <nil>} {GeneralPredicates <nil>} {PodToleratesNodeTaints <nil>} {CheckVolumeBinding <nil>} {MaxGCEPDVolumeCount <nil>} {MatchInterPodAffinity <nil>} {CheckVolumeBinding <nil>}] [{SelectorSpreadPriority 1 <nil>} {InterPodAffinityPriority 1 <nil>} {LeastRequestedPriority 1 <nil>} {BalancedResourceAllocation 1 <nil>} {NodePreferAvoidPodsPriority 1 <nil>} {NodeAffinityPriority 1 <nil>} {TaintTolerationPriority 1 <nil>}] [{http://127.0.0.1:10262/scheduler filter preempt  1  false <nil> 30s false [] false}] 0 false}
I0522 02:46:08.509227       1 factory.go:358] Registering predicate: NoVolumeZoneConflict
I0522 02:46:08.509234       1 plugins.go:236] Predicate type NoVolumeZoneConflict already registered, reusing.
I0522 02:46:08.509238       1 factory.go:358] Registering predicate: MaxEBSVolumeCount
I0522 02:46:08.509241       1 plugins.go:236] Predicate type MaxEBSVolumeCount already registered, reusing.
I0522 02:46:08.509245       1 factory.go:358] Registering predicate: MaxAzureDiskVolumeCount
I0522 02:46:08.509248       1 plugins.go:236] Predicate type MaxAzureDiskVolumeCount already registered, reusing.
I0522 02:46:08.509251       1 factory.go:358] Registering predicate: NoDiskConflict
I0522 02:46:08.509254       1 plugins.go:236] Predicate type NoDiskConflict already registered, reusing.
I0522 02:46:08.509257       1 factory.go:358] Registering predicate: GeneralPredicates
I0522 02:46:08.509260       1 plugins.go:236] Predicate type GeneralPredicates already registered, reusing.
I0522 02:46:08.509263       1 factory.go:358] Registering predicate: PodToleratesNodeTaints
I0522 02:46:08.509266       1 plugins.go:236] Predicate type PodToleratesNodeTaints already registered, reusing.
I0522 02:46:08.509270       1 factory.go:358] Registering predicate: CheckVolumeBinding
I0522 02:46:08.509273       1 plugins.go:236] Predicate type CheckVolumeBinding already registered, reusing.
I0522 02:46:08.509276       1 factory.go:358] Registering predicate: MaxGCEPDVolumeCount
I0522 02:46:08.509279       1 plugins.go:236] Predicate type MaxGCEPDVolumeCount already registered, reusing.
I0522 02:46:08.509282       1 factory.go:358] Registering predicate: MatchInterPodAffinity
I0522 02:46:08.509285       1 plugins.go:236] Predicate type MatchInterPodAffinity already registered, reusing.
I0522 02:46:08.509289       1 factory.go:358] Registering predicate: CheckVolumeBinding
I0522 02:46:08.509292       1 plugins.go:236] Predicate type CheckVolumeBinding already registered, reusing.
I0522 02:46:08.509296       1 factory.go:373] Registering priority: SelectorSpreadPriority
I0522 02:46:08.509303       1 plugins.go:348] Priority type SelectorSpreadPriority already registered, reusing.
I0522 02:46:08.509318       1 factory.go:373] Registering priority: InterPodAffinityPriority
I0522 02:46:08.509323       1 plugins.go:348] Priority type InterPodAffinityPriority already registered, reusing.
I0522 02:46:08.509328       1 factory.go:373] Registering priority: LeastRequestedPriority
I0522 02:46:08.509331       1 plugins.go:348] Priority type LeastRequestedPriority already registered, reusing.
I0522 02:46:08.509335       1 factory.go:373] Registering priority: BalancedResourceAllocation
I0522 02:46:08.509338       1 plugins.go:348] Priority type BalancedResourceAllocation already registered, reusing.
I0522 02:46:08.509342       1 factory.go:373] Registering priority: NodePreferAvoidPodsPriority
I0522 02:46:08.509345       1 plugins.go:348] Priority type NodePreferAvoidPodsPriority already registered, reusing.
I0522 02:46:08.509349       1 factory.go:373] Registering priority: NodeAffinityPriority
I0522 02:46:08.509352       1 plugins.go:348] Priority type NodeAffinityPriority already registered, reusing.
I0522 02:46:08.509356       1 factory.go:373] Registering priority: TaintTolerationPriority
I0522 02:46:08.509359       1 plugins.go:348] Priority type TaintTolerationPriority already registered, reusing.
I0522 02:46:08.509364       1 factory.go:382] Creating extender with config {URLPrefix:http://127.0.0.1:10262/scheduler FilterVerb:filter PreemptVerb:preempt PrioritizeVerb: Weight:1 BindVerb: EnableHTTPS:false TLSConfig:<nil> HTTPTimeout:30s NodeCacheCapable:false ManagedResources:[] Ignorable:false}
I0522 02:46:08.509382       1 factory.go:412] Creating scheduler with fit predicates 'map[CheckVolumeBinding:{} GeneralPredicates:{} MatchInterPodAffinity:{} MaxAzureDiskVolumeCount:{} MaxEBSVolumeCount:{} MaxGCEPDVolumeCount:{} NoDiskConflict:{} NoVolumeZoneConflict:{} PodToleratesNodeTaints:{}]' and priority functions 'map[BalancedResourceAllocation:{} InterPodAffinityPriority:{} LeastRequestedPriority:{} NodeAffinityPriority:{} NodePreferAvoidPodsPriority:{} SelectorSpreadPriority:{} TaintTolerationPriority:{}]'
W0522 02:46:08.509931       1 authorization.go:47] Authorization is disabled
W0522 02:46:08.509939       1 authentication.go:55] Authentication is disabled
I0522 02:46:08.509946       1 deprecated_insecure_serving.go:49] Serving healthz insecurely on [::]:10261
I0522 02:46:08.510312       1 secure_serving.go:116] Serving securely on [::]:10259
I0522 02:46:11.411304       1 controller_utils.go:1027] Waiting for caches to sync for scheduler controller
I0522 02:46:11.511435       1 controller_utils.go:1034] Caches are synced for scheduler controller
I0522 02:46:11.511513       1 leaderelection.go:217] attempting to acquire leader lease  tidb-operator/tidb-scheduler...
I0522 02:46:28.736252       1 leaderelection.go:227] successfully acquired lease tidb-operator/tidb-scheduler
E0522 03:00:33.641939       1 factory.go:660] Error scheduling zzzdemo1-tidb/tidb-pd-0: v1.PersistentVolumeClaim "zzzdemo1-tidb/pd-tidb-pd-0" is out of sync (stored: 802676338, assume: 802676322); retrying
E0522 03:00:33.650097       1 scheduler.go:501] error assuming volumes: v1.PersistentVolumeClaim "zzzdemo1-tidb/pd-tidb-pd-0" is out of sync (stored: 802676338, assume: 802676322)
E0522 03:00:33.699969       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:00:33.733671       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:00:34.199112       1 trace.go:81] Trace[1083086756]: "Scheduling zzzdemo1-tidb/tidb-pd-0" (started: 2020-05-22 03:00:33.733717984 +0000 UTC m=+867.599508393) (total time: 465.367127ms):
Trace[1083086756]: [465.364552ms] [465.355456ms] Prioritizing
I0522 03:00:34.594090       1 trace.go:81] Trace[1648846855]: "Scheduling zzzdemo1-tidb/tidb-pd-1" (started: 2020-05-22 03:00:34.19922617 +0000 UTC m=+868.065016606) (total time: 394.822477ms):
Trace[1648846855]: [394.822477ms] [394.800068ms] END
E0522 03:00:34.606348       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:00:35.193863       1 trace.go:81] Trace[636704976]: "Scheduling zzzdemo1-tidb/tidb-pd-2" (started: 2020-05-22 03:00:34.606377633 +0000 UTC m=+868.472168077) (total time: 587.44998ms):
Trace[636704976]: [587.44998ms] [587.432173ms] END
E0522 03:00:35.203664       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:00:35.794155       1 trace.go:81] Trace[145750173]: "Scheduling zzzdemo1-tidb/tidb-pd-1" (started: 2020-05-22 03:00:35.203687513 +0000 UTC m=+869.069477902) (total time: 590.419469ms):
Trace[145750173]: [590.419469ms] [590.399657ms] END
E0522 03:00:35.804476       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:00:36.838959       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:00:37.837847       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:00:40.296738       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:00:41.211709       1 scheduler.go:572] pod zzzdemo1-tidb/tidb-pd-0 is bound successfully on node ip-10-136-94-171.us-west-2.compute.internal, 25 nodes evaluated, 1 nodes were found feasible
E0522 03:00:42.867963       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:00:44.841415       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:00:51.847602       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:02:08.527434       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:02:08.599423       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:03:38.538739       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:03:38.599474       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:05:08.536952       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:05:08.601512       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:05:11.277842       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:05:11.307664       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:06:38.528497       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
E0522 03:06:38.603967       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.

@cofyc
Copy link
Contributor Author

cofyc commented May 22, 2020

I guess the pod tidb-pd-3 (edit: tidb-pd-0) is assigned to ip-10-136-135-87.us-west-2.compute.internal, right?

Could you elaborate here? I'm not familiar with the scheduler phases. We want these low priority overprovisioning pods to be preempted so that PD (and other pods) can be scheduled on them. Why would we want to exclude these nodes from preemption?

The basic scheduler workflow in 1.14.x is like this:

  • a) Filter (find feasible nodes)
    will call our extender (tidb-scheduler) filter API
  • b) Prioritize (sorting nodes by score)
  • c.1) Bind (if a feasible node is found, bind pod to this node)
  • c.2) Preempt (if no node is feasible, try to find a node from which we can preempt some pods then the pod can be scheduled onto)
    will call our extender (tidb-scheduler) preempt API (after this PR, we support this)

at before, our extender (tidb-scheduler) does not implement preempt API, all nodes are chosen by kube-scheduler.

I0521 17:20:59.024310       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:59.024325       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0521 17:20:59.024332       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.

an invalid node (ip-10-136-135-87.us-west-2.compute.internal) is nominated but this node already has a PD running and is rejected by tidb-scheduler Filter API.

I0521 17:19:52.890844       1 ha.go:208] topology ip-10-136-135-87.us-west-2.compute.internal has 1 instances of component pd, max allowed is 1, skipping

after this PR, ip-10-136-135-87.us-west-2.compute.internal should be ignored in the preempt phase.

@cofyc
Copy link
Contributor Author

cofyc commented May 22, 2020

Thanks! can you show the output of this command? I'd like know the current status:

kubectl -n <your-tidb-cluster-ns> get pods -o wide

@cofyc
Copy link
Contributor Author

cofyc commented May 22, 2020

I'll test with your Kubernetes version (1.14.9-eks) to see why the scheduler emits these errors. Thanks for the feedback!

E0522 03:00:35.804476       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
E0522 03:00:36.838959       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.

@tirsen
Copy link
Contributor

tirsen commented May 22, 2020

Here's the -v=4 logs of kube-scheduler:

kube-scheduler.log
I0522 03:29:03.609772       1 flags.go:33] FLAG: --address="0.0.0.0"
I0522 03:29:03.609809       1 flags.go:33] FLAG: --algorithm-provider=""
I0522 03:29:03.609813       1 flags.go:33] FLAG: --alsologtostderr="false"
I0522 03:29:03.609820       1 flags.go:33] FLAG: --authentication-kubeconfig=""
I0522 03:29:03.609823       1 flags.go:33] FLAG: --authentication-skip-lookup="false"
I0522 03:29:03.609827       1 flags.go:33] FLAG: --authentication-token-webhook-cache-ttl="10s"
I0522 03:29:03.609832       1 flags.go:33] FLAG: --authentication-tolerate-lookup-failure="true"
I0522 03:29:03.609839       1 flags.go:33] FLAG: --authorization-always-allow-paths="[/healthz]"
I0522 03:29:03.609849       1 flags.go:33] FLAG: --authorization-kubeconfig=""
I0522 03:29:03.609852       1 flags.go:33] FLAG: --authorization-webhook-cache-authorized-ttl="10s"
I0522 03:29:03.609856       1 flags.go:33] FLAG: --authorization-webhook-cache-unauthorized-ttl="10s"
I0522 03:29:03.609859       1 flags.go:33] FLAG: --bind-address="0.0.0.0"
I0522 03:29:03.609869       1 flags.go:33] FLAG: --cert-dir=""
I0522 03:29:03.609872       1 flags.go:33] FLAG: --client-ca-file=""
I0522 03:29:03.609875       1 flags.go:33] FLAG: --config=""
I0522 03:29:03.609879       1 flags.go:33] FLAG: --contention-profiling="false"
I0522 03:29:03.609882       1 flags.go:33] FLAG: --failure-domains="kubernetes.io/hostname,failure-domain.beta.kubernetes.io/zone,failure-domain.beta.kubernetes.io/region"
I0522 03:29:03.609892       1 flags.go:33] FLAG: --feature-gates=""
I0522 03:29:03.609902       1 flags.go:33] FLAG: --hard-pod-affinity-symmetric-weight="1"
I0522 03:29:03.609906       1 flags.go:33] FLAG: --help="false"
I0522 03:29:03.609909       1 flags.go:33] FLAG: --http2-max-streams-per-connection="0"
I0522 03:29:03.609913       1 flags.go:33] FLAG: --kube-api-burst="100"
I0522 03:29:03.609917       1 flags.go:33] FLAG: --kube-api-content-type="application/vnd.kubernetes.protobuf"
I0522 03:29:03.609925       1 flags.go:33] FLAG: --kube-api-qps="50"
I0522 03:29:03.609930       1 flags.go:33] FLAG: --kubeconfig=""
I0522 03:29:03.609933       1 flags.go:33] FLAG: --leader-elect="true"
I0522 03:29:03.609936       1 flags.go:33] FLAG: --leader-elect-lease-duration="15s"
I0522 03:29:03.609939       1 flags.go:33] FLAG: --leader-elect-renew-deadline="10s"
I0522 03:29:03.609943       1 flags.go:33] FLAG: --leader-elect-resource-lock="endpoints"
I0522 03:29:03.609950       1 flags.go:33] FLAG: --leader-elect-retry-period="2s"
I0522 03:29:03.609953       1 flags.go:33] FLAG: --lock-object-name="tidb-scheduler"
I0522 03:29:03.609956       1 flags.go:33] FLAG: --lock-object-namespace="tidb-operator"
I0522 03:29:03.609959       1 flags.go:33] FLAG: --log-backtrace-at=":0"
I0522 03:29:03.609967       1 flags.go:33] FLAG: --log-dir=""
I0522 03:29:03.698040       1 flags.go:33] FLAG: --log-file=""
I0522 03:29:03.698059       1 flags.go:33] FLAG: --log-flush-frequency="5s"
I0522 03:29:03.698065       1 flags.go:33] FLAG: --logtostderr="true"
I0522 03:29:03.698071       1 flags.go:33] FLAG: --master=""
I0522 03:29:03.698077       1 flags.go:33] FLAG: --policy-config-file=""
I0522 03:29:03.698188       1 flags.go:33] FLAG: --policy-configmap="tidb-scheduler-policy"
I0522 03:29:03.698203       1 flags.go:33] FLAG: --policy-configmap-namespace="tidb-operator"
I0522 03:29:03.698207       1 flags.go:33] FLAG: --port="10261"
I0522 03:29:03.698211       1 flags.go:33] FLAG: --profiling="false"
I0522 03:29:03.698215       1 flags.go:33] FLAG: --requestheader-allowed-names="[]"
I0522 03:29:03.698225       1 flags.go:33] FLAG: --requestheader-client-ca-file=""
I0522 03:29:03.698228       1 flags.go:33] FLAG: --requestheader-extra-headers-prefix="[x-remote-extra-]"
I0522 03:29:03.698249       1 flags.go:33] FLAG: --requestheader-group-headers="[x-remote-group]"
I0522 03:29:03.698254       1 flags.go:33] FLAG: --requestheader-username-headers="[x-remote-user]"
I0522 03:29:03.698260       1 flags.go:33] FLAG: --scheduler-name="tidb-scheduler"
I0522 03:29:03.698263       1 flags.go:33] FLAG: --secure-port="10259"
I0522 03:29:03.698266       1 flags.go:33] FLAG: --skip-headers="false"
I0522 03:29:03.698269       1 flags.go:33] FLAG: --stderrthreshold="2"
I0522 03:29:03.698272       1 flags.go:33] FLAG: --tls-cert-file=""
I0522 03:29:03.698275       1 flags.go:33] FLAG: --tls-cipher-suites="[]"
I0522 03:29:03.698282       1 flags.go:33] FLAG: --tls-min-version=""
I0522 03:29:03.698285       1 flags.go:33] FLAG: --tls-private-key-file=""
I0522 03:29:03.698288       1 flags.go:33] FLAG: --tls-sni-cert-key="[]"
I0522 03:29:03.698293       1 flags.go:33] FLAG: --use-legacy-policy-config="false"
I0522 03:29:03.698296       1 flags.go:33] FLAG: --v="4"
I0522 03:29:03.698300       1 flags.go:33] FLAG: --version="false"
I0522 03:29:03.698309       1 flags.go:33] FLAG: --vmodule=""
I0522 03:29:03.698313       1 flags.go:33] FLAG: --write-config-to=""
I0522 03:29:05.321070       1 serving.go:319] Generated self-signed cert in-memory
W0522 03:29:06.616843       1 options.go:300] Neither --kubeconfig nor --master was specified. Using default API client. This might not work.
I0522 03:29:06.616918       1 merged_client_builder.go:122] Using in-cluster configuration
I0522 03:29:06.619146       1 server.go:142] Version: v1.14.9
I0522 03:29:06.619195       1 defaults.go:87] TaintNodesByCondition is enabled, PodToleratesNodeTaints predicate is mandatory
I0522 03:29:06.619206       1 server.go:161] Starting Kubernetes Scheduler version v1.14.9
I0522 03:29:06.623142       1 factory.go:341] Creating scheduler from configuration: {{ } [{NoVolumeZoneConflict <nil>} {MaxEBSVolumeCount <nil>} {MaxAzureDiskVolumeCount <nil>} {NoDiskConflict <nil>} {GeneralPredicates <nil>} {PodToleratesNodeTaints <nil>} {CheckVolumeBinding <nil>} {MaxGCEPDVolumeCount <nil>} {MatchInterPodAffinity <nil>} {CheckVolumeBinding <nil>}] [{SelectorSpreadPriority 1 <nil>} {InterPodAffinityPriority 1 <nil>} {LeastRequestedPriority 1 <nil>} {BalancedResourceAllocation 1 <nil>} {NodePreferAvoidPodsPriority 1 <nil>} {NodeAffinityPriority 1 <nil>} {TaintTolerationPriority 1 <nil>}] [{http://127.0.0.1:10262/scheduler filter preempt  1  false <nil> 30s false [] false}] 0 false}
I0522 03:29:06.623199       1 factory.go:358] Registering predicate: NoVolumeZoneConflict
I0522 03:29:06.623208       1 plugins.go:236] Predicate type NoVolumeZoneConflict already registered, reusing.
I0522 03:29:06.623213       1 factory.go:358] Registering predicate: MaxEBSVolumeCount
I0522 03:29:06.623221       1 plugins.go:236] Predicate type MaxEBSVolumeCount already registered, reusing.
I0522 03:29:06.623227       1 factory.go:358] Registering predicate: MaxAzureDiskVolumeCount
I0522 03:29:06.623231       1 plugins.go:236] Predicate type MaxAzureDiskVolumeCount already registered, reusing.
I0522 03:29:06.623234       1 factory.go:358] Registering predicate: NoDiskConflict
I0522 03:29:06.623237       1 plugins.go:236] Predicate type NoDiskConflict already registered, reusing.
I0522 03:29:06.623241       1 factory.go:358] Registering predicate: GeneralPredicates
I0522 03:29:06.623244       1 plugins.go:236] Predicate type GeneralPredicates already registered, reusing.
I0522 03:29:06.623248       1 factory.go:358] Registering predicate: PodToleratesNodeTaints
I0522 03:29:06.623255       1 plugins.go:236] Predicate type PodToleratesNodeTaints already registered, reusing.
I0522 03:29:06.623258       1 factory.go:358] Registering predicate: CheckVolumeBinding
I0522 03:29:06.623261       1 plugins.go:236] Predicate type CheckVolumeBinding already registered, reusing.
I0522 03:29:06.623264       1 factory.go:358] Registering predicate: MaxGCEPDVolumeCount
I0522 03:29:06.623267       1 plugins.go:236] Predicate type MaxGCEPDVolumeCount already registered, reusing.
I0522 03:29:06.623271       1 factory.go:358] Registering predicate: MatchInterPodAffinity
I0522 03:29:06.623274       1 plugins.go:236] Predicate type MatchInterPodAffinity already registered, reusing.
I0522 03:29:06.623278       1 factory.go:358] Registering predicate: CheckVolumeBinding
I0522 03:29:06.623285       1 plugins.go:236] Predicate type CheckVolumeBinding already registered, reusing.
I0522 03:29:06.623289       1 factory.go:373] Registering priority: SelectorSpreadPriority
I0522 03:29:06.623293       1 plugins.go:348] Priority type SelectorSpreadPriority already registered, reusing.
I0522 03:29:06.623300       1 factory.go:373] Registering priority: InterPodAffinityPriority
I0522 03:29:06.623306       1 plugins.go:348] Priority type InterPodAffinityPriority already registered, reusing.
I0522 03:29:06.623313       1 factory.go:373] Registering priority: LeastRequestedPriority
I0522 03:29:06.623319       1 plugins.go:348] Priority type LeastRequestedPriority already registered, reusing.
I0522 03:29:06.623326       1 factory.go:373] Registering priority: BalancedResourceAllocation
I0522 03:29:06.623330       1 plugins.go:348] Priority type BalancedResourceAllocation already registered, reusing.
I0522 03:29:06.623334       1 factory.go:373] Registering priority: NodePreferAvoidPodsPriority
I0522 03:29:06.623340       1 plugins.go:348] Priority type NodePreferAvoidPodsPriority already registered, reusing.
I0522 03:29:06.623345       1 factory.go:373] Registering priority: NodeAffinityPriority
I0522 03:29:06.623348       1 plugins.go:348] Priority type NodeAffinityPriority already registered, reusing.
I0522 03:29:06.623355       1 factory.go:373] Registering priority: TaintTolerationPriority
I0522 03:29:06.623360       1 plugins.go:348] Priority type TaintTolerationPriority already registered, reusing.
I0522 03:29:06.623366       1 factory.go:382] Creating extender with config {URLPrefix:http://127.0.0.1:10262/scheduler FilterVerb:filter PreemptVerb:preempt PrioritizeVerb: Weight:1 BindVerb: EnableHTTPS:false TLSConfig:<nil> HTTPTimeout:30s NodeCacheCapable:false ManagedResources:[] Ignorable:false}
I0522 03:29:06.623399       1 factory.go:412] Creating scheduler with fit predicates 'map[CheckVolumeBinding:{} GeneralPredicates:{} MatchInterPodAffinity:{} MaxAzureDiskVolumeCount:{} MaxEBSVolumeCount:{} MaxGCEPDVolumeCount:{} NoDiskConflict:{} NoVolumeZoneConflict:{} PodToleratesNodeTaints:{}]' and priority functions 'map[BalancedResourceAllocation:{} InterPodAffinityPriority:{} LeastRequestedPriority:{} NodeAffinityPriority:{} NodePreferAvoidPodsPriority:{} SelectorSpreadPriority:{} TaintTolerationPriority:{}]'
W0522 03:29:06.624183       1 authorization.go:47] Authorization is disabled
W0522 03:29:06.624192       1 authentication.go:55] Authentication is disabled
I0522 03:29:06.624199       1 deprecated_insecure_serving.go:49] Serving healthz insecurely on [::]:10261
I0522 03:29:06.624672       1 secure_serving.go:116] Serving securely on [::]:10259
I0522 03:29:06.698320       1 reflector.go:123] Starting reflector *v1.Pod (0s) from k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:223
I0522 03:29:06.698337       1 reflector.go:161] Listing and watching *v1.Pod from k8s.io/kubernetes/cmd/kube-scheduler/app/server.go:223
I0522 03:29:06.698341       1 reflector.go:123] Starting reflector *v1.StorageClass (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698352       1 reflector.go:161] Listing and watching *v1.StorageClass from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698354       1 reflector.go:123] Starting reflector *v1.Node (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698363       1 reflector.go:161] Listing and watching *v1.Node from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698405       1 reflector.go:123] Starting reflector *v1.PersistentVolumeClaim (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698419       1 reflector.go:161] Listing and watching *v1.PersistentVolumeClaim from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698445       1 reflector.go:123] Starting reflector *v1.PersistentVolume (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698465       1 reflector.go:161] Listing and watching *v1.PersistentVolume from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698490       1 reflector.go:123] Starting reflector *v1.StatefulSet (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698504       1 reflector.go:161] Listing and watching *v1.StatefulSet from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698508       1 reflector.go:123] Starting reflector *v1.ReplicaSet (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698526       1 reflector.go:161] Listing and watching *v1.ReplicaSet from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698571       1 reflector.go:123] Starting reflector *v1.Service (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698579       1 reflector.go:123] Starting reflector *v1.ReplicationController (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698586       1 reflector.go:123] Starting reflector *v1beta1.PodDisruptionBudget (0s) from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698586       1 reflector.go:161] Listing and watching *v1.Service from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698590       1 reflector.go:161] Listing and watching *v1.ReplicationController from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.698592       1 reflector.go:161] Listing and watching *v1beta1.PodDisruptionBudget from k8s.io/client-go/informers/factory.go:133
I0522 03:29:06.898798       1 shared_informer.go:123] caches populated
I0522 03:29:07.098317       1 shared_informer.go:123] caches populated
I0522 03:29:07.198457       1 shared_informer.go:123] caches populated
I0522 03:29:07.298617       1 shared_informer.go:123] caches populated
I0522 03:29:07.399147       1 shared_informer.go:123] caches populated
I0522 03:29:07.499338       1 shared_informer.go:123] caches populated
I0522 03:29:07.599749       1 shared_informer.go:123] caches populated
I0522 03:29:08.699910       1 shared_informer.go:123] caches populated
I0522 03:29:08.800120       1 shared_informer.go:123] caches populated
I0522 03:29:08.800165       1 controller_utils.go:1027] Waiting for caches to sync for scheduler controller
I0522 03:29:08.900309       1 shared_informer.go:123] caches populated
I0522 03:29:08.900324       1 controller_utils.go:1034] Caches are synced for scheduler controller
I0522 03:29:08.900425       1 leaderelection.go:217] attempting to acquire leader lease  tidb-operator/tidb-scheduler...
I0522 03:29:08.906451       1 leaderelection.go:326] lock is held by tidb-scheduler-5d958b4cd6-wzpnz_63a0d03a-9bd6-11ea-ab78-9eaa11974bb9 and has not yet expired
I0522 03:29:08.906465       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0522 03:29:12.339018       1 leaderelection.go:326] lock is held by tidb-scheduler-5d958b4cd6-wzpnz_63a0d03a-9bd6-11ea-ab78-9eaa11974bb9 and has not yet expired
I0522 03:29:12.339037       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0522 03:29:15.184314       1 leaderelection.go:326] lock is held by tidb-scheduler-5d958b4cd6-wzpnz_63a0d03a-9bd6-11ea-ab78-9eaa11974bb9 and has not yet expired
I0522 03:29:15.184331       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0522 03:29:18.840088       1 leaderelection.go:326] lock is held by tidb-scheduler-5d958b4cd6-wzpnz_63a0d03a-9bd6-11ea-ab78-9eaa11974bb9 and has not yet expired
I0522 03:29:18.840104       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0522 03:29:22.056019       1 leaderelection.go:326] lock is held by tidb-scheduler-5d958b4cd6-wzpnz_63a0d03a-9bd6-11ea-ab78-9eaa11974bb9 and has not yet expired
I0522 03:29:22.056033       1 leaderelection.go:222] failed to acquire lease tidb-operator/tidb-scheduler
I0522 03:29:24.154258       1 leaderelection.go:227] successfully acquired lease tidb-operator/tidb-scheduler
I0522 03:29:24.254478       1 shared_informer.go:123] caches populated
I0522 03:32:01.640987       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-0
I0522 03:32:01.641004       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-0
I0522 03:32:01.641577       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.641631       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.641643       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.645063       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-0", PVC "zzzdemo1-tidb/pd-tidb-pd-0" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:01.645085       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-0" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:01.716922       1 scheduler_binder.go:269] AssumePodVolumes for pod "zzzdemo1-tidb/tidb-pd-0", node "ip-10-136-94-171.us-west-2.compute.internal"
E0522 03:32:01.716965       1 factory.go:660] Error scheduling zzzdemo1-tidb/tidb-pd-0: v1.PersistentVolumeClaim "zzzdemo1-tidb/pd-tidb-pd-0" is out of sync (stored: 802698491, assume: 802698472); retrying
I0522 03:32:01.716989       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-0 to (PodScheduled==False, Reason=SchedulerError)
E0522 03:32:01.731165       1 scheduler.go:501] error assuming volumes: v1.PersistentVolumeClaim "zzzdemo1-tidb/pd-tidb-pd-0" is out of sync (stored: 802698491, assume: 802698472)
I0522 03:32:01.731224       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-1
I0522 03:32:01.731236       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:32:01.731825       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.731873       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.731881       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.735069       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:01.735089       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:01.801941       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-1: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:01.802048       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:01.857244       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:01.857261       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:01.857269       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:01.857566       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857580       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857601       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857609       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857610       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857611       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857617       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857650       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.857661       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.860554       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:01.860574       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:01.860680       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:01.860698       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:01.861319       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:01.861352       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
E0522 03:32:01.862615       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:32:01.862670       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-2
I0522 03:32:01.862679       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:32:01.863023       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.863065       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.863075       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.865750       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:01.865765       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:01.908751       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-2: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:01.908801       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:01.934775       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:01.934791       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:01.934799       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:01.935103       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935121       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935124       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935140       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935150       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935157       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935158       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935166       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.935169       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.938128       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:01.938151       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0522 03:32:01.938168       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:01.938184       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:01.938283       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:01.938304       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
E0522 03:32:01.939129       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:32:01.939177       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-0
I0522 03:32:01.939193       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-0
I0522 03:32:01.939513       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.939553       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.939562       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:01.942951       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-0", PVC "zzzdemo1-tidb/pd-tidb-pd-0" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:01.942968       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-0" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:02.262479       1 trace.go:81] Trace[2014437324]: "Scheduling zzzdemo1-tidb/tidb-pd-0" (started: 2020-05-22 03:32:01.939197601 +0000 UTC m=+178.412918817) (total time: 323.252144ms):
Trace[2014437324]: [11.01µs] [11.01µs] Computing predicates
Trace[2014437324]: [323.249472ms] [323.238462ms] Prioritizing
Trace[2014437324]: [323.252144ms] [2.672µs] END
I0522 03:32:02.262515       1 scheduler_binder.go:269] AssumePodVolumes for pod "zzzdemo1-tidb/tidb-pd-0", node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:02.262534       1 scheduler_assume_cache.go:319] Assumed v1.PersistentVolumeClaim "zzzdemo1-tidb/pd-tidb-pd-0", version 802698491
I0522 03:32:02.262577       1 scheduler_binder.go:344] BindPodVolumes for pod "zzzdemo1-tidb/tidb-pd-0", node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:02.262612       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-1
I0522 03:32:02.262636       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:32:02.263009       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.263023       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.263067       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.263076       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.263084       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.263095       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.266317       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:02.266339       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:02.655869       1 trace.go:81] Trace[994294910]: "Scheduling zzzdemo1-tidb/tidb-pd-1" (started: 2020-05-22 03:32:02.26264039 +0000 UTC m=+178.736361945) (total time: 393.160021ms):
Trace[994294910]: [26.233µs] [26.233µs] Computing predicates
Trace[994294910]: [393.160021ms] [393.133788ms] END
I0522 03:32:02.655931       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-1: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:02.655968       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:02.661835       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:02.661849       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:02.661856       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:02.662225       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662227       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662242       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662268       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662275       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662284       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662294       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662302       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662276       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662227       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662439       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.662452       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.665290       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:02.665312       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:02.667420       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:02.667446       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:02.667514       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:02.667528       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
E0522 03:32:02.668271       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:32:02.668395       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-2
I0522 03:32:02.668406       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:32:02.668731       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.668744       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.668776       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.668783       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.668789       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.668793       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:02.671520       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:02.671538       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:02.801092       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:03.256049       1 trace.go:81] Trace[930915676]: "Scheduling zzzdemo1-tidb/tidb-pd-2" (started: 2020-05-22 03:32:02.668409148 +0000 UTC m=+179.142130352) (total time: 587.6099ms):
Trace[930915676]: [9.634µs] [9.634µs] Computing predicates
Trace[930915676]: [587.6099ms] [587.600266ms] END
I0522 03:32:03.256096       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-2: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:03.256132       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:03.260840       1 backoff_utils.go:79] Backing off 2s
I0522 03:32:03.260964       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:03.260976       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:03.260981       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:03.261315       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261319       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261334       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261349       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261351       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261352       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261361       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261361       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261388       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261400       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261410       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.261423       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.264317       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:03.264339       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:03.264632       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:03.264653       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0522 03:32:03.265934       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:03.265958       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
E0522 03:32:03.266937       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:32:03.801199       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:03.801240       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-1
I0522 03:32:03.801250       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:32:03.801604       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.801618       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.801658       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.801666       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.801672       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.801677       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.804790       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:03.804812       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:03.856959       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-1: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:03.856988       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:03.862219       1 backoff_utils.go:79] Backing off 2s
I0522 03:32:03.862727       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:03.862737       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:03.862742       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:03.863049       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863052       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863057       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863066       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863080       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863087       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863087       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863087       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863094       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863096       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863102       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.863106       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:03.866049       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:03.866066       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0522 03:32:03.866074       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:03.866085       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:03.866091       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:03.866097       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
E0522 03:32:03.866785       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:32:04.801317       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:05.801449       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:05.801471       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-2
I0522 03:32:05.801481       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:32:05.801848       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.801862       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.801901       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.801909       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.801915       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.801920       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.805092       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:05.805113       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:05.815492       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-2: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:05.815527       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:05.820226       1 backoff_utils.go:79] Backing off 4s
I0522 03:32:05.820226       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:05.820243       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:05.820248       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:05.820555       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820560       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820561       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820576       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820595       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820597       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820598       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820603       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820602       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820609       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820611       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.820615       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:05.823530       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:05.823534       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:05.823553       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:05.823554       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0522 03:32:05.899480       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:05.899499       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
E0522 03:32:05.900263       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:32:06.801574       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-1
I0522 03:32:06.801593       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:32:06.801576       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:06.802028       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.802047       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.802098       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.802108       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.802117       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.802125       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.805195       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:06.805217       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:06.821049       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-1: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:06.821097       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:06.826524       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:06.826527       1 backoff_utils.go:79] Backing off 4s
I0522 03:32:06.826538       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:06.826544       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:06.826860       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826868       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826868       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826875       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826902       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826904       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826908       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826904       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826914       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826914       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826921       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-0 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.826918       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:06.829895       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:06.829914       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:06.831937       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:06.831963       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:06.832100       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:06.832114       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
E0522 03:32:06.832810       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:32:07.801708       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:08.801787       1 cache.go:643] Couldn't expire cache for pod zzzdemo1-tidb/tidb-pd-0. Binding is still in progress.
I0522 03:32:09.271376       1 scheduler_binder.go:559] All PVCs for pod "zzzdemo1-tidb/tidb-pd-0" are bound
I0522 03:32:09.271410       1 factory.go:733] Attempting to bind tidb-pd-0 to ip-10-136-94-171.us-west-2.compute.internal
I0522 03:32:09.277103       1 scheduler.go:572] pod zzzdemo1-tidb/tidb-pd-0 is bound successfully on node ip-10-136-94-171.us-west-2.compute.internal, 25 nodes evaluated, 1 nodes were found feasible
I0522 03:32:10.802040       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-2
I0522 03:32:10.802066       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:32:10.802477       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.802535       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.802546       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.805666       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:10.805687       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:10.845776       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-2: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:10.845807       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:10.851338       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:10.851341       1 backoff_utils.go:79] Backing off 8s
I0522 03:32:10.851350       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:10.851358       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:10.851692       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851692       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851727       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851730       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851735       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851737       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851692       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851812       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.851822       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:10.854610       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:10.854626       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:10.854857       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:10.854874       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:10.860688       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:10.860714       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
E0522 03:32:10.861454       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:32:11.802186       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-1
I0522 03:32:11.802202       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:32:11.802604       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.802685       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.802702       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.808170       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:11.808201       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:11.819059       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-1: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:11.819093       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:11.824442       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:11.824455       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:11.824462       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:11.824511       1 backoff_utils.go:79] Backing off 8s
I0522 03:32:11.824764       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824776       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824775       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824795       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824804       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824805       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824809       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824813       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.824817       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:11.827883       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:11.827889       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:11.827902       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:11.827906       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0522 03:32:11.827913       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:11.827929       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
E0522 03:32:11.828641       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:32:19.802973       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-2
I0522 03:32:19.802989       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:32:19.803537       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.803591       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.803602       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.806907       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:19.806927       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:19.826604       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-2: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:32:19.826644       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:32:19.831432       1 backoff_utils.go:79] Backing off 10s
I0522 03:32:19.831455       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:19.831462       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:19.831470       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:32:19.831799       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831800       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831816       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831834       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831842       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831843       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831844       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831854       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.831854       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:32:19.835058       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:32:19.835081       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:32:19.835265       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:32:19.835299       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:32:19.841333       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:32:19.841353       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
E0522 03:32:19.842164       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.
I0522 03:33:23.984811       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-1
I0522 03:33:23.984827       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-1
I0522 03:33:23.985400       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:23.985460       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:23.985472       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:23.988821       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:33:23.988842       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:33:23.998894       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-1: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:33:23.998923       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-1 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:33:24.003490       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:33:24.003503       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:33:24.003507       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:33:24.003809       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003819       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003823       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003849       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003851       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003853       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003863       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003866       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.003864       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-1 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.006888       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:33:24.006908       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
I0522 03:33:24.006911       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:33:24.006927       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:33:24.006953       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-1", PVC "zzzdemo1-tidb/pd-tidb-pd-1" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:33:24.006971       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-1" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
E0522 03:33:24.007688       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-1.
I0522 03:33:24.007721       1 scheduling_queue.go:908] About to try and schedule pod zzzdemo1-tidb/tidb-pd-2
I0522 03:33:24.007730       1 scheduler.go:453] Attempting to schedule pod: zzzdemo1-tidb/tidb-pd-2
I0522 03:33:24.008057       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.008098       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.008112       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.010965       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:33:24.010983       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:33:24.030284       1 factory.go:647] Unable to schedule zzzdemo1-tidb/tidb-pd-2: no fit: 0/25 nodes are available: 2 Insufficient cpu, 22 node(s) didn't match node selector.; waiting
I0522 03:33:24.030310       1 factory.go:742] Updating pod condition for zzzdemo1-tidb/tidb-pd-2 to (PodScheduled==False, Reason=Unschedulable)
I0522 03:33:24.034783       1 generic_scheduler.go:1118] Node ip-10-136-135-87.us-west-2.compute.internal is a potential node for preemption.
I0522 03:33:24.034794       1 generic_scheduler.go:1118] Node ip-10-136-100-18.us-west-2.compute.internal is a potential node for preemption.
I0522 03:33:24.034797       1 generic_scheduler.go:1118] Node ip-10-136-94-171.us-west-2.compute.internal is a potential node for preemption.
I0522 03:33:24.035112       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035128       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035131       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035136       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035150       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035156       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035168       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035171       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.035180       1 predicates.go:452] PVC zzzdemo1-tidb/pd-tidb-pd-2 is not bound, assuming PVC matches predicate when counting limits
I0522 03:33:24.037958       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-100-18.us-west-2.compute.internal"
I0522 03:33:24.037960       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-94-171.us-west-2.compute.internal"
I0522 03:33:24.038085       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-94-171.us-west-2.compute.internal" ...
I0522 03:33:24.097998       1 scheduler_binder.go:697] No matching volumes for Pod "zzzdemo1-tidb/tidb-pd-2", PVC "zzzdemo1-tidb/pd-tidb-pd-2" on node "ip-10-136-135-87.us-west-2.compute.internal"
I0522 03:33:24.098007       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-100-18.us-west-2.compute.internal" ...
I0522 03:33:24.098022       1 scheduler_binder.go:752] Provisioning for claims of pod "zzzdemo1-tidb/tidb-pd-2" that has no matching volumes on node "ip-10-136-135-87.us-west-2.compute.internal" ...
E0522 03:33:24.098755       1 scheduler.go:299] Error preempting victims to make room for zzzdemo1-tidb/tidb-pd-2.

(updated with more logs)

@tirsen
Copy link
Contributor

tirsen commented May 22, 2020

$ kubectl -n zzzdemo1-tidb get pods
Running: SQM_ENV=staging SQM_REGION=us-west-2 /Users/jontirsen/Development/go/bin/sqm --admin kubectl -- -n zzzdemo1-tidb get pods
NAME                               READY   STATUS    RESTARTS   AGE
tidb-discovery-5765dff886-nbwfk    1/1     Running   0          4m36s
tidb-monitor-6bccdf9889-h78z7      3/3     Running   0          4m36s
tidb-pd-0                          1/1     Running   0          4m36s
tidb-pd-1                          0/1     Pending   0          4m36s
tidb-pd-2                          0/1     Pending   0          4m36s
tidb-tidb-debug-56c78bf565-tct86   1/1     Running   0          4m37s

@cofyc
Copy link
Contributor Author

cofyc commented May 22, 2020

I0522 03:00:33.699811       1 scheduler.go:193] preempting for pod zzzdemo1-tidb/tidb-pd-1
I0522 03:00:33.699828       1 scheduler.go:209] entering preempt/predicate: HAScheduling, nodes: []
I0522 03:00:33.699836       1 scheduler.go:211] leaving preempt/predicate: HAScheduling, nodes: []
E0522 03:00:33.699842       1 mux.go:134] unable to preempt nodes: no nodes available to schedule pods zzzdemo1-tidb/tidb-pd-1

The potential nodes are sent to the extender but not parsed from JSON string correctly. There is a bug in Kubernetes 1.16.0 and before that the JSON tag in ExtenderPreemptionArg is wrong. I'll fix it soon.

https://github.com/kubernetes/kubernetes/blob/v1.16.0/pkg/scheduler/api/v1/types.go#L270

@cofyc
Copy link
Contributor Author

cofyc commented May 22, 2020

hi, @mightyguava @tirsen

PR is updated, can you build the image and try again? I've verified it manually with this example, the scheduler evicts all overprovisioning pods and schedule pods onto the nodes. We will add an integration or e2e test for this scenario.

@mightyguava
Copy link
Contributor

Yes! This works! This is awesome. The overprovisioning pods were successfully preempted, the tidb pods scheduled, and new ec2 nodes were created to run the overprovisioning pods

@cofyc
Copy link
Contributor Author

cofyc commented May 25, 2020

Great!

Copy link
Contributor

@DanielZhangQD DanielZhangQD left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@cofyc
Copy link
Contributor Author

cofyc commented May 25, 2020

/run-e2e-tests

1 similar comment
@cofyc
Copy link
Contributor Author

cofyc commented May 25, 2020

/run-e2e-tests

@cofyc
Copy link
Contributor Author

cofyc commented May 25, 2020

/merge

@sre-bot
Copy link
Contributor

sre-bot commented May 25, 2020

/run-all-tests

@sre-bot
Copy link
Contributor

sre-bot commented May 25, 2020

@cofyc merge failed.

@cofyc
Copy link
Contributor Author

cofyc commented May 25, 2020

/run-e2e-tests

@cofyc cofyc merged commit dd1fc1c into pingcap:master May 25, 2020
@cofyc
Copy link
Contributor Author

cofyc commented May 26, 2020

/run-cherry-picker

sre-bot pushed a commit to sre-bot/tidb-operator that referenced this pull request May 26, 2020
@sre-bot
Copy link
Contributor

sre-bot commented May 26, 2020

cherry pick to release-1.1 in PR #2555

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

scheduler doesn't account for priority
6 participants