K8S集群性能测试-clusterloader

1
2
3

export GOPATH=/home/wangb/goprojects
cd $GOPATH/src/k8s.io/perf-tests/clusterloader2
go build -o clusterloader './cmd/'

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25

# 进入clusterloader可执行文件目录，配置文件也需转移到了此位置
cd /home/wangb/perf-test/clusterloader2
# ssh访问参数
export KUBE_SSH_KEY_PATH=/root/.ssh/id_rsa
# master节点信息
MASTER_NAME=node1
TEST_MASTER_IP=192.168.182.101
TEST_MASTER_INTERNAL_IP=192.168.182.101
KUBE_CONFIG=${HOME}/.kube/config
# 测试配置文件
TEST_CONFIG='/home/wangb/perf-test/clusterloader2/testing/density/config2.yaml'
# 测试报告目录位置
REPORT_DIR='./reports'
# 测试日志打印文件
LOG_FILE='test.log'


./clusterloader --kubeconfig=$KUBE_CONFIG \
    --mastername=$TEST_MASTER_IP \
    --masterip=$MASTER_IP \
    --master-internal-ip=TEST_MASTER_INTERNAL_IP \
    --testconfig=$TEST_CONFIG \
    --report-dir=$REPORT_DIR \
    --alsologtostderr 2>&1 | tee $LOG_FILE

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203

# ASSUMPTIONS:
# - Underlying cluster should have 100+ nodes.
# - Number of nodes should be divisible by NODES_PER_NAMESPACE (default 100).

#Constants
{{$DENSITY_RESOURCE_CONSTRAINTS_FILE := DefaultParam .DENSITY_RESOURCE_CONSTRAINTS_FILE ""}}
{{$NODE_MODE := DefaultParam .NODE_MODE "allnodes"}}
{{$NODES_PER_NAMESPACE := DefaultParam .NODES_PER_NAMESPACE 100}}
{{$PODS_PER_NODE := DefaultParam .PODS_PER_NODE 30}}
{{$DENSITY_TEST_THROUGHPUT := DefaultParam .DENSITY_TEST_THROUGHPUT 20}}
# LATENCY_POD_MEMORY and LATENCY_POD_CPU are calculated for 1-core 4GB node.
# Increasing allocation of both memory and cpu by 10%
# decreases the value of priority function in scheduler by one point.
# This results in decreased probability of choosing the same node again.
{{$LATENCY_POD_CPU := DefaultParam .LATENCY_POD_CPU 100}}
{{$LATENCY_POD_MEMORY := DefaultParam .LATENCY_POD_MEMORY 350}}
{{$MIN_LATENCY_PODS := 500}}
{{$MIN_SATURATION_PODS_TIMEOUT := 180}}
{{$ENABLE_CHAOSMONKEY := DefaultParam .ENABLE_CHAOSMONKEY false}}
{{$ENABLE_SYSTEM_POD_METRICS:= DefaultParam .ENABLE_SYSTEM_POD_METRICS true}}
{{$ENABLE_RESTART_COUNT_CHECK := DefaultParam .ENABLE_RESTART_COUNT_CHECK false}}
{{$RESTART_COUNT_THRESHOLD_OVERRIDES:= DefaultParam .RESTART_COUNT_THRESHOLD_OVERRIDES ""}}
#Variables
{{$namespaces := DivideInt .Nodes $NODES_PER_NAMESPACE}}
{{$podsPerNamespace := MultiplyInt $PODS_PER_NODE $NODES_PER_NAMESPACE}}
{{$totalPods := MultiplyInt $podsPerNamespace $namespaces}}
{{$latencyReplicas := DivideInt (MaxInt $MIN_LATENCY_PODS .Nodes) $namespaces}}
{{$totalLatencyPods := MultiplyInt $namespaces $latencyReplicas}}
{{$saturationRCTimeout := DivideFloat $totalPods $DENSITY_TEST_THROUGHPUT | AddInt $MIN_SATURATION_PODS_TIMEOUT}}
# saturationRCHardTimeout must be at least 20m to make sure that ~10m node
# failure won't fail the test. See https://github.com/kubernetes/kubernetes/issues/73461#issuecomment-467338711
{{$saturationRCHardTimeout := MaxInt $saturationRCTimeout 1200}}

name: density
automanagedNamespaces: {{$namespaces}}
tuningSets:
- name: Uniform5qps
  qpsLoad:
    qps: 5
{{if $ENABLE_CHAOSMONKEY}}
chaosMonkey:
  nodeFailure:
    failureRate: 0.01
    interval: 1m
    jitterFactor: 10.0
    simulatedDowntime: 10m
{{end}}
steps:
- measurements:
  - Identifier: APIResponsiveness
    Method: APIResponsiveness
    Params:
      action: reset
  - Identifier: TestMetrics
    Method: TestMetrics
    Params:
      action: start
      nodeMode: {{$NODE_MODE}}
      resourceConstraints: {{$DENSITY_RESOURCE_CONSTRAINTS_FILE}}
      systemPodMetricsEnabled: {{$ENABLE_SYSTEM_POD_METRICS}}
      restartCountThresholdOverrides: {{YamlQuote $RESTART_COUNT_THRESHOLD_OVERRIDES 4}}
      enableRestartCountCheck: {{$ENABLE_RESTART_COUNT_CHECK}}

# Create saturation pods
- measurements:
  - Identifier: SaturationPodStartupLatency
    Method: PodStartupLatency
    Params:
      action: start
      labelSelector: group = saturation
      threshold: {{$saturationRCTimeout}}s
- measurements:
  - Identifier: WaitForRunningSaturationRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: start
      apiVersion: v1
      kind: ReplicationController
      labelSelector: group = saturation
      operationTimeout: {{$saturationRCHardTimeout}}s
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: 1
    tuningSet: Uniform5qps
    objectBundle:
    - basename: saturation-rc
      objectTemplatePath: rc.yaml
      templateFillMap:
        Replicas: {{$podsPerNamespace}}
        Group: saturation
        CpuRequest: 1m
        MemoryRequest: 10M
- measurements:
  - Identifier: SchedulingThroughput
    Method: SchedulingThroughput
    Params:
      action: start
      labelSelector: group = saturation
- measurements:
  - Identifier: WaitForRunningSaturationRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- measurements:
  - Identifier: SaturationPodStartupLatency
    Method: PodStartupLatency
    Params:
      action: gather
- measurements:
  - Identifier: SchedulingThroughput
    Method: SchedulingThroughput
    Params:
      action: gather
- name: Creating saturation pods
# Create latency pods
- measurements:
  - Identifier: PodStartupLatency
    Method: PodStartupLatency
    Params:
      action: start
      labelSelector: group = latency
- measurements:
  - Identifier: WaitForRunningLatencyRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: start
      apiVersion: v1
      kind: ReplicationController
      labelSelector: group = latency
      operationTimeout: 15m
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: {{$latencyReplicas}}
    tuningSet: Uniform5qps
    objectBundle:
    - basename: latency-pod-rc
      objectTemplatePath: rc.yaml
      templateFillMap:
        Replicas: 1
        Group: latency
        CpuRequest: {{$LATENCY_POD_CPU}}m
        MemoryRequest: {{$LATENCY_POD_MEMORY}}M
- measurements:
  - Identifier: WaitForRunningLatencyRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- name: Creating latency pods
# Remove latency pods
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: 0
    tuningSet: Uniform5qps
    objectBundle:
    - basename: latency-pod-rc
      objectTemplatePath: rc.yaml
- measurements:
  - Identifier: WaitForRunningLatencyRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- measurements:
  - Identifier: PodStartupLatency
    Method: PodStartupLatency
    Params:
      action: gather
- name: Deleting latancy pods
# Delete pods
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: 0
    tuningSet: Uniform5qps
    objectBundle:
    - basename: saturation-rc
      objectTemplatePath: rc.yaml
- measurements:
  - Identifier: WaitForRunningSaturationRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- name: Deleting saturation pods
# Collect measurements
- measurements:
  - Identifier: APIResponsiveness
    Method: APIResponsiveness
    Params:
      action: gather
  - Identifier: TestMetrics
    Method: TestMetrics
    Params:
      action: gather
      systemPodMetricsEnabled: {{$ENABLE_SYSTEM_POD_METRICS}}
      restartCountThresholdOverrides: {{YamlQuote $RESTART_COUNT_THRESHOLD_OVERRIDES 4}}
      enableRestartCountCheck: {{$ENABLE_RESTART_COUNT_CHECK}}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37

