Home > AWS, CPU speed, EC2, Linux Scheduler, Virtualization > AWS RDS and EC2 CPU performance (in)consistency – Part 2

AWS RDS and EC2 CPU performance (in)consistency – Part 2

After discovering that in my prior tests there was significant variable factor of sqlplus session connect time (which still needs to be researched but this is for a later time), I decided to try and isolate this factor so that the test would be focused more on sql elapsed time as a measure of CPU performance.

I modified the script to have large 15 sec delay to setup connections and also to separately report session creation times and sql execution times. I also printed “ps” PSR field for corresponding server processes in a hope to spot any dependency. The test sql was also modified in order to increase elapsed time :

with t as ( SELECT rownum FROM dual CONNECT BY LEVEL <= 200 )
select /*+ ALL_ROWS */ count(*) as cnt from t,t,t,t ;

Full script is listed in the end of this post.

With that on c4.4xlarge EC2 instance (i.e. 16 vCPUs / 8 cores / 16 Hyperthreads ) I am observing following:

When number of parallel sessions is less or equal to 8, all sessions sql elapsed time is consistent at about 40 seconds. For example with 8 sessions:

8-sessions

However when I add one more session to make it 9, the sql elapsed time on two sessions out of 9 increases by 50%  :

9-sessions

I interpret this as additional session starting to share a core with one of the other 8 sessions, thus making the two sessions run slower.

What is striking is that once a session starts running – its vCPU assignment does not change. This can be seen with “top” by pressing “F” then moving cursor to highlight P=Last Used Cpu (SMP) field then pressing space bar to select it. One would expect that kernel scheduler would try and balance CPU workload by moving processes across all available cores. However this is not happening, and as a result I get 50% longer elapsed time on 2 sessions out of 9. Of course scheduler switching CPU may not be cheap considering all the associated work and also that the process will loose CPU L-cache contents thus reducing overall performance in exchange for more consistency.

Update 1/11/2017: The tests were run on AWS EC2 c4.4xlarge instance with following OS and Oracle versions:

Red Hat Enterprise Linux Server release 7.2 (Maipo)
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production

Appendix: Script used in this test

#!/bin/ksh
#
# cpu_throughput_test_v2_continuous_cpudetails.sh
#
# this script runs CPU-intensive sql in N parallel sqlplus sessions
#
# Parameters: $1 - how many parallel sqlplus sessions to run
#
# Usage example: cpu_throughput_test_v2_continuous_cpudetails.sh 8 | tee 8_sessions.log
#
# Script Steps:
#    1. create N named pipes
#    2. start N sqlplus processes in background, connect to db and start reading from named pipes
#    3. push into pipes:
#       3.1 "sleep 15" to let sessions establish
#       3.2 for debugging: set time on sqlprompt, set timing
#       3.3 for debugging: push into pipes sql to find corresponding server SPID
#       3.4 push test SQL into pipes
#       3.5 for debugging: print last known CPU number
#    5. wait for all background sqlplus sessions to finish and measure elapsed time
#    6. repeat above process 100 times for given parallel=N
#
# change log:
#    122016 - A. Balbekov, initial creation
#

PARALLEL=$1
#CONN=username/psw@//host:port/sid
CONN="/ as sysdba"

trap 'kill -KILL `jobs -p` ; exit' INT
trap 'rm -f inputpipe_*; exit' EXIT

# run 100 tests
rm output_*
for tst_cnt in {1..100} ; do

        # start PARALLEL sqlplus processes in background having them wait for input in testpipes
		# the processes will immediately block until there is something in pipes (i.e. will not immediately connect to database)
        i=0
        while [ $i -lt $PARALLEL ] ; do
                rm -f inputpipe_$i
                mkfifo inputpipe_$i
                sqlplus $CONN < inputpipe_$i 1>output_$i 2>&1 &
                (( i=$i+1 ))
        done

        # push commands into inputpipes to trigger sqlplus executions
		# push this in background to make it as parallel as possible
        i=0
        while [ $i -lt $PARALLEL ] ; do
				# output of folowing block goes into named pipes, so the pipes initiate
				# this wakes up blocked sqlplus processes that are waiting to read from the pipes
				# let the first command be "sleep" to give time for sqlplus db connections to establish
                (
				sleep 15
				# set time on sqlprompt for debugging
				# set timing for debugging
				echo "set time on timing on"
				# determine SPID for server process
				echo "col spid new_value v_spid noprint"
				echo 'select p.spid from v$session s, v$process p'
				echo 'where s.sid in (select sid from v$mystat where rownum <=1)'
				echo "and s.paddr = p.addr;"
				# run test sql
                echo "with t as ( SELECT rownum FROM dual CONNECT BY LEVEL <= 200 )"                 echo "select /*+ ALL_ROWS */ count(*) as cnt from t,t,t,t ;" 				## 				# print last known CPU number 				echo 'host ps -o pid,psr,comm -p &&v_spid'                 echo exit                 ) > inputpipe_$i &
                (( i=$i+1 ))
        done

        # wait until all background processes finish and measure time
		# this time includes 15 sec sleep time above
        TIMEFORMAT=%R
        echo -n `date` " "
        (time wait) 2>&1  # redirect err to stdout since time ouputs to err

		# collect and print some per-process diagnostics output
		s_process=""; s_vCPU=""; s_elapsed=""; s_sqlplus_banner_time=""; s_sqlplus_1st_prompt_time=""
		i=0
		while [ $i -lt $PARALLEL ] ; do
			s_process="${s_process} `printf "%8d" $i`"
			s_sqlplus_banner_time="$s_sqlplus_banner_time `head -2 output_$i | tail -1 | awk '{print $9}'`"
			s_sqlplus_1st_prompt_time="$s_sqlplus_1st_prompt_time `head -11 output_$i | tail -1 | awk '{print $2}'`"
			# collect "last known CPU number"
			s_vCPU="$s_vCPU `tail -4 output_$i | head -1 | awk '{printf "[%6d]", $2}'`"
			# collect elapsed times; careful! - this gets only min:sec portion in elapsed time
			s_elapsed=${s_elapsed}" "`tail -6 output_$i | head -1 | awk '{print $2}' | awk -F ":" '{print $2":"$3}'`
			(( i=$i+1 ))
		done
		echo "Process Number           : $s_process"
		echo "sqlplus banner time      : $s_sqlplus_banner_time"
		echo "sqlplus 1st prompt time  : $s_sqlplus_1st_prompt_time"
		echo "ps PSR (Last Known CPU)  : $s_vCPU"
		echo "SQL Elapsed time(min:Sec): $s_elapsed"

done

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: