-
Notifications
You must be signed in to change notification settings - Fork 43
/
production-log-load-stats
165 lines (151 loc) · 6.62 KB
/
production-log-load-stats
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
#!/bin/bash
if [ ${BASH_VERSION%%.*} -lt 4 ]; then
echo "bash version >=4 is required!"
exit 2
fi
usage() {
echo "$*"
echo
echo "usage: $0 logfile [sort-results]"
echo "where (optional) sort-results can be:"
echo " 2: sort by count"
echo " 3: sort by min time"
echo " 4: sort by max time"
echo " 5: sort by avg time"
echo " 6: sort by mean time"
echo " 7: sort by sum time / percentage"
exit 1
}
if [ $# -lt 1 ]; then
usage "missing argument!"
fi
f=${1}
if ! [ -f $f ]; then
usage "cannot read file $f"
fi
if [ $# -gt 1 ]; then
sortresults=${2}
if ! [[ $sortresults =~ ^[2-7]$ ]]; then
usage "sort-results can be only a number from 2 to 7"
fi
fi
# remove auxiliary files
rm -f times.* results.* concur-requests.*
# parse input file to extract from lines like:
#
# 2020-04-01T03:17:59 [I|app|07bb6705] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
# ..
# 2020-04-01T03:17:59 [I|app|07bb6705] Completed 200 OK in 38ms (Views: 10.7ms | ActiveRecord: 7.3ms)
#
# ignore empty request IDs
# relevant data: requestID, processing/completed, type of request or its duration; in particular:
#
# 07bb6705 p Katello::Api::V2::RootController#rhsm_resource_list
# 07bb6705 c 38ms
echo "$(date): extracting relevant data from input file '${f}'.."
grep -e "\] Processing by" -e "\] Completed" $f | cut -d'|' -f3 | grep -v "^]" | sed "s/\] Completed / c in /g" | sed "s/\] Processing by / p in in /g" | awk -F " in " '{ print $1" "$3 }' | awk '{ print $1" "$2" "$3 }' > processing.completed.extracted
# Check if there are any valid results by looking at processing.completed.extracted or exit
if [ ! -s processing.completed.extracted ]; then
echo "$(date): No valid requests or responses found in log file '${f}', exiting"
rm -f processing.completed.extracted
exit 3
fi
# process those extracted data as tripples ($req $act $typeortime) as follows:
# - if act is "p" / Processing, memorize the type of request in a "requests" hash
# - if act is "c" / Completed, fetch from "requests" hash the type and append the time (without "ms") to the relevant file
echo "$(date): processing the extracted data (this can take a while).."
declare -A requests
declare -A times
# also count number of pending requests for stats about level of concurrency
pending=0
maxpending=0
maxpendingid=""
pendinglist=()
while read req act typeortime; do
if [ "$act" == "p" ]; then
requests[${req}]="${typeortime}"
pending=$((pending+1))
pendinglist+=($pending)
if [ ${pending} -gt ${maxpending} ]; then
maxpending=${pending}
maxpendingid=${req}
fi
else
type=${requests[${req}]}
# if $type is empty, we didnt hash the request that was logged in a previous (missing) logfile - ignore this
if [ -n "${type}" ]; then
unset requests[${req}]
times[${type}]+="${typeortime%ms},"
# echo ${typeortime%ms} >> times.${type}
pending=$((pending-1))
pendinglist+=($pending)
else # increment all past concurrency levels by one
maxpending=$((maxpending+1))
# echo "$(date): ${req} ${act} ${typeortime}: bumping pendinglist of size ${#pendinglist[@]}"
for i in ${!pendinglist[@]}; do
pendinglist[$i]=$((pendinglist[$i]+1))
done
fi
fi
done < <(cat processing.completed.extracted)
rm -f processing.completed.extracted
# write the times to corresponding times.* files
for key in "${!times[@]}"; do
echo ${times[$key]} | tr ',' '\n' | grep -v ^$ > times.${key}
done
# each file times.${type} now contains response times of requests of the type ${type}; let do some stats over them
# first, find overall number of requests and their duration and print it to results.summary file
echo "$(date): summarizing stats.."
read sumall countall < <(cat times.* | awk '{ sum+=$1; c+=1 } END { print sum" "c }')
echo "there were $countall requests taking $sumall ms (i.e. $(echo $sumall | awk '{ printf "%.2f", $1/3600000 }') hours, i.e. $(echo $sumall | awk '{ printf "%.2f", $1/3600000/24 }') days) in summary" > results.summary
echo >> results.summary
# for each request type, find basic stats and print it to other results.* files
echo -e "type\t\t\t\t\t\tcount\tmin\tmax\tavg\tmean\tsum\t\tpercentage" > results.header
echo "--------------------------------------------------------------------------------------------------------------------" >> results.header
spaces=" "
for type in $(ls times.* -1 | cut -d'.' -f2); do
outtype=${type##*::}
len=${#outtype}
if [ $len -gt 47 ]; then
outtype="..${outtype:(-45)}"
else
outtype="${outtype}${spaces:0:$((47-len))}"
fi
sort -n times.${type} > aux; mv -f aux times.${type}
read sum count < <(cat times.${type} | awk '{ sum+=$1; c+=1 } END { print sum" "c }')
min=$(head -n1 times.${type})
max=$(tail -n1 times.${type})
avg=$((sum/count))
mean=$(head -n $(((count+1)/2)) times.${type} | tail -n1) # technically, for odd $count, this is not statistical term of mean, but let get over it for now
percents=$(echo "$sum $sumall" | awk '{ printf "%.2f %", 100*$1/$2 }')
if [ $sum -lt 10000000 ]; then
sum="${sum}\t"
fi
echo -e "${outtype}\t${count}\t${min}\t${max}\t${avg}\t${mean}\t${sum}\t${percents}" >> results.table
done
echo >> results.table
# count stats from concurrent requests processed
echo ${pendinglist[@]} | tr ' ' '\n' > concur-requests.txt
sort -n concur-requests.txt > concur-requests.sorted.txt
read sumconcur countconcur < <(awk '{ sum+=$1; c+=1 } END { print sum" "c }' concur-requests.txt)
echo "concurrent requests:" > results.concur
echo "- MAX: $(tail -n1 concur-requests.sorted.txt) when processing request with ID '${maxpendingid}'" >> results.concur
echo "- AVG: $(echo $sumconcur $countconcur | awk '{ printf "%.0f", $1/$2 }')" >> results.concur
echo "- MEAN: $(head -n $(((countconcur+1)/2)) concur-requests.sorted.txt | tail -n1)" >> results.concur
echo "- 90%PERCENTILE: $(tail -n $((countconcur/10)) concur-requests.sorted.txt | head -n1)" >> results.concur
echo >> results.concur
echo > results.footer
echo "results are in results.* files, individual requests per each type are in times.* files, concurrent requests in concur-requests.txt file" >> results.footer
echo >> results.footer
echo "Be aware, next execution of the script overrides those files." >> results.footer
echo >> results.footer
# now, print all results.* files to stdout; if table should be sorted, sort it
echo
for i in summary header table concur footer; do
if [ "$i" == "table" -a "$sortresults" ]; then
cmd="sort -nrk ${sortresults}"
else
cmd="cat"
fi
$cmd results.${i}
done