apiVersion: v1
kind: ReplicationController
metadata:
  name: {{.Name}}
  labels:
    group: {{.Group}}
spec:
  replicas: {{.Replicas}}
  selector:
    name: {{.Name}}
  template:
    metadata:
      labels:
        name: {{.Name}}
        group: {{.Group}}
    spec:
      containers:
      - image: k8s.gcr.io/pause:3.1
        imagePullPolicy: IfNotPresent
        name: {{.Name}}
        ports:
        resources:
          requests:
            cpu: {{.CpuRequest}}
            memory: {{.MemoryRequest}}
      # Add not-ready/unreachable tolerations for 15 minutes so that node
      # failure doesn't trigger pod deletion.
      tolerations:
      - key: "node.kubernetes.io/not-ready"
        operator: "Exists"
        effect: "NoExecute"
        tolerationSeconds: 900
      - key: "node.kubernetes.io/unreachable"
        operator: "Exists"
        effect: "NoExecute"
        tolerationSeconds: 900

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38

apiVersion: apps/v1
kind: Deployment
metadata:
  name: {{.Name}}
  labels:
    group: {{.Group}}
spec:
  replicas: {{.Replicas}}
  selector:
    matchLabels:
      name: {{.Name}}
  template:
    metadata:
      labels:
        name: {{.Name}}
        group: {{.Group}}
    spec:
      containers:
      - image: k8s.gcr.io/pause:3.1
        imagePullPolicy: IfNotPresent
        name: {{.Name}}
        ports:
        resources:
          requests:
            cpu: {{.CpuRequest}}
            memory: {{.MemoryRequest}}
      # Add not-ready/unreachable tolerations for 15 minutes so that node
      # failure doesn't trigger pod deletion.
      tolerations:
      - key: "node.kubernetes.io/not-ready"
        operator: "Exists"
        effect: "NoExecute"
        tolerationSeconds: 900
      - key: "node.kubernetes.io/unreachable"
        operator: "Exists"
        effect: "NoExecute"
        tolerationSeconds: 900

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

