Add timestamps to master-worker messaging

Timestamps enable matching traced system calls in the worker to
observed latencies. This is essential when finding out explanations
for anomalies in response times.

Author: askervin

metrics/scaling/k8s_scale_nc.sh

@@ -24,7 +24,7 @@ nc_port=33101
 nc_req_msg=$(head -c $nc_req_msg_len /dev/zero | tr  '\0' 'x')
 nc_percentiles=(0 1 5 25 50 75 95 99 100)
 
-pod_command="[\"nc\", \"-lk\", \"-p\", \"${nc_port}\", \"-e\", \"/bin/cat\"]"
+pod_command="[\"nc\", \"-lk\", \"-p\", \"${nc_port}\", \"-e\", \"sh\", \"-c\", \"echo \${EPOCHREALTIME/./}; cat; echo \${EPOCHREALTIME/./}\"]"
 
 # Set some default metrics env vars
 TEST_ARGS="runtime=${RUNTIME}"
@@ -340,7 +340,7 @@ run() {
 
 		if [[ ${nc_reqs_per_pod} -ge 1 ]]; then
 			mkdir -p "$RESULT_DIR" 2>/dev/null || true
-			local latency_raw_output="$RESULT_DIR/${TEST_NAME// /-}.t_pods_round_ip_latency_fail_rx.raw"
+			local latency_raw_output="$RESULT_DIR/${TEST_NAME// /-}.tmaster_tworker_pods_r_ipord_ipaddr_lattot_latconn_latio_latdisconn_rx.raw"
 			pod_ips=$(kubectl get pods --selector ${LABEL}=${LABELVALUE} -o json | jq -r '.items[].status.podIP')
 			if [[ ${reqs} != $(echo $pod_ips | wc -w) ]]; then
 				info "WARNING: pod IP count mismatch expected ${reqs} found $(echo $pod_ips | wc -w)"
@@ -349,18 +349,30 @@ run() {
 			local latency_failures=0
 			local latency_pod_array=()
 			for latency_round in $(seq ${nc_reqs_per_pod}); do
+				local pod_ip_ord=0
 				for pod_ip in ${pod_ips}; do
+					pod_ip_ord=$(( pod_ip_ord + 1 ))
 					local latency_failed=0
-					local latency_pod_start_time=$(date +%s%N)
-					local latency_pod_response=$(echo ${nc_req_msg} | nc ${pod_ip} ${nc_port})
-					local latency_pod_end_time=$(date +%s%N)
-					local latency_response_microseconds=$(( (latency_pod_end_time - latency_pod_start_time) / 1000 ))
+					local latency_pod_start_time=${EPOCHREALTIME/./}
+					local latency_pod_start_response_end=$(echo ${latency_pod_start_time} ${nc_req_msg} | nc ${pod_ip} ${nc_port})
+					# start_response_end contents: <worker_start_ts> <master_ts> <nc_req_msg> <worker_end_ts>
+					local latency_pod_end_time=${EPOCHREALTIME/./}
+					local latency_response_microseconds=$(( latency_pod_end_time - latency_pod_start_time ))
+					local latency_pod_response=$(echo $latency_pod_start_response_end | awk '{print $3}')
 					if [[ "$latency_pod_response" != "${nc_req_msg}" ]]; then
 						latency_failures=$(( latency_failures + 1 ))
+						local latency_pod_first_t=000000000000000
+						local latency_pod_last_t=000000000000000
 						latency_failed=1
+					else
+						local latency_pod_first_t=$(echo $latency_pod_start_response_end | awk '{print $1}')
+						local latency_pod_last_t=$(echo $latency_pod_start_response_end | awk '{print $4}')
 					fi
+					local latency_pod_local_io=$(( latency_pod_last_t - latency_pod_first_t ))
+					local latency_pod_conn=$(( latency_pod_first_t - latency_pod_start_time ))
+					local latency_pod_disconn=$(( latency_pod_end_time - latency_pod_last_t ))
 					latency_pod_array+=($latency_response_microseconds)
-					echo "$latency_pod_start_time $reqs $latency_round $pod_ip $latency_response_microseconds $latency_failed $(echo $latency_pod_response | wc -c)" >> $latency_raw_output
+					echo "$latency_pod_start_time $latency_pod_first_t $reqs $latency_round $pod_ip_ord $pod_ip $latency_response_microseconds $latency_pod_conn $latency_pod_local_io $latency_pod_disconn $(echo $latency_pod_start_response_end | wc -c)" >> $latency_raw_output
 				done
 			done
 			IFS=$'\n'