go.ligato.io/vpp-agent/v3@v3.5.0/k8s/tests/timemeasure.sh (about) 1 #!/bin/bash 2 3 export LC_NUMERIC="en_US.UTF-8" 4 5 # takes two time values in ns and returns their subtraction in HH:MM:SS:ms format 6 calcTimeFormat(){ 7 dt=$(echo "$1 - $2" | bc) 8 dd=$(echo "$dt/86400" | bc) 9 dt2=$(echo "$dt-86400*$dd" | bc) 10 dh=$(echo "$dt2/3600" | bc) 11 dt3=$(echo "$dt2-3600*$dh" | bc) 12 dm=$(echo "$dt3/60" | bc) 13 ds=$(echo "$dt3-60*$dm" | bc) 14 retstr=LC_NUMERIC="en_US.UTF-8" printf "%02d:%02d:%02.5f\n" $dh $dm $ds 15 echo $retstr 16 } 17 18 # takes timemstamp format value and calculates nanoseconds 19 calcNanoTime(){ 20 a=(`echo $1 | sed -e 's/[:]/ /g'`) 21 seconds= echo "${a[2]}+60*${a[1]}+3600*${a[0]}" | bc 22 echo $seconds 23 } 24 25 # takes ns time value and returns HH:MM:SS:ms time format 26 showTime(){ 27 dd=$(echo "$1/86400" | bc) 28 dt2=$(echo "$1-86400*$dd" | bc) 29 dh=$(echo "$dt2/3600" | bc) 30 dt3=$(echo "$dt2-3600*$dh" | bc) 31 dm=$(echo "$dt3/60" | bc) 32 ds=$(echo "$dt3-60*$dm" | bc) 33 retstr=LC_NUMERIC="en_US.UTF-8" printf "%02d:%02d:%02.5f\n" $dh $dm $ds 34 echo $retstr 35 } 36 37 # proccess intermediate file log/out.csv 38 # line iteration and calculation of time duration 39 # results are stored in log/measuring_exp.csv 40 processResult(){ 41 start=0 42 startAgent=0 43 resynctime=0 44 etcdTime=0 45 resyncTookTime=0 46 etcdTookTime=0 47 resyncStamp=0 48 etcdStamp=0 49 run=1 50 line_id=1 51 rel_item=0 52 vppTookTime=0 53 resyncBeginTime=0 54 echo "#record,#run,step,timeline,relative time,relative to #record,duration(ms)" > log/measuring_exp.csv 55 while IFS="," read -r val1 val2 val3;do 56 #echo "Processed line $val1, $val2, $val3" 57 if [[ "$val2" =~ ' stopwatch enabled:' ]] 58 then 59 echo "$line_id,$run,$val2,$val1,00:00:00.0,0" >> log/measuring_exp.csv 60 echo "$line_id,$run,$val2,$val1,00:00:00.0,0" 61 line_id=$((line_id+1)) 62 elif [[ "$val2" =~ ' stopwatch disabled:' ]] 63 then 64 echo "$line_id,$run,$val2,$val1,00:00:00.0,0" >> log/measuring_exp.csv 65 echo "$line_id,$run,$val2,$val1,00:00:00.0,0" 66 line_id=$((line_id+1)) 67 elif [[ "$val2" == ' Started measuring' ]] 68 then 69 start=$(calcNanoTime $val1) 70 echo "$line_id,$run,Measuring started,$val1,00:00:00.0,0" >> log/measuring_exp.csv 71 echo "$line_id,$run,Measuring started,$val1,00:00:00.0,0" 72 rel_item=$line_id 73 line_id=$((line_id+1)) 74 75 elif [[ "$val2" == ' Starting the agent...' ]] 76 then 77 vppKilled=0 78 startAgent=$(calcNanoTime $val1) 79 diff=$(echo "$startAgent-$start" | bc) 80 if [ $(bc <<< "$diff > 0") -eq 1 ] 81 then 82 time=$(showTime $diff) 83 echo "$line_id,$run,Starting Agent,$val1,$time,$rel_item" >> log/measuring_exp.csv 84 echo "$line_id,$run,Starting Agent,$val1,$time,$rel_item" 85 rel_item=$line_id 86 line_id=$((line_id+1)) 87 else 88 time=$(showTime $start) 89 echo "$line_id,$run,Kill failed,$time,00:00:00.0,0" >> log/measuring_exp.csv 90 echo "$line_id,$run,Kill failed,$time,00:00:00.0,0" 91 line_id=$((line_id+1)) 92 fi 93 elif [[ "$val2" =~ ' Connecting to etcd took' ]] 94 then 95 etcdTime=$(calcNanoTime $val1) 96 etcdStamp=$val1 97 #etcdTookTime=$(bc <<< "scale = 10; $val3 / 1000000 ") 98 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 99 etcdTookTimge=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 100 101 elif [[ "$val2" =~ ' Resync took' ]] 102 then 103 resyncTime=$(calcNanoTime $val1) 104 resyncStamp=$val1 105 #resyncTookTime=$(bc <<< "scale = 10; $val3 / 1000000 ") 106 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 107 resyncTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 108 109 elif [[ "$val2" == ' VPP Killed' ]] 110 then 111 vppKilled=$(calcNanoTime $val1) 112 vppItem=$line_id 113 diff=$(echo "$vppKilled-$start" | bc) 114 time=$(showTime $diff) 115 echo "$line_id,$run,VPP Killed,$val1,$time,$rel_item" >> log/measuring_exp.csv 116 echo "$line_id,$run,VPP Killed,$val1,$time,$rel_item" 117 line_id=$((line_id+1)) 118 119 elif [[ "$val2" == ' VPP-Agent Killed' ]] 120 then 121 vppKilled=$(calcNanoTime $val1) 122 vppItem=$line_id 123 diff=$(echo "$vppKilled-$start" | bc) 124 time=$(showTime $diff) 125 echo "$line_id,$run,VPP Agent Killed,$val1,$time,$rel_item" >> log/measuring_exp.csv 126 echo "$line_id,$run,VPP Agent Killed,$val1,$time,$rel_item" 127 line_id=$((line_id+1)) 128 elif [[ "$val2" =~ ' Loading topology' ]] 129 then 130 diff=$(echo "$vppKilled-0" | bc) 131 time=$(showTime $diff) 132 echo "$line_id,$run,$val2,$val1,$time,0" >> log/measuring_exp.csv 133 echo "$line_id,$run,$val2,$val1,$time,0" 134 line_id=$((line_id+1)) 135 elif [[ "$val2" =~ ' Container cooled down for' ]] 136 then 137 coreDone=$(calcNanoTime $val1) 138 diff=$(echo "$coreDone - $startAgent" | bc) 139 time=$(showTime $diff) 140 echo "$line_id,$run,$val2,$val1,$time,$rel_item" >> log/measuring_exp.csv 141 echo "$line_id,$run,$val2,$val1,$time,$vppItem" 142 line_id=$((line_id+1)) 143 elif [[ "$val2" =~ ' Core dump of size' ]] 144 then 145 coreDone=$(calcNanoTime $val1) 146 diff=$(echo "$coreDone - $vppKilled" | bc) 147 time=$(showTime $diff) 148 echo "$line_id,$run,$val2,$val1,$time,$vppItem" >> log/measuring_exp.csv 149 echo "$line_id,$run,$val2,$val1,$time,$vppItem" 150 line_id=$((line_id+1)) 151 elif [[ "$val2" = ' Core dump not created' ]] 152 then 153 coreDone=$(calcNanoTime $val1) 154 diff=$(echo "$coreDone - $vppKilled" | bc) 155 time=$(showTime $diff) 156 echo "$line_id,$run,$val2,$val1,$time,$vppItem" >> log/measuring_exp.csv 157 echo "$line_id,$run,$val2,$val1,$time,$vppItem" 158 line_id=$((line_id+1)) 159 elif [[ "$val2" =~ ' call took' ]] 160 then 161 coreDone=$(calcNanoTime $val1) 162 diff=$(echo "$coreDone - $resyncBeginTime" | bc) 163 time=$(showTime $diff) 164 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 165 vppTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 166 echo "$line_id,$run,$val2,$val1,$time,$resyncBeginItem,$vppTookTime" >> log/measuring_exp.csv 167 echo "$line_id,$run,$val2,$val1,$time,$resyncBeginItem,$vppTookTime" 168 line_id=$((line_id+1)) 169 elif [[ "$val2" =~ ' stopwatch has no entries' ]] 170 then 171 coreDone=$(calcNanoTime $val1) 172 diff=$(echo "$coreDone - $resyncBeginTime" | bc) 173 time=$(showTime $diff) 174 echo "$line_id,$run,$val2,$val1,$time,$resyncBeginItem" >> log/measuring_exp.csv 175 echo "$line_id,$run,$val2,$val1,$time,$resyncBeginItem" 176 line_id=$((line_id+1)) 177 elif [[ "$val2" =~ ' partial resync time is' ]] 178 then 179 coreDone=$(calcNanoTime $val1) 180 diff=$(echo "$coreDone - $resyncBeginTime" | bc) 181 time=$(showTime $diff) 182 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 183 vppTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 184 echo "$line_id,$run,$val2,$val1,$time,$resyncBeginItem,$vppTookTime" >> log/measuring_exp.csv 185 echo "$line_id,$run,$val2,$val1,$time,$resyncBeginItem,$vppTookTime" 186 line_id=$((line_id+1)) 187 elif [[ "$val2" = ' Sleeping while VPP will be ready' ]] 188 then 189 coreDone=$(calcNanoTime $val1) 190 diff=$(echo "$coreDone - $startAgent" | bc) 191 time=$(showTime $diff) 192 echo "$line_id,$run,$val2,$val1,$time,$rel_item" >> log/measuring_exp.csv 193 echo "$line_id,$run,$val2,$val1,$time,$rel_item" 194 line_id=$((line_id+1)) 195 elif [[ "$val2" = ' VPP is ready to connect' ]] 196 then 197 coreDone=$(calcNanoTime $val1) 198 diff=$(echo "$coreDone - $startAgent" | bc) 199 time=$(showTime $diff) 200 echo "$line_id,$run,$val2,$val1,$time,$rel_item" >> log/measuring_exp.csv 201 echo "$line_id,$run,$val2,$val1,$time,$rel_item" 202 line_id=$((line_id+1)) 203 elif [[ "$val2" =~ ' Connecting to VPP took' ]] 204 then 205 vppTime=$(calcNanoTime $val1) 206 vppStamp=$val1 207 #vppTookTime=$(bc <<< "scale = 10; $val3 / 1000000 ") 208 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 209 vppTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 210 elif [[ "$val2" =~ ' resync the VPP Configuration begin' ]] 211 then 212 resyncBeginTime=$(calcNanoTime $val1) 213 resyncBeginTimeStamp=$val1 214 resyncBeginItem=$line_id 215 diff=$(echo "$resyncBeginTime - $startAgent" | bc) 216 time=$(showTime $diff) 217 echo "$line_id,$run,$val2,$val1,$time,$rel_item" >> log/measuring_exp.csv 218 echo "$line_id,$run,$val2,$val1,$time,$rel_item" 219 line_id=$((line_id+1)) 220 elif [[ "$val2" =~ ' resync the Linux Configuration' ]] 221 then 222 resyncBeginTime=$(calcNanoTime $val1) 223 resyncBeginTimeStamp=$val1 224 resyncBeginItem=$line_id 225 diff=$(echo "$resyncBeginTime - $startAgent" | bc) 226 time=$(showTime $diff) 227 echo "$line_id,$run,$val2,$val1,$time,$rel_item" >> log/measuring_exp.csv 228 echo "$line_id,$run,$val2,$val1,$time,$rel_item" 229 line_id=$((line_id+1)) 230 231 elif [[ "$val2" =~ ' Connecting to kafka took' ]] 232 then 233 kafkaTime=$(calcNanoTime $val1) 234 kafkaStamp=$val1 235 #kafkaTookTime=$(bc <<< "scale = 10; $val3 / 1000000 ") 236 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 237 kafkaTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 238 elif [[ "$val2" =~ ' plugin GoVPP: Init' ]] 239 then 240 GoVPPInitTime=$(calcNanoTime $val1) 241 GoVPPInitStamp=$val1 242 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 243 GoVPPInitTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 244 elif [[ "$val2" =~ ' plugin Linux: Init' ]] 245 then 246 LinuxInitTime=$(calcNanoTime $val1) 247 LinuxInitStamp=$val1 248 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 249 LinuxInitTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 250 elif [[ "$val2" =~ ' plugin VPP: Init' ]] 251 then 252 PluginVPPInitTime=$(calcNanoTime $val1) 253 PluginVPPInitStamp=$val1 254 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 255 PluginVPPInitTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 256 elif [[ "$val2" =~ ' resync the VPP Configuration end' ]] 257 then 258 PluginVPPResyncTime=$(calcNanoTime $val1) 259 PluginVPPResyncStamp=$val1 260 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 261 PluginVPPResyncTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 262 elif [[ "$val2" =~ ' Agent Init' ]] 263 then 264 AgentInitTime=$(calcNanoTime $val1) 265 AgentInitStamp=$val1 266 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 267 AgentInitTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 268 elif [[ "$val2" =~ ' Agent AfterInit' ]] 269 then 270 AgentAfterInitTime=$(calcNanoTime $val1) 271 AgentAfterInitStamp=$val1 272 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 273 AgentAfterInitTookTime=$(bc <<< "scale = 10; ${a[0]} / 1000000 ") 274 elif [ "$val2" == ' Killed' ] 275 then 276 start1=$(calcNanoTime $val1) 277 diff=$(echo "$start1-$start" | bc) 278 time=$(showTime $diff) 279 if [ $(bc <<< "$diff < 0") -eq 1 ] 280 then 281 echo "$line_id,$run,Kill failed,$val1,$time,$rel_item" >> log/measuring_exp.csv 282 echo "$line_id,$run,Kill failed,$val1,$time,$rel_item" 283 line_id=$((line_id+1)) 284 fi 285 run=$((run + 1)) 286 start=$start1 287 echo "$line_id,$run,Container Killed,$val1,$time,$rel_item" >> log/measuring_exp.csv 288 echo "$line_id,$run,Container Killed,$val1,$time,$rel_item" 289 rel_item=$line_id 290 line_id=$((line_id+1)) 291 startAgent=0 292 resynctime=0 293 etcdTime=0 294 vppTime=0 295 kafkaTime=0 296 #vppKilled=0 297 GoVPPInitTime=0 298 LinuxInitTime=0 299 PluginVPPInitTime=0 300 PluginVPPResyncTime=0 301 AgentInitTime=0 302 AgentAfterInitTime=0 303 resyncTookTime=0 304 etcdTookTime=0 305 vppTookTime=0 306 kafkaTookTime=0 307 AllInitTime=0 308 GoVPPInitTookTime=0 309 LinuxInitTookTime=0 310 PluginVPPInitTookTime=0 311 PluginVPPResyncTookTime=0 312 AgentInitTookTime=0 313 AgentAfterInitTookTime=0 314 resyncStamp=0 315 etcdStamp=0 316 vppStamp=0 317 kafkaStamp=0 318 GoVPPInitStamp=0 319 LinuxInitStamp=0 320 PluginVPPInitStamp=0 321 PluginVPPResyncStamp=0 322 AgentInitStamp=0 323 AgentAfterInitStamp=0 324 AllInitStamp=0 325 resyncBeginTimeStamp=0 326 resyncBeginTime=0 327 elif [ "$val2" == '--' ] 328 then 329 diff=$(echo "$startAgent-$start" | bc) 330 if [ $(bc <<< "$diff > 0") -eq 1 ] 331 then 332 diff=$(echo "$etcdTime-$startAgent" | bc) 333 time=$(showTime $diff) 334 echo "$line_id,$run,ETCD connected,$etcdStamp,$time,$rel_item,$etcdTookTime" >> log/measuring_exp.csv 335 echo "$line_id,$run,ETCD connected,$etcdStamp,$time,$rel_item,$etcdTookTime" 336 line_id=$((line_id+1)) 337 diff=$(echo "$kafkaTime-$startAgent" | bc) 338 time=$(showTime $diff) 339 echo "$line_id,$run,Kafka connected,$kafkaStamp,$time,$rel_item,$kafkaTookTime" >> log/measuring_exp.csv 340 echo "$line_id,$run,Kafka connected,$kafkaStamp,$time,$rel_item,$kafkaTookTime" 341 line_id=$((line_id+1)) 342 diff=$(echo "$vppTime-$startAgent" | bc) 343 time=$(showTime $diff) 344 echo "$line_id,$run,VPP connected,$vppStamp,$time,$rel_item,$vppTookTime" >> log/measuring_exp.csv 345 echo "$line_id,$run,VPP connected,$vppStamp,$time,$rel_item,$vppTookTime" 346 line_id=$((line_id+1)) 347 diff=$(echo "$GoVPPInitTime-$startAgent" | bc) 348 time=$(showTime $diff) 349 echo "$line_id,$run,GoVPP Init,$GoVPPInitStamp,$time,$rel_item,$GoVPPInitTookTime" >> log/measuring_exp.csv 350 echo "$line_id,$run,GoVPP Init,$GoVPPInitStamp,$time,$rel_item,$GoVPPInitTookTime" 351 352 line_id=$((line_id+1)) 353 diff=$(echo "$LinuxInitTime-$startAgent" | bc) 354 time=$(showTime $diff) 355 echo "$line_id,$run,Linux plugin Init,$LinuxInitStamp,$time,$rel_item,$LinuxInitTookTime" >> log/measuring_exp.csv 356 echo "$line_id,$run,Linux plugin Init,$LinuxInitStamp,$time,$rel_item,$LinuxInitTookTime" 357 358 line_id=$((line_id+1)) 359 diff=$(echo "$PluginVPPInitTime-$startAgent" | bc) 360 time=$(showTime $diff) 361 echo "$line_id,$run,VPP plugin Init,$PluginVPPInitStamp,$time,$rel_item,$PluginVPPInitTookTime" >> log/measuring_exp.csv 362 echo "$line_id,$run,VPP plugin Init,$PluginVPPInitStamp,$time,$rel_item,$PluginVPPInitTookTime" 363 364 line_id=$((line_id+1)) 365 diff=$(echo "$PluginVPPResyncTime-$startAgent" | bc) 366 time=$(showTime $diff) 367 echo "$line_id,$run,Resync of VPP config,$PluginVPPResyncStamp,$time,$rel_item,$PluginVPPResyncTookTime" >> log/measuring_exp.csv 368 echo "$line_id,$run,Resync of VPP config,$PluginVPPResyncStamp,$time,$rel_item,$PluginVPPResyncTookTime" 369 370 line_id=$((line_id+1)) 371 diff=$(echo "$resyncTime-$startAgent" | bc) 372 time=$(showTime $diff) 373 echo "$line_id,$run,Resync done,$resyncStamp,$time,$rel_item,$resyncTookTime" >> log/measuring_exp.csv 374 echo "$line_id,$run,Resync done,$resyncStamp,$time,$rel_item,$resyncTookTime" 375 376 line_id=$((line_id+1)) 377 diff=$(echo "$AgentInitTime-$startAgent" | bc) 378 time=$(showTime $diff) 379 echo "$line_id,$run,Agent Init,$AgentInitStamp,$time,$rel_item,$AgentInitTookTime" >> log/measuring_exp.csv 380 echo "$line_id,$run,Agent Init,$AgentInitStamp,$time,$rel_item,$AgentInitTookTime" 381 382 line_id=$((line_id+1)) 383 diff=$(echo "$AgentAfterInitTime-$startAgent" | bc) 384 time=$(showTime $diff) 385 echo "$line_id,$run,Agent AfterInit,$AgentAfterInitStamp,$time,$rel_item,$AgentAfterInitTookTime" >> log/measuring_exp.csv 386 echo "$line_id,$run,Agent AfterInit,$AgentAfterInitStamp,$time,$rel_item,$AgentAfterInitTookTime" 387 388 389 line_id=$((line_id+1)) 390 diff=$(echo "$AllInitTime-$startAgent" | bc) 391 time=$(showTime $diff) 392 echo "$line_id,$run,Agent ready,$AllInitStamp,$time,$rel_item" >> log/measuring_exp.csv 393 echo "$line_id,$run,Agent ready,$AllInitStamp,$time,$rel_item" 394 line_id=$((line_id+1)) 395 fi 396 elif [ "$val2" == ' All plugins initialized successfully' ] 397 then 398 AllInitTime=$(calcNanoTime $val1) 399 AllInitStamp=$val1 400 a=(`echo $val3 | sed -e 's/[:]/ /g'`) 401 fi 402 done <$1 403 } 404 405 # starting etcd and kafka containers 406 # loading topology into etcd (if any ) 407 # topology can be SET BY topo variable, 408 # eventually other preprared topology can be 409 # loaded here by modifying the function 410 setup() { 411 #cleanup prev results 412 rm -f logresult.zip 413 rm -rf log 2>&1 414 mkdir log 415 416 #start kafka + etcd and wait until they are ready 417 sudo docker run -p 22379:2379 --name etcd -e ETCDCTL_API=3 -d \ 418 quay.io/coreos/etcd:v3.1.0 /usr/local/bin/etcd \ 419 -advertise-client-urls http://0.0.0.0:2379 \ 420 -listen-client-urls http://0.0.0.0:2379 > log/etcd.log 2>&1 421 422 sudo docker exec -it etcd etcdctl get --prefix "" 423 echo "Etcd started..." 424 425 sudo docker run -p 2181:2181 -p 9092:9092 --name kafka -d\ 426 --env ADVERTISED_HOST=172.17.0.1 --env ADVERTISED_PORT=9092 spotify/kafka > log/kafka.log 2>&1 427 428 # # list kafka topics to ensure that kafka is ready 429 sudo docker exec -it kafka /opt/kafka_2.11-0.10.1.0/bin/kafka-topics.sh --list --zookeeper localhost:2181 > /dev/null 2> /dev/null 430 echo "Kafka started..." 431 432 restime0=$(showTime $(date +%s.%N)) 433 434 # set one of the topology for testing 435 #topo=1 436 #topo=2 437 #topo=3 438 topo=4 439 if [ "$topo" == "1" ] 440 then 441 #### 1 - basic topology 442 ./topology.sh 443 echo "$restime0, Loading basic topology to ETCD..." 444 echo "$restime0, Loading basic topology to ETCD..." > log/out.csv 445 elif [ "$topo" == "2" ] 446 then 447 #### 2 -topology with 0 routes 448 ./topology-generate-routes.sh 0 449 echo "$restime0, Loading topology 0 routes to ETCD..." 450 echo "$restime0, Loading topology 0 routes to ETCD..." > log/out.csv 451 elif [ "$topo" == "3" ] 452 then 453 #### 3 topology with 1000 routes 454 ./topology-generate-routes.sh 1000 455 echo "$restime0, Loading topology 1k routes to ETCD..." 456 echo "$restime0, Loading topology 1k routes to ETCD..." > log/out.csv 457 elif [ "$topo" == "4" ] 458 then 459 #### 4 topology with 1000 l2fib entries 460 ./topology-generate-fib.sh 1000 461 echo "$restime0, Loading topology 1k l2fib to ETCD..." 462 echo "$restime0, Loading topology 1k l2fib to ETCD..." > log/out.csv 463 fi 464 } 465 466 # this two scripts have to be executed on each startup of container 467 # to overwrite the core dump path size and mode initial values 468 setCoreDump() { 469 mkdir /tmp/cores 470 kubectl exec vpp -- chmod +x /tmp/change_core_dump_path.sh 471 kubectl exec vpp -- chmod +x /tmp/set_core_dump_size.sh 472 kubectl exec vpp -- bash -c /tmp/change_core_dump_path.sh 473 kubectl exec vpp -- bash -c /tmp/set_core_dump_size.sh 474 } 475 476 # writing two scripts into shared memory to be able to run them 477 # inside container 478 enableCoreDumpInPod() { 479 sudo rm -rf /tmp/cores/ 2>&1 480 cat <<EOF > /tmp/change_core_dump_path.sh 481 echo /tmp/cores/core.dump > /proc/sys/kernel/core_pattern 482 echo "0" > /proc/sys/kernel/core_uses_pid 483 EOF 484 cat <<EOF > /tmp/set_core_dump_size.sh 485 #sed -i '/#* soft core 0/c\** soft core $1' /etc/security/limits.conf 486 echo "* soft core 0" >> /etc/security/limits.conf 487 488 #ulimit -H -c unlimited 489 #ulimit -S -c $1 490 #ulimit -S -c 491 #ulimit -H -c 492 #reboot 493 EOF 494 setCoreDump 495 } 496 497 # function kills vpp process and waits till 498 # the PID is removed from list of running processes 499 # there is a python script killing the main proces - supervisord 500 # that will results in restarting of the container 501 KillVppAndCheck() { 502 vpp_id_line=$(kubectl exec vpp -- ps aux | grep /usr/bin/vpp) 503 #echo $vpp_id_line 504 vpp_id=$(echo $vpp_id_line | awk '{print $2}') 505 #echo $vpp_id 506 sudo rm -f /tmp/cores/core.dump 507 restime0=$(showTime $(date +%s.%N)) 508 echo "$restime0, VPP Killed" >> log/out.csv 509 echo "Killing the vpp - run ${i}" 510 kubectl exec vpp -- kill -s ABRT $vpp_id 511 for (( ig = 1; ig <= 800; ig++ )) 512 do 513 vpp_id_line=$(kubectl exec vpp -- ps aux | grep /bin/vpp-agent) 514 #echo $vpp_id_line 515 new_vpp_id=$(echo $vpp_id_line | awk '{print $2}') 516 if [[ $vpp_id != $new_vpp_id ]] 517 then 518 echo "VPP was killed!" 519 break 520 fi 521 sleep 0.1 522 done 523 } 524 525 # function kills vpp-agent process and waits till 526 # the PID is removed from list of running processes 527 # there is a python script killing the main proces - supervisord 528 # that will results in restarting of the container 529 KillAgentAndCheck() { 530 vpp_id_line=$(kubectl exec vpp -- ps aux | grep /bin/vpp-agent) 531 #echo $vpp_id_line 532 vpp_id=$(echo $vpp_id_line | awk '{print $2}') 533 #echo $vpp_id 534 sudo rm -f /tmp/cores/core.dump 535 restime0=$(showTime $(date +%s.%N)) 536 echo "$restime0, VPP-Agent Killed" >> log/out.csv 537 echo "Killing the VPP-agent - run ${i}" 538 kubectl exec vpp -- kill -s ABRT $vpp_id 539 for (( ig = 1; ig <= 800; ig++ )) 540 do 541 vpp_id_line=$(kubectl exec vpp -- ps aux | grep /bin/vpp-agent) 542 #echo $vpp_id_line 543 new_vpp_id=$(echo $vpp_id_line | awk '{print $2}') 544 if [[ "$vpp_id" != "$new_vpp_id" ]] 545 then 546 echo "VPP-agent was killed!" 547 break 548 fi 549 sleep 0.1 550 done 551 } 552 553 # waits till code dump file is createde or timeout is reached 554 getCoreDumpFile() { 555 last_vpp_core_time='00:00:00.00' 556 file_done=0 557 for (( ig = 1; ig <= 800; ig++ )) 558 do 559 if [ -f /tmp/cores/core.dump ] 560 then 561 vpp_core_final=$(stat -c %y /tmp/cores/core.dump) 562 vpp_core_final_time=$(echo $vpp_core_final | awk '{print $2}') 563 vpp_core_final_time_zone=$(echo $vpp_core_final | awk '{print $3}') 564 tz_sign=${vpp_core_final_time_zone:0:1} 565 tz_value=${vpp_core_final_time_zone:1:4} 566 tz=$(echo "$tz_value/100" | bc) 567 vpp_calc=$(calcNanoTime $vpp_core_final_time) 568 tzsec=$(echo "$tz*3600" | bc) 569 #echo "Core_final:$vpp_core_final" 570 #echo "Core_final_time:$vpp_core_final_time" 571 #echo "Core_final_time_zone:$vpp_core_final_time_zone" 572 #echo "TZsign:$tz_sign" 573 #echo "TZValue:$tz_value" 574 #echo "TZ:$tz" 575 #echo "valc:$vpp_calc" 576 #echo "tzsec:$tzsec" 577 if [ "$vpp_core_final_time" == "$last_vpp_core_time" ] 578 then 579 if [ "$tz_sign" == "+" ] 580 then 581 #echo "substract" 582 timecalc=$(echo "$vpp_calc-$tzsec" | bc) 583 showtime=$(showTime $timecalc) 584 else 585 #echo "adding" 586 timecalc=$(echo "$vpp_calc+$tzsec" | bc) 587 showtime=$(showTime $timecalc) 588 fi 589 corefilesize=$(stat --format=%s "/tmp/cores/core.dump") 590 corefilesizekB=$(echo "$corefilesize/1024" | bc) 591 corefilesizeMB=$(echo "$corefilesizekB/1024" | bc) 592 echo "Core dump file size is :$corefilesizeMB MBs" 593 echo "$showtime, Core dump of size: $corefilesizeMB MB done" >> log/out.csv 594 echo "$showtime, Core dump of size: $corefilesizeMB MB done" 595 file_done=1 596 break 597 else 598 last_vpp_core_time=$vpp_core_final_time 599 fi 600 else 601 if [ $(bc <<< "$ig % 100") -eq 0 ] 602 then 603 echo "Waiting for core dump file: $ig" 604 fi 605 fi 606 sleep 0.1 607 done 608 if [ "$file_done" == "0" ] 609 then 610 restime0=$(showTime $(date +%s.%N)) 611 echo "$restime0, Core dump not created" >> log/out.csv 612 echo "$restime0, Core dump not created" 613 fi 614 } 615 616 # this is the filter taking away all important lines from the log file 617 # and does some extract of data from the lines 618 handleLogsFromOneRun() { 619 kubectl logs vpp > log/vpp$1.log 620 grep -E 'Starting the agent...|stopwatch enabled:|stopwatch disabled:|resync the Linux Configuration|resync the VPP Configuration begin|call took|partial resync time is|stopwatch has no entries|Sleeping while VPP will be ready|VPP is ready to connect|Connecting to etcd took|Resync took|Connecting to VPP took|Connecting to kafka took|All plugins initialized successfully|plugin Linux: Init|plugin GoVPP: Init|plugin VPP: Init|resync the VPP Configuration end|Agent Init|Agent AfterInit' log/vpp$1.log > log/log$1.log 621 cat log/log$1.log | sed -r 's/^time="[0-9-]{10} ([^"]+)".+ msg="([^"]+)"(([^"]*(durationInNs[:]?[ ]?=([0-9]+)))|(\s*))/\1, \2, \6/' >> log/out.csv 622 echo "--,--,--,--------" >> log/out.csv 623 } 624 625 626 ######################################### 627 #################### MAIN ############### 628 ######################################### 629 waitTime="30s" 630 #recoveryTime="30s" 631 recoveryTime="630s" 632 #coredumpLimit="unlimited" 633 coredumpLimit=40000 634 #coredumpLimit=0 635 636 #: <<'BLOCK_COMMENT' 637 # kill_proc 0 sets VPP to be killed 638 # kill_proc 1 sets VPP-Agent to be killed 639 640 #kill_proc=0 641 kill_proc=1 642 643 if [ -z "$1" ] 644 then 645 cycle=1 646 else 647 cycle=$1 648 fi 649 650 setup 651 652 restime0=$(showTime $(date +%s.%N)) 653 kubectl apply -f vnf-vpp.yaml 654 echo "$restime0, Started measuring" >> log/out.csv 655 echo "$restime0, Started measuring" 656 #kubectl apply -f vpp.yaml 657 kubectl apply -f vswitch-vpp.yaml 658 echo "Setting Core dump limits" 659 sleep 10s 660 enableCoreDumpInPod $coredumpLimit 661 echo "Collecting logs" 662 sleep ${waitTime} 663 664 #echo "Core dump file hard limit is:" 665 #kubectl exec vswitch-vpp -- bash -c ulimit -H -c 666 #echo "Core dump file soft limit is:" 667 #kubectl exec vswitch-vpp -- bash -c ulimit -S -c 668 669 for (( i = 1; i <= $cycle; i++ )) 670 do 671 handleLogsFromOneRun ${i} 672 #if [ $(bc <<< "$i % 2") -eq 0 ] 673 #then 674 # echo "Cooling down container for $recoveryTime" 675 # sleep ${recoveryTime} 676 #else 677 # echo "Cooling down container for $waitTime" 678 # sleep ${waitTime} 679 #fi 680 restime0=$(showTime $(date +%s.%N)) 681 echo "$restime0, Container cooled down for $recoveryTime" >> log/out.csv 682 echo "Container cooled down for $recoveryTime" 683 sleep ${recoveryTime} 684 if [ "$kill_proc" == "0" ] 685 then 686 KillVppAndCheck 687 else 688 KillAgentAndCheck 689 fi 690 #sleep 3s 691 echo "Killing the vpp pod - run ${i}" 692 restime0=$(showTime $(date +%s.%N)) 693 694 echo "$restime0, Killed" >> log/out.csv 695 #supervisor_line=$(kubectl exec vpp -- ps aux | grep "/usr/bin/python /usr/bin/supervisord") 696 #supervisor_id=$(echo $supervisor_line | awk '{print $2}') 697 #kubectl exec vpp kill $supervisor_id 698 699 sleep ${waitTime} 700 getCoreDumpFile 701 done 702 703 handleLogsFromOneRun $((cycle+1)) 704 #BLOCK_COMMENT 705 processResult log/out.csv 706 707 zip -r logresult.zip log 708 709 ./remove-pods.sh