void main(){

    // 构造clusterLoaderConfig

    // 构造framework，即各种k8s client
    f, err := framework.NewFramework(
        &clusterLoaderConfig.ClusterConfig,
        getClientsNumber(clusterLoaderConfig.ClusterConfig.Nodes),
    )
    // 遍历测试配置文件（可多个），按配置用例运行测试
    for _, clusterLoaderConfig.TestConfigPath = range testConfigPaths {
        test.RunTest(f, prometheusFramework, &clusterLoaderConfig)
    }
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

// RunTest runs test based on provided test configuration.
func RunTest(clusterFramework, prometheusFramework *framework.Framework, clusterLoaderConfig *config.ClusterLoaderConfig) *errors.ErrorList {

    // simpleContext上下文信息
    ctx := CreateContext(clusterLoaderConfig, clusterFramework, prometheusFramework, state.NewState())
    testConfigFilename := filepath.Base(clusterLoaderConfig.TestConfigPath)
    // 按参数 设置override config 和 nodes参数
    mapping, errList := config.GetMapping(clusterLoaderConfig)
    if errList != nil {
        return errList
    }
    // 使用emplateProvider根据mapping信息把testConfig的模板文件渲染成可用的api.Config
    testConfig, err := ctx.GetTemplateProvider().TemplateToConfig(testConfigFilename, mapping)
    if err != nil {
        return errors.NewErrorList(fmt.Errorf("config reading error: %v", err))
    }
    return Test.ExecuteTest(ctx, testConfig)
}

// api.Config 定义
// Config is a structure that represents configuration
// for a single test scenario.
type Config struct {
    // Name of the test case.
    Name string `json: name`
    // AutomanagedNamespaces is a number of automanaged namespaces.
    AutomanagedNamespaces int32 `json: automanagedNamespaces`
    // Steps is a sequence of test steps executed in serial.
    Steps []Step `json: steps`
    // TuningSets is a collection of tuning sets that can be used by steps.
    TuningSets []TuningSet `json: tuningSets`
    // ChaosMonkey is a config for simulated component failures.
    ChaosMonkey ChaosMonkeyConfig `json: chaosMonkey`
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31

// ExecuteTest executes test based on provided configuration.
func (ste *simpleTestExecutor) ExecuteTest(ctx Context, conf *api.Config)  {

    // auto set test namespace
  ctx.GetClusterFramework().SetAutomanagedNamespacePrefix(fmt.Sprintf("test-%s", util.RandomDNS1123String(6)))
  // clear test resource
  defer cleanupResources(ctx)  
  // create test namespace
  err = ctx.GetClusterFramework().CreateAutomanagedNamespaces(int(conf.AutomanagedNamespaces))
  // 遍历steps，分步执行，如果某step出错stepErr，则退出。
  for i := range conf.Steps {
    if stepErrList := ste.ExecuteStep(ctx, &conf.Steps[i]); !stepErrList.IsEmpty() {
      errList.Concat(stepErrList)
      if isErrsCritical(stepErrList) {
        return errList
      }
    }
  }

  // 输出测试汇总信息
  for _, summary := range ctx.GetMeasurementManager().GetSummaries() {
    if ctx.GetClusterLoaderConfig().ReportDir == "" {
      klog.Infof("%v: %v", summary.SummaryName(), summary.SummaryContent())
    } else {
      // TODO(krzysied): Remember to keep original filename style for backward compatibility.
      filePath := path.Join(ctx.GetClusterLoaderConfig().ReportDir, summary.SummaryName()+"_"+conf.Name+"_"+summary.SummaryTime().Format(time.RFC3339)+"."+summary.SummaryExt())
      ioutil.WriteFile(filePath, []byte(summary.SummaryContent()), 0644)
    }
  }

}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

// ExecuteStep executes single test step based on provided step configuration.
func (ste *simpleTestExecutor) ExecuteStep(ctx Context, step *api.Step) *errors.ErrorList {
  var wg wait.Group
  errList := errors.NewErrorList()
  if len(step.Measurements) > 0 {
    for i := range step.Measurements {
      // index is created to make i value unchangeable during thread execution.
      index := i
      wg.Start(func() {
        err := ctx.GetMeasurementManager().Execute(step.Measurements[index].Method,
          step.Measurements[index].Identifier,
          step.Measurements[index].Params)
        if err != nil {
          errList.Append(fmt.Errorf("measurement call %s - %s error: %v", step.Measurements[index].Method, step.Measurements[index].Identifier, err))
        }
      })
    }
  } else {
    for i := range step.Phases {
      phase := &step.Phases[i]
      wg.Start(func() {
        if phaseErrList := ste.ExecutePhase(ctx, phase); !phaseErrList.IsEmpty() {
          errList.Concat(phaseErrList)
        }
      })
    }
  }
  wg.Wait()
  if step.Name != "" {
    klog.Infof("Step \"%s\" ended", step.Name)
  }
  return errList
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18

// Execute executes measurement based on provided identifier, methodName and params.
func (mm *MeasurementManager) Execute(methodName string, identifier string, params map[string]interface{}) error {
    measurementInstance, err := mm.getMeasurementInstance(methodName, identifier)
    if err != nil {
        return err
    }
    config := &MeasurementConfig{
        ClusterFramework:    mm.clusterFramework,
        PrometheusFramework: mm.prometheusFramework,
        Params:              params,
        TemplateProvider:    mm.templateProvider,
        Identifier:          identifier,
        CloudProvider:       mm.clusterLoaderConfig.ClusterConfig.Provider,
    }
    summaries, err := measurementInstance.Execute(config)
    mm.summaries = append(mm.summaries, summaries...)
    return err
}

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180

// Execute supports two actions:
// - start - Starts to observe pods and pods events.
// - gather - Gathers and prints current pod latency data.
// Does NOT support concurrency. Multiple calls to this measurement
// shouldn't be done within one step.
func (p *podStartupLatencyMeasurement) Execute(config *measurement.MeasurementConfig) ([]measurement.Summary, error) {
    action, err := util.GetString(config.Params, "action")
    if err != nil {
        return nil, err
    }

    switch action {
    case "start":
        p.namespace, err = util.GetStringOrDefault(config.Params, "namespace", metav1.NamespaceAll)
        if err != nil {
            return nil, err
        }
        p.labelSelector, err = util.GetStringOrDefault(config.Params, "labelSelector", "")
        if err != nil {
            return nil, err
        }
        p.fieldSelector, err = util.GetStringOrDefault(config.Params, "fieldSelector", "")
        if err != nil {
            return nil, err
        }
        p.threshold, err = util.GetDurationOrDefault(config.Params, "threshold", defaultPodStartupLatencyThreshold)
        if err != nil {
            return nil, err
        }
        return nil, p.start(config.ClusterFramework.GetClientSets().GetClient())
    case "gather":
        return p.gather(config.ClusterFramework.GetClientSets().GetClient(), config.Identifier)
    default:
        return nil, fmt.Errorf("unknown action %v", action)
    }

}
// 测试启动
func (p *podStartupLatencyMeasurement) start(c clientset.Interface) error {
    if p.isRunning {
        klog.Infof("%s: pod startup latancy measurement already running", p)
        return nil
    }
    p.selectorsString = measurementutil.CreateSelectorsString(p.namespace, p.labelSelector, p.fieldSelector)
    klog.Infof("%s: starting pod startup latency measurement...", p)
    p.isRunning = true
    p.stopCh = make(chan struct{})
    p.informer = informer.NewInformer(
        c,
        "pods",
        p.namespace,
        p.fieldSelector,
        p.labelSelector,
        // 使用checkPod回调处理，一旦pod状态为running，则更新测试工具保存的pod的start时间
        p.checkPod,
    )
    // 启动了监听该范围内的pod资源
    go p.informer.Run(p.stopCh)
    timeoutCh := make(chan struct{})
    timeoutTimer := time.AfterFunc(informerSyncTimeout, func() {
        close(timeoutCh)
    })
    defer timeoutTimer.Stop()
    if !cache.WaitForCacheSync(timeoutCh, p.informer.HasSynced) {
        return fmt.Errorf("timed out waiting for caches to sync")
    }
    return nil
}


// 测试收集
func (p *podStartupLatencyMeasurement) gather(c clientset.Interface, identifier string) ([]measurement.Summary, error) {
    klog.Infof("%s: gathering pod startup latency measurement...", p)
    // 检查podStartupLatencyMeasurement 是否已启动
    if !p.isRunning {
        return nil, fmt.Errorf("metric %s has not been started", podStartupLatencyMeasurementName)
    }

    scheduleLag := make([]measurementutil.LatencyData, 0)
    startupLag := make([]measurementutil.LatencyData, 0)
    watchLag := make([]measurementutil.LatencyData, 0)
    schedToWatchLag := make([]measurementutil.LatencyData, 0)
    e2eLag := make([]measurementutil.LatencyData, 0)

    p.stop()
    // 通过schedEvents方式获取调度器事件的create时间
    if err := p.gatherScheduleTimes(c); err != nil {
        return nil, err
    }
    // 遍历pod-createTime map，按pod生命周期逻辑，进行条件检查
    for key, create := range p.createTimes {
        sched, hasSched := p.scheduleTimes[key]
        if !hasSched {
            klog.Infof("%s: failed to find schedule time for %v", p, key)
        }
        run, ok := p.runTimes[key]
        if !ok {
            klog.Infof("%s: failed to find run time for %v", p, key)
            continue
        }
        watch, ok := p.watchTimes[key]
        if !ok {
            klog.Infof("%s: failed to find watch time for %v", p, key)
            continue
        }
        node, ok := p.nodeNames[key]
        if !ok {
            klog.Infof("%s: failed to find node for %v", p, key)
            continue
        }
        // 计算各种延时，重要。。。
        if hasSched {
            scheduleLag = append(scheduleLag, podLatencyData{Name: key, Node: node, Latency: sched.Time.Sub(create.Time)})
            startupLag = append(startupLag, podLatencyData{Name: key, Node: node, Latency: run.Time.Sub(sched.Time)})
            schedToWatchLag = append(schedToWatchLag, podLatencyData{Name: key, Node: node, Latency: watch.Time.Sub(sched.Time)})
        }
        watchLag = append(watchLag, podLatencyData{Name: key, Node: node, Latency: watch.Time.Sub(run.Time)})
        e2eLag = append(e2eLag, podLatencyData{Name: key, Node: node, Latency: watch.Time.Sub(create.Time)})
    }
    // 把各个pod的各延时指标值进行排序，排序目的是为了方便进行数据统计
    sort.Sort(measurementutil.LatencySlice(scheduleLag))
    sort.Sort(measurementutil.LatencySlice(startupLag))
    sort.Sort(measurementutil.LatencySlice(watchLag))
    sort.Sort(measurementutil.LatencySlice(schedToWatchLag))
    sort.Sort(measurementutil.LatencySlice(e2eLag))

    p.printLatencies(scheduleLag, "worst create-to-schedule latencies")
    p.printLatencies(startupLag, "worst schedule-to-run latencies")
    p.printLatencies(watchLag, "worst run-to-watch latencies")
    p.printLatencies(schedToWatchLag, "worst schedule-to-watch latencies")
    p.printLatencies(e2eLag, "worst e2e latencies")

    podStartupLatency := &podStartupLatency{
        CreateToScheduleLatency: measurementutil.ExtractLatencyMetrics(scheduleLag),
        ScheduleToRunLatency:    measurementutil.ExtractLatencyMetrics(startupLag),
        RunToWatchLatency:       measurementutil.ExtractLatencyMetrics(watchLag),
        ScheduleToWatchLatency:  measurementutil.ExtractLatencyMetrics(schedToWatchLag),
        E2ELatency:              measurementutil.ExtractLatencyMetrics(e2eLag),
    }
    // 成功率
    var err error
    if successRatio := float32(len(e2eLag)) / float32(len(p.createTimes)); successRatio < successfulStartupRatioThreshold {
        err = fmt.Errorf("only %v%% of all pods were scheduled successfully", successRatio*100)
        klog.Errorf("%s: %v", p, err)
    }
    // 设置阈值，这里各百分位数使用的都是相同阈值
    podStartupLatencyThreshold := &measurementutil.LatencyMetric{
        Perc50: p.threshold,
        Perc90: p.threshold,
        Perc99: p.threshold,
    }
    // 进行延时指标验证，判断是否满足slos，不满足则输出错误信息
    if slosErr := podStartupLatency.E2ELatency.VerifyThreshold(podStartupLatencyThreshold); slosErr != nil {
        err = errors.NewMetricViolationError("pod startup", slosErr.Error())
        klog.Errorf("%s: %v", p, err)
    }

    content, jsonErr := util.PrettyPrintJSON(podStartupLatencyToPerfData(podStartupLatency))
    if err != nil {
        return nil, jsonErr
    }
    summary := measurement.CreateSummary(fmt.Sprintf("%s_%s", podStartupLatencyMeasurementName, identifier), "json", content)
    return []measurement.Summary{summary}, err
}


// VerifyThreshold verifies latency metric against given percentile thresholds.
func (metric *LatencyMetric) VerifyThreshold(threshold *LatencyMetric) error {
    if metric.Perc50 > threshold.Perc50 {
        return fmt.Errorf("too high latency 50th percentile: %v", metric.Perc50)
    }
    if metric.Perc90 > threshold.Perc90 {
        return fmt.Errorf("too high latency 90th percentile: %v", metric.Perc90)
    }
    if metric.Perc99 > threshold.Perc99 {
        return fmt.Errorf("too high latency 99th percentile: %v", metric.Perc99)
    }
    return nil
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

// ExecutePhase executes single test phase based on provided phase configuration.
func (ste *simpleTestExecutor) ExecutePhase(ctx Context, phase *api.Phase) *errors.ErrorList {
    // TODO: add tuning set
    errList := errors.NewErrorList()
    nsList := createNamespacesList(ctx, phase.NamespaceRange)
    tuningSet, err := ctx.GetTuningSetFactory().CreateTuningSet(phase.TuningSet)

    instances, exists := ctx.GetState().GetNamespacesState().Get(nsName, id)
    // // ExecuteObject executes single test object operation based on provided object configuration.
    ste.ExecuteObject(ctx, &phase.ObjectBundle[j], nsName, replicaIndex, XXX)

    tuningSet.Execute(actions)
    
}

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206

# ASSUMPTIONS:
# - Underlying cluster should have 100+ nodes.
# - Number of nodes should be divisible by NODES_PER_NAMESPACE (default 100).

#Constants
{{$DENSITY_RESOURCE_CONSTRAINTS_FILE := DefaultParam .DENSITY_RESOURCE_CONSTRAINTS_FILE ""}}
#{{$NODE_MODE := DefaultParam .NODE_MODE "allnodes"}}
{{$NODE_MODE := DefaultParam .NODE_MODE "master"}}
{{$NODES_PER_NAMESPACE := DefaultParam .NODES_PER_NAMESPACE 1}}
{{$PODS_PER_NODE := DefaultParam .PODS_PER_NODE 2}}
{{$DENSITY_TEST_THROUGHPUT := DefaultParam .DENSITY_TEST_THROUGHPUT 20}}
# LATENCY_POD_MEMORY and LATENCY_POD_CPU are calculated for 1-core 4GB node.
# Increasing allocation of both memory and cpu by 10%
# decreases the value of priority function in scheduler by one point.
# This results in decreased probability of choosing the same node again.
{{$LATENCY_POD_CPU := DefaultParam .LATENCY_POD_CPU 5}}
{{$LATENCY_POD_MEMORY := DefaultParam .LATENCY_POD_MEMORY 3}}
{{$MIN_LATENCY_PODS := 20}}
{{$MIN_SATURATION_PODS_TIMEOUT := 180}}
{{$ENABLE_CHAOSMONKEY := DefaultParam .ENABLE_CHAOSMONKEY false}}
{{$ENABLE_SYSTEM_POD_METRICS:= DefaultParam .ENABLE_SYSTEM_POD_METRICS false}}
{{$ENABLE_RESTART_COUNT_CHECK := DefaultParam .ENABLE_RESTART_COUNT_CHECK false}}
{{$RESTART_COUNT_THRESHOLD_OVERRIDES:= DefaultParam .RESTART_COUNT_THRESHOLD_OVERRIDES ""}}
#Variables
{{$namespaces := DivideInt .Nodes $NODES_PER_NAMESPACE}}
{{$podsPerNamespace := MultiplyInt $PODS_PER_NODE $NODES_PER_NAMESPACE}}
{{$totalPods := MultiplyInt $podsPerNamespace $namespaces}}
{{$latencyReplicas := DivideInt (MaxInt $MIN_LATENCY_PODS .Nodes) $namespaces}}
{{$totalLatencyPods := MultiplyInt $namespaces $latencyReplicas}}
{{$saturationRCTimeout := DivideFloat $totalPods $DENSITY_TEST_THROUGHPUT | AddInt $MIN_SATURATION_PODS_TIMEOUT}}
# saturationRCHardTimeout must be at least 20m to make sure that ~10m node
# failure won't fail the test. See https://github.com/kubernetes/kubernetes/issues/73461#issuecomment-467338711
{{$saturationRCHardTimeout := MaxInt $saturationRCTimeout 1200}}

name: density
automanagedNamespaces: {{$namespaces}}
tuningSets:
- name: Uniform5qps
  qpsLoad:
    qps: 5
{{if $ENABLE_CHAOSMONKEY}}
chaosMonkey:
  nodeFailure:
    failureRate: 0.01
    interval: 1m
    jitterFactor: 10.0
    simulatedDowntime: 10m
{{end}}
steps:
- measurements:
  - Identifier: APIResponsiveness
    Method: APIResponsiveness
    Params:
      action: reset
  - Identifier: TestMetrics
    Method: TestMetrics
    Params:
      action: start
      nodeMode: {{$NODE_MODE}}
      resourceConstraints: {{$DENSITY_RESOURCE_CONSTRAINTS_FILE}}
      systemPodMetricsEnabled: {{$ENABLE_SYSTEM_POD_METRICS}}
      restartCountThresholdOverrides: {{YamlQuote $RESTART_COUNT_THRESHOLD_OVERRIDES 4}}
      enableRestartCountCheck: {{$ENABLE_RESTART_COUNT_CHECK}}

# Create saturation pods
- measurements:
  - Identifier: SaturationPodStartupLatency
    Method: PodStartupLatency
    Params:
      action: start
      labelSelector: group = saturation
      threshold: {{$saturationRCTimeout}}s
- measurements:
  - Identifier: WaitForRunningSaturationRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: start
      apiVersion: v1
      kind: ReplicationController
      labelSelector: group = saturation
      operationTimeout: {{$saturationRCHardTimeout}}s
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: 1
    tuningSet: Uniform5qps
    objectBundle:
    - basename: saturation-rc
      objectTemplatePath: rc.yaml
      templateFillMap:
        Replicas: {{$podsPerNamespace}}
        Group: saturation
        CpuRequest: 1m
        MemoryRequest: 10M
- measurements:
  - Identifier: SchedulingThroughput
    Method: SchedulingThroughput
    Params:
      action: start
      labelSelector: group = saturation
- measurements:
  - Identifier: WaitForRunningSaturationRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- measurements:
  - Identifier: SaturationPodStartupLatency
    Method: PodStartupLatency
    Params:
      action: gather
- measurements:
  - Identifier: SchedulingThroughput
    Method: SchedulingThroughput
    Params:
      action: gather
- name: Creating saturation pods
# Create latency pods
- measurements:
  - Identifier: PodStartupLatency
    Method: PodStartupLatency
    Params:
      action: start
      labelSelector: group = latency
- measurements:
  - Identifier: WaitForRunningLatencyRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: start
      apiVersion: v1
      kind: ReplicationController
      labelSelector: group = latency
      operationTimeout: 15m
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: {{$latencyReplicas}}
    tuningSet: Uniform5qps
    objectBundle:
    - basename: latency-pod-rc
      objectTemplatePath: rc.yaml
      templateFillMap:
        Replicas: 1
        Group: latency
        CpuRequest: {{$LATENCY_POD_CPU}}m
        MemoryRequest: {{$LATENCY_POD_MEMORY}}M
- measurements:
  - Identifier: WaitForRunningLatencyRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- name: Creating latency pods
# Remove latency pods
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: 0
    tuningSet: Uniform5qps
    objectBundle:
    - basename: latency-pod-rc
      objectTemplatePath: rc.yaml
- measurements:
  - Identifier: WaitForRunningLatencyRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- measurements:
  - Identifier: PodStartupLatency
    Method: PodStartupLatency
    Params:
      action: gather
- name: Deleting latancy pods

# Delete pods
- phases:
  - namespaceRange:
      min: 1
      max: {{$namespaces}}
    replicasPerNamespace: 0
    tuningSet: Uniform5qps
    objectBundle:
    - basename: saturation-rc
      objectTemplatePath: rc.yaml
- measurements:
  - Identifier: WaitForRunningSaturationRCs
    Method: WaitForControlledPodsRunning
    Params:
      action: gather
- name: Deleting saturation pods
# Collect measurements
- measurements:
  - Identifier: APIResponsiveness
    Method: APIResponsiveness
    Params:
      action: gather
  - Identifier: TestMetrics
    Method: TestMetrics
    Params:
      action: gather
      systemPodMetricsEnabled: {{$ENABLE_SYSTEM_POD_METRICS}}
      restartCountThresholdOverrides: {{YamlQuote $RESTART_COUNT_THRESHOLD_OVERRIDES 4}}
      enableRestartCountCheck: {{$ENABLE_RESTART_COUNT_CHECK}}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37

apiVersion: v1
kind: ReplicationController
metadata:
  name: {{.Name}}
  labels:
    group: {{.Group}}
spec:
  replicas: {{.Replicas}}
  selector:
    name: {{.Name}}
  template:
    metadata:
      labels:
        name: {{.Name}}
        group: {{.Group}}
    spec:
      containers:
      - image: 192.168.182.101:5000/com.inspur/pause-amd64:3.1
        imagePullPolicy: IfNotPresent
        name: {{.Name}}
        ports:
        resources:
          requests:
            cpu: {{.CpuRequest}}
            memory: {{.MemoryRequest}}
      # Add not-ready/unreachable tolerations for 15 minutes so that node
      # failure doesn't trigger pod deletion.
      tolerations:
      - key: "node.kubernetes.io/not-ready"
        operator: "Exists"
        effect: "NoExecute"
        tolerationSeconds: 900
      - key: "node.kubernetes.io/unreachable"
        operator: "Exists"
        effect: "NoExecute"
        tolerationSeconds: 900

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

[root@node1 clusterloader2]# ls
clusterloader  reports  testing  test.log
[root@node1 clusterloader2]# cd reports/
[root@node1 reports]# ll
total 44
-rw-r--r-- 1 root root 10093 Dec 11 15:38 APIResponsiveness_density_2020-12-11T15:38:47+08:00.json
-rw-r--r-- 1 root root  9792 Dec 11 16:29 APIResponsiveness_density_2020-12-11T16:29:41+08:00.json
-rw-r--r-- 1 root root   287 Dec 11 16:29 junit.xml
-rw-r--r-- 1 root root  1054 Dec 11 15:38 PodStartupLatency_SaturationPodStartupLatency_density_2020-12-11T15:37:54+08:00.json
-rw-r--r-- 1 root root  1048 Dec 11 16:29 PodStartupLatency_SaturationPodStartupLatency_density_2020-12-11T16:28:49+08:00.json
-rw-r--r-- 1 root root    64 Dec 11 15:38 SchedulingThroughput_density_2020-12-11T15:37:54+08:00.json
-rw-r--r-- 1 root root    64 Dec 11 16:29 SchedulingThroughput_density_2020-12-11T16:28:49+08:00.json

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151

I1214 15:48:46.685903  129068 clusterloader.go:105] ClusterConfig.Nodes set to 2
E1214 15:48:46.690191  129068 clusterloader.go:122] Getting master external ip error: did not find any ExternalIP master IPs
I1214 15:48:46.690809  129068 clusterloader.go:206] Using config: {ClusterConfig:{KubeConfigPath:/root/.kube/config Nodes:2 Provider: MasterIPs:[] MasterInternalIPs:[TEST_MASTER_INTERNAL_IP] MasterName:192.168.182.101 KubemarkRootKubeConfigPath:} ReportDir:./reports EnablePrometheusServer:false TearDownPrometheusServer:false TestConfigPath: TestOverridesPath:[] PrometheusConfig:{EnableServer:false TearDownServer:true ScrapeEtcd:false ScrapeNodeExporter:false ScrapeKubelets:false ScrapeKubeProxy:true SnapshotProject:}}
I1214 15:48:46.693242  129068 cluster.go:56] Listing cluster nodes:
I1214 15:48:46.693254  129068 cluster.go:68] Name: node1, clusterIP: 192.168.182.101, externalIP: , isSchedulable: true
I1214 15:48:46.693260  129068 cluster.go:68] Name: node2, clusterIP: 192.168.182.102, externalIP: , isSchedulable: true
I1214 15:48:46.696447  129068 clusterloader.go:167] --------------------------------------------------------------------------------
I1214 15:48:46.696469  129068 clusterloader.go:168] Running /home/wangb/perf-test/clusterloader2/testing/density/config2.yaml
I1214 15:48:46.696472  129068 clusterloader.go:169] --------------------------------------------------------------------------------
I1214 15:48:46.697804  129068 simple_test_executor.go:50] AutomanagedNamespacePrefix: test-tteu8b
I1214 15:48:46.729142  129068 etcd_metrics.go:76] EtcdMetrics: starting etcd metrics collecting...
I1214 15:48:46.729168  129068 scheduler_latency.go:77] SchedulingMetrics: resetting latency metrics in scheduler...
I1214 15:48:46.729274  129068 api_responsiveness.go:70] APIResponsiveness: resetting latency metrics in apiserver...
I1214 15:48:46.936885  129068 resource_usage.go:106] ResourceUsageSummary: starting resource usage collecting...
I1214 15:48:46.948058  129068 system_pod_metrics.go:82] skipping collection of system pod metrics
I1214 15:48:46.948107  129068 pod_startup_latency.go:131] PodStartupLatency: labelSelector(group = saturation): starting pod startup latency measurement...
I1214 15:48:47.048405  129068 wait_for_controlled_pods.go:163] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1214 15:48:47.607326  129068 scheduling_throughput.go:107] SchedulingThroughput: starting collecting throughput data
I1214 15:48:47.607393  129068 wait_for_controlled_pods.go:196] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I1214 15:48:52.226268  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=saturation-rc-0): Pods: 2 out of 2 created, 2 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:52.408575  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=saturation-rc-0): Pods: 2 out of 2 created, 2 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:52.607705  129068 scheduling_throughput.go:123] SchedulingThroughput: labelSelector(group = saturation): 4 pods scheduled
I1214 15:48:52.611510  129068 wait_for_controlled_pods.go:235] WaitForControlledPodsRunning: running 2, deleted 0, timeout: 0, unknown: 0
I1214 15:48:52.611535  129068 wait_for_controlled_pods.go:249] WaitForControlledPodsRunning: 2/2 ReplicationControllers are running with all pods
I1214 15:48:52.611582  129068 pod_startup_latency.go:163] PodStartupLatency: labelSelector(group = saturation): gathering pod startup latency measurement...
I1214 15:48:52.630805  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = saturation): 4 worst create-to-schedule latencies: [{test-tteu8b-2/saturation-rc-0-t2t27 node2 0s} {test-tteu8b-1/saturation-rc-0-vxxc6 node2 0s} {test-tteu8b-1/saturation-rc-0-pqmh6 node1 0s} {test-tteu8b-2/saturation-rc-0-phkng node1 0s}]
I1214 15:48:52.630877  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = saturation): perc50: 0s, perc90: 0s, perc99: 0s; threshold: 3m0s
I1214 15:48:52.630887  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = saturation): 4 worst schedule-to-run latencies: [{test-tteu8b-2/saturation-rc-0-t2t27 node2 1s} {test-tteu8b-1/saturation-rc-0-vxxc6 node2 1s} {test-tteu8b-1/saturation-rc-0-pqmh6 node1 1s} {test-tteu8b-2/saturation-rc-0-phkng node1 1s}]
I1214 15:48:52.630894  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = saturation): perc50: 1s, perc90: 1s, perc99: 1s; threshold: 3m0s
I1214 15:48:52.630903  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = saturation): 4 worst run-to-watch latencies: [{test-tteu8b-2/saturation-rc-0-t2t27 node2 1.202667785s} {test-tteu8b-1/saturation-rc-0-vxxc6 node2 1.22260201s} {test-tteu8b-1/saturation-rc-0-pqmh6 node1 1.292204887s} {test-tteu8b-2/saturation-rc-0-phkng node1 1.30166796s}]
I1214 15:48:52.630909  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = saturation): perc50: 1.22260201s, perc90: 1.30166796s, perc99: 1.30166796s; threshold: 3m0s
I1214 15:48:52.630912  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = saturation): 4 worst schedule-to-watch latencies: [{test-tteu8b-2/saturation-rc-0-t2t27 node2 2.202667785s} {test-tteu8b-1/saturation-rc-0-vxxc6 node2 2.22260201s} {test-tteu8b-1/saturation-rc-0-pqmh6 node1 2.292204887s} {test-tteu8b-2/saturation-rc-0-phkng node1 2.30166796s}]
I1214 15:48:52.630920  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = saturation): perc50: 2.22260201s, perc90: 2.30166796s, perc99: 2.30166796s; threshold: 3m0s
I1214 15:48:52.630922  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = saturation): 4 worst e2e latencies: [{test-tteu8b-2/saturation-rc-0-t2t27 node2 2.202667785s} {test-tteu8b-1/saturation-rc-0-vxxc6 node2 2.22260201s} {test-tteu8b-1/saturation-rc-0-pqmh6 node1 2.292204887s} {test-tteu8b-2/saturation-rc-0-phkng node1 2.30166796s}]
I1214 15:48:52.630926  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = saturation): perc50: 2.22260201s, perc90: 2.30166796s, perc99: 2.30166796s; threshold: 3m0s
I1214 15:48:52.631183  129068 scheduling_throughput.go:136] SchedulingThroughput: gathering data
I1214 15:48:52.631231  129068 simple_test_executor.go:128] Step "Creating saturation pods" ended
I1214 15:48:52.631261  129068 pod_startup_latency.go:131] PodStartupLatency: labelSelector(group = latency): starting pod startup latency measurement...
I1214 15:48:52.731639  129068 wait_for_controlled_pods.go:163] WaitForControlledPodsRunning: starting wait for controlled pods measurement...
I1214 15:48:56.854842  129068 wait_for_controlled_pods.go:196] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I1214 15:48:57.893711  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-0): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:58.090743  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-1): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:58.290905  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-2): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:58.489711  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-3): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:58.690296  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-4): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:58.889999  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-5): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:59.089820  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-6): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:59.289666  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-7): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:59.490967  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-8): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:59.690953  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-9): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:48:59.892106  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-0): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:00.093290  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-1): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:00.296933  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-2): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:00.498491  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-3): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:00.700027  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-4): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:00.963786  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-5): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:01.107629  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-6): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:01.311728  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-7): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:01.509745  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-8): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:01.710317  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-9): Pods: 1 out of 1 created, 0 running, 1 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:02.893967  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-0): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:03.090943  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-1): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:03.290972  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-2): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:03.490268  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-3): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:03.690609  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-4): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:03.890985  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-5): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:04.090049  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-6): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:04.290203  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-7): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:04.691160  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-9): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:05.093608  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-1): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:05.499007  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-3): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:05.964020  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-5): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:06.312641  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-7): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:06.710758  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-9): Pods: 1 out of 1 created, 1 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:06.710803  129068 wait_for_controlled_pods.go:235] WaitForControlledPodsRunning: running 20, deleted 0, timeout: 0, unknown: 0
I1214 15:49:06.715769  129068 wait_for_controlled_pods.go:249] WaitForControlledPodsRunning: 20/20 ReplicationControllers are running with all pods
I1214 15:49:06.720533  129068 simple_test_executor.go:128] Step "Creating latency pods" ended
I1214 15:49:10.750656  129068 wait_for_controlled_pods.go:196] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I1214 15:49:11.801519  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-0): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:11.986805  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-1): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:12.184772  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-2): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:12.382919  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-3): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:12.589442  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-4): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:12.785810  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-5): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:12.983926  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-6): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:13.184330  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-7): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:13.384069  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-8): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:13.586112  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-9): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:13.790252  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-0): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:13.987269  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-1): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:14.192313  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-2): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:14.397369  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-3): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:14.605276  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-4): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:14.798794  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-5): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:14.997796  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-6): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:15.209917  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-7): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:15.394405  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-8): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:15.594518  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-9): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:17.184991  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-2): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:17.383303  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-3): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:17.786423  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-5): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:17.984309  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-6): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:18.184626  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-7): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:18.586402  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-9): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:18.987494  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-1): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:19.397720  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-3): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:19.799365  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-5): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:20.210268  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-7): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:20.594992  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=latency-pod-rc-9): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:22.984472  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-6): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:23.587181  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=latency-pod-rc-9): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:23.587247  129068 wait_for_controlled_pods.go:235] WaitForControlledPodsRunning: running 0, deleted 20, timeout: 0, unknown: 0
I1214 15:49:23.587289  129068 wait_for_controlled_pods.go:249] WaitForControlledPodsRunning: 0/0 ReplicationControllers are running with all pods
I1214 15:49:23.612305  129068 pod_startup_latency.go:163] PodStartupLatency: labelSelector(group = latency): gathering pod startup latency measurement...
I1214 15:49:23.650456  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = latency): 20 worst create-to-schedule latencies: [{test-tteu8b-1/latency-pod-rc-0-lnrtg node2 0s} {test-tteu8b-1/latency-pod-rc-7-646cq node2 0s} {test-tteu8b-2/latency-pod-rc-4-tbszn node1 0s} {test-tteu8b-1/latency-pod-rc-5-mjbsr node2 0s} {test-tteu8b-1/latency-pod-rc-3-42gdw node2 0s} {test-tteu8b-2/latency-pod-rc-7-c7rst node2 0s} {test-tteu8b-1/latency-pod-rc-4-ngh2t node2 0s} {test-tteu8b-2/latency-pod-rc-1-4j655 node2 0s} {test-tteu8b-2/latency-pod-rc-9-xmct4 node2 0s} {test-tteu8b-1/latency-pod-rc-1-nk24t node2 0s} {test-tteu8b-1/latency-pod-rc-2-rj7h5 node2 0s} {test-tteu8b-1/latency-pod-rc-9-ww659 node2 0s} {test-tteu8b-2/latency-pod-rc-3-k8g85 node2 0s} {test-tteu8b-2/latency-pod-rc-0-wdhxz node1 0s} {test-tteu8b-2/latency-pod-rc-2-pwgsb node1 0s} {test-tteu8b-2/latency-pod-rc-8-c5m4q node1 0s} {test-tteu8b-2/latency-pod-rc-6-x7d4t node1 0s} {test-tteu8b-1/latency-pod-rc-8-4kx24 node1 0s} {test-tteu8b-1/latency-pod-rc-6-wskwq node2 0s} {test-tteu8b-2/latency-pod-rc-5-xx7qn node2 1s}]
I1214 15:49:23.650562  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = latency): perc50: 0s, perc90: 0s, perc99: 1s; threshold: 5s
I1214 15:49:23.650571  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = latency): 20 worst schedule-to-run latencies: [{test-tteu8b-1/latency-pod-rc-8-4kx24 node1 1s} {test-tteu8b-2/latency-pod-rc-2-pwgsb node1 1s} {test-tteu8b-2/latency-pod-rc-0-wdhxz node1 2s} {test-tteu8b-2/latency-pod-rc-6-x7d4t node1 2s} {test-tteu8b-2/latency-pod-rc-4-tbszn node1 2s} {test-tteu8b-2/latency-pod-rc-8-c5m4q node1 2s} {test-tteu8b-1/latency-pod-rc-0-lnrtg node2 3s} {test-tteu8b-1/latency-pod-rc-1-nk24t node2 3s} {test-tteu8b-2/latency-pod-rc-5-xx7qn node2 4s} {test-tteu8b-2/latency-pod-rc-9-xmct4 node2 4s} {test-tteu8b-1/latency-pod-rc-3-42gdw node2 4s} {test-tteu8b-2/latency-pod-rc-7-c7rst node2 4s} {test-tteu8b-1/latency-pod-rc-2-rj7h5 node2 4s} {test-tteu8b-1/latency-pod-rc-6-wskwq node2 4s} {test-tteu8b-1/latency-pod-rc-9-ww659 node2 5s} {test-tteu8b-2/latency-pod-rc-1-4j655 node2 5s} {test-tteu8b-1/latency-pod-rc-4-ngh2t node2 5s} {test-tteu8b-1/latency-pod-rc-5-mjbsr node2 5s} {test-tteu8b-1/latency-pod-rc-7-646cq node2 5s} {test-tteu8b-2/latency-pod-rc-3-k8g85 node2 5s}]
I1214 15:49:23.650585  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = latency): perc50: 4s, perc90: 5s, perc99: 5s; threshold: 5s
I1214 15:49:23.650588  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = latency): 20 worst run-to-watch latencies: [{test-tteu8b-2/latency-pod-rc-1-4j655 node2 560.606582ms} {test-tteu8b-2/latency-pod-rc-0-wdhxz node1 721.939052ms} {test-tteu8b-2/latency-pod-rc-8-c5m4q node1 833.924156ms} {test-tteu8b-2/latency-pod-rc-6-x7d4t node1 854.39232ms} {test-tteu8b-1/latency-pod-rc-5-mjbsr node2 1.012828114s} {test-tteu8b-2/latency-pod-rc-5-xx7qn node2 1.411960877s} {test-tteu8b-1/latency-pod-rc-7-646cq node2 1.647809261s} {test-tteu8b-2/latency-pod-rc-3-k8g85 node2 1.812513167s} {test-tteu8b-2/latency-pod-rc-2-pwgsb node1 1.832899011s} {test-tteu8b-2/latency-pod-rc-4-tbszn node1 1.865941757s} {test-tteu8b-1/latency-pod-rc-9-ww659 node2 2.009388509s} {test-tteu8b-1/latency-pod-rc-2-rj7h5 node2 2.082626218s} {test-tteu8b-1/latency-pod-rc-4-ngh2t node2 2.140752308s} {test-tteu8b-2/latency-pod-rc-9-xmct4 node2 2.210054751s} {test-tteu8b-1/latency-pod-rc-8-4kx24 node1 2.508582695s} {test-tteu8b-2/latency-pod-rc-7-c7rst node2 2.611408502s} {test-tteu8b-1/latency-pod-rc-6-wskwq node2 2.625719954s} {test-tteu8b-1/latency-pod-rc-1-nk24t node2 3.066876643s} {test-tteu8b-1/latency-pod-rc-3-42gdw node2 3.538575976s} {test-tteu8b-1/latency-pod-rc-0-lnrtg node2 5.586231683s}]
I1214 15:49:23.650601  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = latency): perc50: 1.865941757s, perc90: 3.066876643s, perc99: 5.586231683s; threshold: 5s
I1214 15:49:23.650604  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = latency): 20 worst schedule-to-watch latencies: [{test-tteu8b-2/latency-pod-rc-0-wdhxz node1 2.721939052s} {test-tteu8b-2/latency-pod-rc-2-pwgsb node1 2.832899011s} {test-tteu8b-2/latency-pod-rc-8-c5m4q node1 2.833924156s} {test-tteu8b-2/latency-pod-rc-6-x7d4t node1 2.85439232s} {test-tteu8b-1/latency-pod-rc-8-4kx24 node1 3.508582695s} {test-tteu8b-2/latency-pod-rc-4-tbszn node1 3.865941757s} {test-tteu8b-2/latency-pod-rc-5-xx7qn node2 5.411960877s} {test-tteu8b-2/latency-pod-rc-1-4j655 node2 5.560606582s} {test-tteu8b-1/latency-pod-rc-5-mjbsr node2 6.012828114s} {test-tteu8b-1/latency-pod-rc-1-nk24t node2 6.066876643s} {test-tteu8b-1/latency-pod-rc-2-rj7h5 node2 6.082626218s} {test-tteu8b-2/latency-pod-rc-9-xmct4 node2 6.210054751s} {test-tteu8b-2/latency-pod-rc-7-c7rst node2 6.611408502s} {test-tteu8b-1/latency-pod-rc-6-wskwq node2 6.625719954s} {test-tteu8b-1/latency-pod-rc-7-646cq node2 6.647809261s} {test-tteu8b-2/latency-pod-rc-3-k8g85 node2 6.812513167s} {test-tteu8b-1/latency-pod-rc-9-ww659 node2 7.009388509s} {test-tteu8b-1/latency-pod-rc-4-ngh2t node2 7.140752308s} {test-tteu8b-1/latency-pod-rc-3-42gdw node2 7.538575976s} {test-tteu8b-1/latency-pod-rc-0-lnrtg node2 8.586231683s}]
I1214 15:49:23.650616  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = latency): perc50: 6.066876643s, perc90: 7.140752308s, perc99: 8.586231683s; threshold: 5s
I1214 15:49:23.650620  129068 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = latency): 20 worst e2e latencies: [{test-tteu8b-2/latency-pod-rc-0-wdhxz node1 2.721939052s} {test-tteu8b-2/latency-pod-rc-2-pwgsb node1 2.832899011s} {test-tteu8b-2/latency-pod-rc-8-c5m4q node1 2.833924156s} {test-tteu8b-2/latency-pod-rc-6-x7d4t node1 2.85439232s} {test-tteu8b-1/latency-pod-rc-8-4kx24 node1 3.508582695s} {test-tteu8b-2/latency-pod-rc-4-tbszn node1 3.865941757s} {test-tteu8b-2/latency-pod-rc-1-4j655 node2 5.560606582s} {test-tteu8b-1/latency-pod-rc-5-mjbsr node2 6.012828114s} {test-tteu8b-1/latency-pod-rc-1-nk24t node2 6.066876643s} {test-tteu8b-1/latency-pod-rc-2-rj7h5 node2 6.082626218s} {test-tteu8b-2/latency-pod-rc-9-xmct4 node2 6.210054751s} {test-tteu8b-2/latency-pod-rc-5-xx7qn node2 6.411960877s} {test-tteu8b-2/latency-pod-rc-7-c7rst node2 6.611408502s} {test-tteu8b-1/latency-pod-rc-6-wskwq node2 6.625719954s} {test-tteu8b-1/latency-pod-rc-7-646cq node2 6.647809261s} {test-tteu8b-2/latency-pod-rc-3-k8g85 node2 6.812513167s} {test-tteu8b-1/latency-pod-rc-9-ww659 node2 7.009388509s} {test-tteu8b-1/latency-pod-rc-4-ngh2t node2 7.140752308s} {test-tteu8b-1/latency-pod-rc-3-42gdw node2 7.538575976s} {test-tteu8b-1/latency-pod-rc-0-lnrtg node2 8.586231683s}]
I1214 15:49:23.650631  129068 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = latency): perc50: 6.082626218s, perc90: 7.140752308s, perc99: 8.586231683s; threshold: 5s
E1214 15:49:23.651429  129068 pod_startup_latency.go:243] PodStartupLatency: labelSelector(group = latency): pod startup: too high latency 50th percentile: 6.082626218s
I1214 15:49:23.651671  129068 simple_test_executor.go:128] Step "Deleting latancy pods" ended
I1214 15:49:24.054984  129068 wait_for_controlled_pods.go:196] WaitForControlledPodsRunning: waiting for controlled pods measurement...
I1214 15:49:28.720087  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=saturation-rc-0): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 1 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:28.910121  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-2), labelSelector(name=saturation-rc-0): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:33.720408  129068 wait_for_pods.go:141] WaitForControlledPodsRunning: namespace(test-tteu8b-1), labelSelector(name=saturation-rc-0): Pods: 0 out of 0 created, 0 running, 0 pending scheduled, 0 not scheduled, 0 inactive, 0 terminating, 0 unknown, 0 runningButNotReady
I1214 15:49:33.723457  129068 wait_for_controlled_pods.go:235] WaitForControlledPodsRunning: running 0, deleted 2, timeout: 0, unknown: 0
I1214 15:49:33.723518  129068 wait_for_controlled_pods.go:249] WaitForControlledPodsRunning: 0/0 ReplicationControllers are running with all pods
I1214 15:49:33.723540  129068 simple_test_executor.go:128] Step "Deleting saturation pods" ended
I1214 15:49:33.833335  129068 api_responsiveness.go:119] APIResponsiveness: Top latency metric: {Resource:pods Subresource: Verb:DELETE Scope:namespace Latency:{Perc50:8.831ms Perc90:13.349ms Perc99:36.302ms} Count:48}; threshold: 1s
I1214 15:49:33.833401  129068 api_responsiveness.go:119] APIResponsiveness: Top latency metric: {Resource:pods Subresource: Verb:GET Scope:namespace Latency:{Perc50:1.705ms Perc90:5.171ms Perc99:32.127ms} Count:184}; threshold: 1s
I1214 15:49:33.833407  129068 api_responsiveness.go:119] APIResponsiveness: Top latency metric: {Resource:pods Subresource:status Verb:PATCH Scope:namespace Latency:{Perc50:2.893ms Perc90:8.968ms Perc99:20.499ms} Count:105}; threshold: 1s
I1214 15:49:33.833412  129068 api_responsiveness.go:119] APIResponsiveness: Top latency metric: {Resource:replicationcontrollers Subresource: Verb:DELETE Scope:namespace Latency:{Perc50:4.333ms Perc90:10.995ms Perc99:19.334ms} Count:22}; threshold: 1s
I1214 15:49:33.833421  129068 api_responsiveness.go:119] APIResponsiveness: Top latency metric: {Resource:pods Subresource:binding Verb:POST Scope:namespace Latency:{Perc50:2.979ms Perc90:9.545ms Perc99:18.153ms} Count:24}; threshold: 1s
I1214 15:49:34.572385  129068 resource_usage.go:124] ResourceUsageSummary: gathering resource usage...
I1214 15:49:34.574852  129068 container_resource_gatherer.go:172] Closed stop channel. Waiting for 1 workers
I1214 15:49:34.574936  129068 resource_gather_worker.go:90] Closing worker for node1
I1214 15:49:34.574949  129068 container_resource_gatherer.go:180] Waitgroup finished.
I1214 15:49:34.576009  129068 system_pod_metrics.go:82] skipping collection of system pod metrics
I1214 15:49:44.638344  129068 simple_test_executor.go:345] Resources cleanup time: 10.059218091s
I1214 15:49:44.641394  129068 clusterloader.go:177] --------------------------------------------------------------------------------
I1214 15:49:44.641440  129068 clusterloader.go:178] Test Finished
I1214 15:49:44.641461  129068 clusterloader.go:179]   Test: /home/wangb/perf-test/clusterloader2/testing/density/config2.yaml
I1214 15:49:44.641465  129068 clusterloader.go:180]   Status: Success
I1214 15:49:44.641467  129068 clusterloader.go:184] --------------------------------------------------------------------------------

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

