From 972755e0718586b678a08b85566722b7074edf06 Mon Sep 17 00:00:00 2001 From: Yongqin Liu Date: Mon, 21 Nov 2016 20:22:50 +0800 Subject: android boottime2: suppport to collect data from multiple boot since the the boottime optimization work is very hard, and boottime reduced will not be obvious compare to the 20s around value, so use average from multiple time is important for the boottime optimization check Change-Id: I9786dbdf5be3109eedf57a0ce0731184f5ab7826 Signed-off-by: Yongqin Liu --- android/boottime2.yaml | 24 +++++++ android/scripts/boottime2.sh | 162 +++++++++++++++++++++++++++++++++++++++++++ android/scripts/common.sh | 89 +++++++++++++----------- 3 files changed, 233 insertions(+), 42 deletions(-) create mode 100644 android/boottime2.yaml create mode 100755 android/scripts/boottime2.sh (limited to 'android') diff --git a/android/boottime2.yaml b/android/boottime2.yaml new file mode 100644 index 0000000..b4044bd --- /dev/null +++ b/android/boottime2.yaml @@ -0,0 +1,24 @@ +metadata: + name: boottime2 + format: "Lava-Test-Shell Test Definition 1.0" + description: "collect the boottime data many times and try to analyse, + when run more than 4 times(including), the average will be + calculated without the maximum and the minmun, if run less + than or equal to 3 time, the average will be calculated with + all data" + maintainer: + - yongqin.liu@linaro.org + os: + - android + scope: + - performance + devices: + - juno + +params: + OPERATION: "COLLECT" + COLLECT_NO: "1" + +run: + steps: + - ./android/scripts/boottime2.sh ${OPERATION} ${COLLECT_NO} diff --git a/android/scripts/boottime2.sh b/android/scripts/boottime2.sh new file mode 100755 index 0000000..d867b0d --- /dev/null +++ b/android/scripts/boottime2.sh @@ -0,0 +1,162 @@ +#!/system/bin/sh + +local_file_path="$0" +local_file_parent=$(dirname "${local_file_path}") +local_file_parent=$(cd "${local_file_parent}"||exit; pwd) +# shellcheck source=android/scripts/common.sh +. "${local_file_parent}/common.sh" + +local_tmp="/data/local/tmp/" +dir_boottime_data="${local_tmp}/boottime" +F_RAW_DATA_CSV="${dir_boottime_data}/boot_time_raw_data.csv" +F_STATISTIC_DATA_CSV="${dir_boottime_data}/boot_time_statistic_data.csv" + + +# dmeg line example +# [ 7.410422] init: Starting service 'logd'... +getTime(){ + key=$1 + if [ -z "${key}" ]; then + return + fi + + key_line=$(grep "${key}" "${LOG_DMESG}") + if [ -n "${key_line}" ]; then + timestamp=$(echo "${key_line}"|awk '{print $2}' | awk -F "]" '{print $1}') + echo "${timestamp}" + fi +} + +getBootTimeInfoFromDmesg(){ + COLLECT_NO=$1 + + LOG_LOGCAT_ALL="${dir_boottime_data}/logcat_all_${COLLECT_NO}.log" + LOG_DMESG="${dir_boottime_data}/dmesg_${COLLECT_NO}.log" + + # dmesg starts before all timers are initialized, so kernel reports time as 0.0. + # we can't work around this without external time metering. + # here we presume kernel message starts from 0 + CONSOLE_SECONDS_START=0 + CONSOLE_SECONDS_END=$(getTime "Freeing unused kernel memory") + if [ ! -z "${CONSOLE_SECONDS_END}" ] && [ ! -z "${CONSOLE_SECONDS_START}" ]; then + CONSOLE_SECONDS=$(echo "$CONSOLE_SECONDS_END $CONSOLE_SECONDS_START - p" | dc) + output_test_result "KERNEL_BOOT_TIME" "pass" "${CONSOLE_SECONDS}" "s" + else + output_test_result "KERNEL_BOOT_TIME" "fail" "-1" "s" + fi + + POINT_FS_MOUNT_START=$(getTime "Freeing unused kernel memory:"|tail -n1) + POINT_FS_MOUNT_END=$(getTime "init: Starting service 'logd'...") + if [ ! -z "${POINT_FS_MOUNT_END}" ] && [ ! -z "${POINT_FS_MOUNT_START}" ]; then + FS_MOUNT_TIME=$(echo "${POINT_FS_MOUNT_END} ${POINT_FS_MOUNT_START} - p" | dc) + output_test_result "FS_MOUNT_TIME" "pass" "${FS_MOUNT_TIME}" "s" + else + output_test_result "FS_MOUNT_TIME" "fail" "-1" "s" + fi + + POINT_FS_DURATION_START=$(getTime "init: /dev/hw_random not found"|tail -n1) + POINT_FS_DURATION_END=$(getTime "init: Starting service 'logd'...") + if [ ! -z "${POINT_FS_DURATION_END}" ] && [ ! -z "${POINT_FS_DURATION_START}" ]; then + FS_MOUNT_DURATION=$(echo "${POINT_FS_DURATION_END} ${POINT_FS_DURATION_START} - p" | dc) + output_test_result "FS_MOUNT_DURATION" "pass" "${FS_MOUNT_DURATION}" "s" + else + output_test_result "FS_MOUNT_DURATION" "fail" "-1" "s" + fi + + POINT_SERVICE_BOOTANIM_START=$(getTime "init: Starting service \'bootanim\'...") + POINT_SERVICE_BOOTANIM_END=$(getTime "init: Service 'bootanim'.* exited with status") + if [ ! -z "${POINT_SERVICE_BOOTANIM_END}" ] && [ ! -z "${POINT_SERVICE_BOOTANIM_START}" ]; then + BOOTANIM_TIME=$(echo "${POINT_SERVICE_BOOTANIM_END} ${POINT_SERVICE_BOOTANIM_START} - p" | dc) + output_test_result "BOOTANIM_TIME" "pass" "${BOOTANIM_TIME}" "s" + else + output_test_result "BOOTANIM_TIME" "fail" "-1" "s" + fi + + TIME_INFO=$(grep "Boot is finished" "${LOG_LOGCAT_ALL}") + if [ -z "${TIME_INFO}" ]; then + output_test_result "ANDROID_BOOT_TIME" "fail" "-1" "s" + else + while echo "${TIME_INFO}"|grep -q "("; do + TIME_INFO=$(echo "${TIME_INFO}"|cut -d\( -f2-) + done + TIME_VALUE=$(echo "${TIME_INFO}"|cut -d\ -f1) + ANDROID_BOOT_TIME=$(echo "${TIME_VALUE} 1000 / p" | dc) + output_test_result "ANDROID_BOOT_TIME" "pass" "${ANDROID_BOOT_TIME}" "s" + fi + + SERVICE_START_TIME_INFO=$(grep "healthd:" "${LOG_DMESG}"|head -n 1) + SERVICE_START_TIME_END=$(echo "$SERVICE_START_TIME_INFO"|cut -d] -f 1|cut -d[ -f2| tr -d " ") + if [ ! -z "${SERVICE_START_TIME_END}" ] && [ ! -z "${CONSOLE_SECONDS_START}" ]; then + SERVICE_START_TIME=$(echo "$SERVICE_START_TIME_END $CONSOLE_SECONDS_START - p" | dc) + output_test_result "ANDROID_SERVICE_START_TIME" "pass" "${SERVICE_START_TIME}" "s" + else + output_test_result "ANDROID_SERVICE_START_TIME" "fail" "-1" "s" + fi + + echo "$CONSOLE_SECONDS $TIME_VALUE 1000 / + p" + if [ ! -z "${CONSOLE_SECONDS}" ] && [ ! -z "${TIME_VALUE}" ]; then + TOTAL_SECONDS=$(echo "$CONSOLE_SECONDS $TIME_VALUE 1000 / + p" | dc) + output_test_result "TOTAL_BOOT_TIME" "pass" "${TOTAL_SECONDS}" "s" + else + output_test_result "TOTAL_BOOT_TIME" "fail" "-1" "s" + fi +} + +OPERATION=$1 +if [ "X${OPERATION}" = "XCOLLECT" ]; then + G_VERBOSE_OUTPUT=FALSE + G_RECORD_LOCAL_CSV=FALSE + COLLECT_NO=$2 + mkdir -p ${dir_boottime_data} + + # shellcheck disable=SC2035 + logcat -d -v time *:V > "${dir_boottime_data}/logcat_all_${COLLECT_NO}.log" + output_test_result "BOOTTIME_LOGCAT_ALL_COLLECT" "pass" + logcat -d -b events -v time > "${dir_boottime_data}/logcat_events_${COLLECT_NO}.log" + output_test_result "BOOTTIME_LOGCAT_EVENTS_COLLECT" "pass" + dmesg > "${dir_boottime_data}/dmesg_${COLLECT_NO}.log" + output_test_result "BOOTTIME_DMESG_COLLECT" "pass" +elif [ "X${OPERATION}" = "XANALYZE" ]; then + count=$2 + i=1 + G_RESULT_NOT_RECORD=TRUE + G_RECORD_LOCAL_CSV=TRUE + export G_RECORD_LOCAL_CSV G_RESULT_NOT_RECORD + while true; do + if [ $i -gt "$count" ]; then + break + fi + getBootTimeInfoFromDmesg ${i} + i=$((i+1)) + done + G_RESULT_NOT_RECORD=FALSE + export G_RESULT_NOT_RECORD + if [ "X${G_RECORD_LOCAL_CSV}" = "XTRUE" ]; then + statistic ${F_RAW_DATA_CSV} 2 |tee ${F_STATISTIC_DATA_CSV} + sed -i 's/=/,/' "${F_STATISTIC_DATA_CSV}" + + G_RECORD_LOCAL_CSV=FALSE + export G_RECORD_LOCAL_CSV + while read -r line; do + if ! echo "$line"|grep -q ,; then + continue + fi + key=$(echo "$line"|cut -d, -f1) + measurement=$(echo "$line"|cut -d, -f2) + units=$(echo "$line"|cut -d, -f3) + output_test_result "${key}" "pass" "${measurement}" "${units}" + done < "${F_STATISTIC_DATA_CSV}" + fi + # set again for following output_test_result + G_RECORD_LOCAL_CSV=FALSE + cd ${local_tmp}|| exit 1 + tar -czvf boottime.tgz boottime + lava-test-run-attach boottime.tgz application/x-gzip + output_test_result "BOOTTIME_ANALYZE" "pass" +else + G_VERBOSE_OUTPUT=FALSE + G_RECORD_LOCAL_CSV=FALSE + export G_VERBOSE_OUTPUT G_RECORD_LOCAL_CSV + echo "Not recognised operation" + output_test_result "BOOTTIME" "fail" +fi diff --git a/android/scripts/common.sh b/android/scripts/common.sh index bc4a526..b2f9091 100644 --- a/android/scripts/common.sh +++ b/android/scripts/common.sh @@ -3,8 +3,10 @@ G_LOOP_COUNT=12 G_RECORD_LOCAL_CSV=TRUE G_VERBOSE_OUTPUT=FALSE +G_RESULT_NOT_RECORD=FALSE F_RAW_DATA_CSV="/data/local/tmp/lava_test_shell_raw_data.csv" F_STATISTIC_DATA_CSV="/data/local/tmp/lava_test_shell_statistic_data.csv" +var_test_func="" ## Description: ## output the max value of the passed 2 parameters @@ -13,10 +15,10 @@ F_STATISTIC_DATA_CSV="/data/local/tmp/lava_test_shell_statistic_data.csv" ## Example: ## max=$(f_max "1.5" "2.0") f_max(){ - local val1=$1 - local val2=$2 - [ -z "$val1" ] && echo $val2 - [ -z "$val2" ] && echo $val1 + val1=$1 + val2=$2 + [ -z "$val1" ] && echo "$val2" + [ -z "$val2" ] && echo "$val1" echo "$val1,$val2"|awk -F, '{if($1<$2) print $2; else print $1}' } @@ -28,10 +30,10 @@ f_max(){ ## Example: ## min=$(f_min "1.5" "2.0") f_min(){ - local val1=$1 - local val2=$2 - [ -z "$val1" ] && echo $val1 - [ -z "$val2" ] && echo $val2 + val1=$1 + val2=$2 + [ -z "$val1" ] && echo "$val1" + [ -z "$val2" ] && echo "$val2" echo "$val1,$val2"|awk -F, '{if($1>$2) print $2; else print $1}' } @@ -48,30 +50,31 @@ f_min(){ ## if less than 4 samples for that key/item there, average will be calculated as total/count ## if 4 or more samples for that key/item there, average will be calculated with max and min excluded statistic(){ - local f_data=$1 + f_data=$1 if ! [ -f "$f_data" ]; then return fi - local field_no=$2 + field_no=$2 if [ -z "$field_no" ]; then field_no=2 fi - local total=0 - local max=0 - local min=0 - local old_key="" - local new_key="" - local count=0 - local units="" - sort ${f_data} >${f_data}.sort - for line in $(cat "${f_data}.sort" |tr ' ' '~'); do + total=0 + max=0 + min=0 + old_key="" + new_key="" + count=0 + units="" + sort "${f_data}" >"${f_data}.sort" + while read -r line; do + line=$(echo "$line"|tr ' ' '~') if ! echo "$line"|grep -q ,; then continue fi - new_key=$(echo $line|cut -d, -f1) - local measurement_units=$(echo $line|cut -d, -f${field_no}) - if echo ${measurement_units}|grep -q '~'; then - value=$(echo ${measurement_units}|cut -d~ -f1) + new_key=$(echo "$line"|cut -d, -f1) + measurement_units=$(echo "$line"|cut -d, -f${field_no}) + if echo "${measurement_units}"|grep -q '~'; then + value=$(echo "${measurement_units}"|cut -d~ -f1) else value=${measurement_units} fi @@ -83,7 +86,7 @@ statistic(){ min=$(f_min "$min" "$value") else if [ "X${old_key}" != "X" ]; then - if [ $count -ge 4 ]; then + if [ "${count}" -ge 4 ]; then average=$(echo "${total},${max},${min},$count"|awk -F, '{printf "%.2f",($1-$2-$3)/($4-2);}') else average=$(echo "${total},$count"|awk -F, '{printf "%.2f",$1/$2;}') @@ -99,13 +102,13 @@ statistic(){ min="${value}" old_key="${new_key}" count=1 - if echo ${measurement_units}|grep -q '~'; then - units=$(echo ${measurement_units}|cut -d~ -f2) + if echo "${measurement_units}"|grep -q '~'; then + units=$(echo "${measurement_units}"|cut -d~ -f2) else units="" fi fi - done + done < "${f_data}.sort" if [ "X${new_key}" != "X" ]; then if [ $count -ge 4 ]; then average=$(echo "${total},${max},${min},$count"|awk -F, '{printf "%.2f",($1-$2-$3)/($4-2);}') @@ -133,17 +136,17 @@ statistic(){ ## G_VERBOSE_OUTPUT: when this environment variant is set to "TRUE", and only it is TRUE, ## the verbose informain about the result will be outputed output_test_result(){ - local test_name=$1 - local result=$2 - local measurement=$3 - local units=$4 + test_name=$1 + result=$2 + measurement=$3 + units=$4 if [ -z "${test_name}" ] || [ -z "$result" ]; then return fi - local output="" - local lava_paras="" - local output_csv="" + output="" + lava_paras="" + output_csv="" if [ -z "$units" ]; then units="points" fi @@ -160,8 +163,9 @@ output_test_result(){ echo "${output}" fi - local cmd="lava-test-case" - if [ -n "$(which $cmd)" ];then + cmd="lava-test-case" + if [ "X${G_RESULT_NOT_RECORD}" = "XFALSE" ] && [ -n "$(which $cmd)" ];then + # shellcheck disable=SC2086 $cmd ${lava_paras} elif [ "X${G_VERBOSE_OUTPUT}" = "XTRUE" ];then echo "$cmd ${lava_paras}" @@ -174,17 +178,18 @@ output_test_result(){ } func_print_usage_common(){ - echo "$(basename $0) [--record-csv TRUE|others] [--loop-count LOOP_COUNT]" + script_name=$(basename "$0") + echo "${script_name} [--record-csv TRUE|others] [--loop-count LOOP_COUNT]" echo " --record-csv: specify if record the result in csv format in file ${F_RAW_DATA_CSV}" echo " Only record the file when TRUE is specified." echo " --loop-count: specify the number that how many times should be run for each application to get the average result, default is 12" echo " --verbose-output: output the result and lava-test-case command for each test case each time it is run" - echo "$(basename $0) [--help|-h]" + echo "${script_name} [--help|-h]" echo " print out this usage." } func_parse_parameters_common(){ - local para_loop_count="" + para_loop_count="" while [ -n "$1" ]; do case "X$1" in X--record-csv) @@ -228,7 +233,7 @@ func_parse_parameters_common(){ done if [ -n "${para_loop_count}" ]; then - local tmp_str=$(echo ${para_loop_count}|tr -d '[:digit:]') + tmp_str=$(echo "${para_loop_count}"|tr -d '[:digit:]') if [ -z "${tmp_str}" ]; then G_LOOP_COUNT=${para_loop_count} else @@ -264,11 +269,11 @@ run_test(){ if [ "X${G_RECORD_LOCAL_CSV}" = "XTRUE" ]; then [ -f "${F_RAW_DATA_CSV}" ] && rm "${F_RAW_DATA_CSV}" [ -f "${F_STATISTIC_DATA_CSV}" ] && rm "${F_STATISTIC_DATA_CSV}" - mkdir -p $(dirname ${F_RAW_DATA_CSV}) + mkdir -p "$(dirname ${F_RAW_DATA_CSV})" fi loop_index=0 - while [ ${loop_index} -lt ${G_LOOP_COUNT} ]; do + while [ "${loop_index}" -lt "${G_LOOP_COUNT}" ]; do if [ -n "${var_test_func}" ]; then ${var_test_func} fi -- cgit v1.2.3