[root@node1 clusterloader2]# ll reports/ -h
total 260K
-rw-r--r-- 1 root root 9.9K Dec 14 16:26 APIResponsiveness_density_2020-12-14T16:26:20+08:00.json
-rw-r--r-- 1 root root 1.6K Dec 14 16:26 EtcdMetrics_density_2020-12-14T16:26:21+08:00.json
-rw-r--r-- 1 root root  287 Dec 14 16:26 junit.xml
-rw-r--r-- 1 root root 224K Dec 14 16:26 MetricsForE2E_density_2020-12-14T16:26:21+08:00.json
-rw-r--r-- 1 root root 1.1K Dec 14 16:26 PodStartupLatency_SaturationPodStartupLatency_density_2020-12-14T16:25:43+08:00.json
-rw-r--r-- 1 root root    3 Dec 14 16:26 ResourceUsageSummary_density_2020-12-14T16:26:21+08:00.json
-rw-r--r-- 1 root root  400 Dec 14 16:26 SchedulingMetrics_density_2020-12-14T16:26:21+08:00.json
-rw-r--r-- 1 root root   72 Dec 14 16:26 SchedulingThroughput_density_2020-12-14T16:25:43+08:00.json

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

[root@node1 wangb]# kubectl get no
NAME            STATUS   ROLES         AGE     VERSION
hollow-node-0   Ready    <none>        9s      v0.0.0-master+4d3c9e0c
hollow-node-1   Ready    <none>        9s      v0.0.0-master+4d3c9e0c
hollow-node-2   Ready    <none>        9s      v0.0.0-master+4d3c9e0c
hollow-node-3   Ready    <none>        9s      v0.0.0-master+4d3c9e0c
hollow-node-4   Ready    <none>        9s      v0.0.0-master+4d3c9e0c
hollow-node-5   Ready    <none>        9s      v0.0.0-master+4d3c9e0c
node1           Ready    master,node   7d22h   v1.14.8
node2           Ready    node          7d22h   v1.14.8

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22

test-l3zhzg-2   saturation-rc-0-gmx45             1/1     Running             0          2m19s   10.152.121.76     hollow-node-1   <none>           <none>
test-l3zhzg-2   saturation-rc-0-grbkl             1/1     Running             0          2m19s   10.233.90.157     node1           <none>           <none>
test-l3zhzg-2   saturation-rc-0-jtw77             1/1     Running             0          2m17s   10.233.96.78      node2           <none>           <none>
test-l3zhzg-2   saturation-rc-0-krzkt             1/1     Running             0          2m19s   10.88.194.43      hollow-node-0   <none>           <none>
test-l3zhzg-2   saturation-rc-0-kskvv             1/1     Running             0          2m16s   10.177.65.132     hollow-node-4   <none>           <none>
test-l3zhzg-2   saturation-rc-0-l4zbp             1/1     Running             0          2m19s   10.16.150.60      hollow-node-0   <none>           <none>
test-l3zhzg-2   saturation-rc-0-l89cz             1/1     Running             0          2m13s   10.118.8.133      hollow-node-1   <none>           <none>
test-l3zhzg-2   saturation-rc-0-lp8tp             1/1     Running             0          2m19s   10.220.39.235     hollow-node-3   <none>           <none>
test-l3zhzg-2   saturation-rc-0-ls9zw             1/1     Running             0          2m19s   10.15.197.103     hollow-node-2   <none>           <none>
test-l3zhzg-2   saturation-rc-0-m64hg             1/1     Running             0          2m14s   10.172.167.195    hollow-node-2   <none>           <none>
test-l3zhzg-2   saturation-rc-0-m7qct             1/1     Running             0          2m17s   10.41.26.226      hollow-node-4   <none>           <none>
test-l3zhzg-2   saturation-rc-0-mct9d             1/1     Running             0          2m18s   10.126.207.219    hollow-node-4   <none>           <none>
test-l3zhzg-2   saturation-rc-0-ml2fw             1/1     Running             0          2m13s   10.245.91.90      hollow-node-2   <none>           <none>
test-l3zhzg-2   saturation-rc-0-mndt2             1/1     Running             0          2m19s   10.177.227.228    hollow-node-3   <none>           <none>
test-l3zhzg-2   saturation-rc-0-n6tzb             1/1     Running             0          2m13s   10.76.229.141     hollow-node-3   <none>           <none>
test-l3zhzg-2   saturation-rc-0-nfq2d             1/1     Running             0          2m19s   10.172.121.37     hollow-node-4   <none>           <none>
test-l3zhzg-2   saturation-rc-0-nn4wn             1/1     Running             0          2m18s   10.22.201.220     hollow-node-0   <none>           <none>
test-l3zhzg-2   saturation-rc-0-nvpz7             1/1     Running             0          2m16s   10.3.93.180       hollow-node-5   <none>           <none>
test-l3zhzg-2   saturation-rc-0-pfw58             1/1     Running             0          2m16s   10.144.139.248    hollow-node-1   <none>           <none>
test-l3zhzg-2   saturation-rc-0-pqbd6             1/1     Running             0          2m17s   10.207.147.215    hollow-node-0   <none>           <none>
test-l3zhzg-2   saturation-rc-0-q9x97             1/1     Running             0          2m14s   10.233.90.149     node1           <none>           <none>
test-l3zhzg-2   saturation-rc-0-qslqs             1/1     Running             0

1
2
3
4
5

I1215 13:59:14.776944   27607 wait_for_controlled_pods.go:249] WaitForControlledPodsRunning: 2/2 ReplicationControllers are running with all pods
I1215 13:59:14.777038   27607 pod_startup_latency.go:163] PodStartupLatency: labelSelector(group = saturation): gathering pod startup latency measurement...
I1215 13:59:14.795377   27607 pod_startup_latency.go:312] PodStartupLatency: labelSelector(group = saturation): 40 worst create-to-schedule latencies: [{test-bijvxv-1/saturation-rc-0-gktmn hollow-node-1 0s} {test-bijvxv-1/saturation-rc-0-gv9qb hollow-node-2 0s} {test-bijvxv-1/saturation-rc-0-n4cm5 hollow-node-4 0s} {test-bijvxv-2/saturation-rc-0-bn9z4 hollow-node-4 0s} {test-bijvxv-2/saturation-rc-0-srlf6 hollow-node-0 0s} {test-bijvxv-2/saturation-rc-0-btbng hollow-node-1 0s} {test-bijvxv-1/saturation-rc-0-kkcr7 hollow-node-5 0s} {test-bijvxv-2/saturation-rc-0-dctpp hollow-node-0 0s} {test-bijvxv-1/saturation-rc-0-5m8b2 hollow-node-1 0s} {test-bijvxv-1/saturation-rc-0-fpg6d hollow-node-2 0s} {test-bijvxv-1/saturation-rc-0-tjkvs hollow-node-4 0s} {test-bijvxv-2/saturation-rc-0-z6vtd hollow-node-2 0s} {test-bijvxv-2/saturation-rc-0-hrpwd hollow-node-3 0s} {test-bijvxv-2/saturation-rc-0-hzvk9 hollow-node-1 0s} {test-bijvxv-1/saturation-rc-0-x9b4c hollow-node-0 0s} {test-bijvxv-2/saturation-rc-0-4cqkz hollow-node-0 0s} {test-bijvxv-2/saturation-rc-0-4nppr node2 0s} {test-bijvxv-1/saturation-rc-0-rz69k hollow-node-2 0s} {test-bijvxv-2/saturation-rc-0-btsq4 hollow-node-3 0s} {test-bijvxv-1/saturation-rc-0-ll8sk hollow-node-3 0s} {test-bijvxv-1/saturation-rc-0-zjs57 hollow-node-1 0s} {test-bijvxv-1/saturation-rc-0-dq7x4 hollow-node-5 0s} {test-bijvxv-2/saturation-rc-0-fgxjz hollow-node-4 0s} {test-bijvxv-1/saturation-rc-0-g2bcp node1 0s} {test-bijvxv-2/saturation-rc-0-qp9pg hollow-node-3 0s} {test-bijvxv-1/saturation-rc-0-bdqzd hollow-node-5 0s} {test-bijvxv-1/saturation-rc-0-j5s2q hollow-node-4 0s} {test-bijvxv-2/saturation-rc-0-cp2wn node1 0s} {test-bijvxv-2/saturation-rc-0-2z8ct node1 0s} {test-bijvxv-2/saturation-rc-0-q6hd5 hollow-node-1 0s} {test-bijvxv-2/saturation-rc-0-68wwc hollow-node-5 0s} {test-bijvxv-2/saturation-rc-0-5t2wb hollow-node-4 0s} {test-bijvxv-1/saturation-rc-0-lt8ws hollow-node-0 0s} {test-bijvxv-1/saturation-rc-0-dwqz4 hollow-node-3 0s} {test-bijvxv-1/saturation-rc-0-vj68z node2 0s} {test-bijvxv-2/saturation-rc-0-96l5s hollow-node-5 0s} {test-bijvxv-1/saturation-rc-0-v7jq6 hollow-node-3 0s} {test-bijvxv-2/saturation-rc-0-8g4hx hollow-node-5 0s} {test-bijvxv-2/saturation-rc-0-hj7c7 hollow-node-2 0s} {test-bijvxv-1/saturation-rc-0-gx72w hollow-node-0 0s}]
I1215 13:59:14.795463   27607 pod_startup_latency.go:313] PodStartupLatency: labelSelector(group = saturation): perc50: 0s, perc90: 0s, perc99: 0s; threshold: 3m2s