diff --git a/continuousintegration/log_analysis/postprocess b/continuousintegration/log_analysis/postprocess
new file mode 100755
index 0000000000000000000000000000000000000000..21db63c8a2c5f151621c269454d9c14664ba75ca
--- /dev/null
+++ b/continuousintegration/log_analysis/postprocess
@@ -0,0 +1,10 @@
+#!/bin/sh
+
+process()
+{
+ echo "log_data = ["
+ awk '/[^ ];$/ && NF == 21 { print $0; }' $1
+ echo "];"
+}
+
+process log_analysis.m >log_analysis_post.m
diff --git a/continuousintegration/log_analysis/preprocess b/continuousintegration/log_analysis/preprocess
index f6633e585260f9dac3c0f6ab130df294b43038e7..82b600ca36d38ca47b1bded1d74cf904b93cfbe0 100755
--- a/continuousintegration/log_analysis/preprocess
+++ b/continuousintegration/log_analysis/preprocess
@@ -2,6 +2,11 @@
#
# Preprocess logfiles for more efficient data extraction
+# Logfile names
+MGM_LOG=xrdlog.mgm
+FRONTEND_LOG=cta-frontend.log
+TAPED_LOG=cta-taped.log
+
# Colours
NC='\033[0m' # No colour
RED='\033[0;31m'
@@ -13,6 +18,12 @@ YELLOW='\033[1;33m'
BLUE='\033[0;34m'
LT_BLUE='\033[1;34m'
+error()
+{
+ echo -e "${RED}$*${NC}" >&2
+ exit 1
+}
+
echoc()
{
COLOUR=$1
@@ -22,11 +33,13 @@ echoc()
process_mgm_log()
{
- echoc $LT_BLUE "Extracting log messages from xrdlog.mgm..."
+ [ -r ${MGM_LOG} ] || error "Can't open ${MGM_LOG}"
+
+ echoc $LT_BLUE "Extracting log messages from ${MGM_LOG}..."
- DATE_OFFSET=$(head -1 xrdlog.mgm-20180414 | awk '{ print $1 }')
+ DATE_OFFSET=$(head -1 ${MGM_LOG} | awk '{ print $1 }')
- awk -vDATE_OFFSET="$DATE_OFFSET" '
+ awk -vDATE_OFFSET="$DATE_OFFSET" 'BEGIN { COMMIT_EVENT="ACO" }
function processLine(pattern, event, logline) {
gsub("time=.*" pattern, "", logline)
split(logline,logarray)
@@ -41,9 +54,10 @@ process_mgm_log()
/ default ARCHIVED / { processLine("ARCHIVED", "ARC", $0) }
/ default CLOSEW / { processLine("CLOSEW", "CLO", $0) }
/ default SYNC::CREATE / { processLine("CREATE", "CRE", $0) }
- / default SYNC::PREPARE / { processLine("PREPARE", "PRE", $0) }
+ / default SYNC::PREPARE / { processLine("PREPARE", "PRE", $0); COMMIT_EVENT="RCO" }
/ retrieve_written CLOSEW / { processLine("CLOSEW", "RWC", $0) }
- ' xrdlog.mgm-20180414 xrdlog.mgm-20180415 >xrdmgm.log.$$
+ / subcmd=commit / { processLine("subcmd=commit path=", COMMIT_EVENT, $0) }
+ ' ${MGM_LOG} >xrdmgm.log.$$
echoc $LT_BLUE "done.\nSorting..."
sort -n xrdmgm.log.$$ >xrdmgm-events.log
@@ -53,10 +67,12 @@ process_mgm_log()
process_frontend_log()
{
+ [ -r ${FRONTEND_LOG} ] || error "Can't open ${FRONTEND_LOG}"
+
echoc $LT_BLUE "Extracting archive log messages from cta-frontend..."
- FE_HOSTNAME=$(head -1 cta-frontend.log | awk '{ print $4 }')
- DATE_OFFSET=$(head -1 cta-frontend.log | awk '{ gsub("^Apr ", "201804"); print $1 }')
+ FE_HOSTNAME=$(head -1 ${FRONTEND_LOG} | awk '{ print $4 }')
+ DATE_OFFSET=$(head -1 ${FRONTEND_LOG} | awk '{ gsub("^Apr ", "201804"); print $1 }')
awk -vFE_HOSTNAME="$FE_HOSTNAME" -vDATE_OFFSET="$DATE_OFFSET" '
function processLine(event, logline) {
@@ -69,14 +85,15 @@ process_frontend_log()
HOURS=substr(logarray[2],1,2)
MINS=substr(logarray[2],4,2)
SECS=substr(logarray[2],7,2)
+ MSECS=substr(logarray[2],10)
timesecs=((DAYS*24 + HOURS)*60 + MINS)*60 + SECS
- print logarray[3],event,timesecs
+ print logarray[3],event,timesecs "." MSECS
}
/CREATE/ { processLine("CRE", $0) }
/CLOSEW/ { processLine("CLW", $0) }
/PREPARE/ { processLine("PRE", $0) }
- ' cta-frontend.log >cta-frontend.log.$$
+ ' ${FRONTEND_LOG} >cta-frontend.log.$$
echoc $LT_BLUE "done.\nSorting..."
sort -n cta-frontend.log.$$ >cta-frontend-events.log
@@ -86,10 +103,12 @@ process_frontend_log()
process_taped_log()
{
+ [ -r ${TAPED_LOG} ] || error "Can't open ${TAPED_LOG}"
+
echoc $LT_BLUE "Extracting archive log messages from cta-taped..."
- TAPED_HOSTNAME=$(head -1 cta-taped.log | awk '{ print $4 }')
- DATE_OFFSET=$(head -1 cta-taped.log | awk '{ gsub("^Apr ", "201804"); print $1 }')
+ TAPED_HOSTNAME=$(head -1 ${TAPED_LOG} | awk '{ print $4 }')
+ DATE_OFFSET=$(head -1 ${TAPED_LOG} | awk '{ gsub("^Apr ", "201804"); print $1 }')
awk -vTAPED_HOSTNAME="$TAPED_HOSTNAME" -vDATE_OFFSET="$DATE_OFFSET" '
function processLine(event, logline) {
@@ -101,8 +120,9 @@ process_taped_log()
HOURS=substr(logarray[2],1,2)
MINS=substr(logarray[2],4,2)
SECS=substr(logarray[2],7,2)
+ MSECS=substr(logarray[2],10)
timesecs=((DAYS*24 + HOURS)*60 + MINS)*60 + SECS
- print logarray[3],event,timesecs
+ print logarray[3],event,timesecs "." MSECS
}
/In ArchiveMount::getNextJobBatch\(\): popped one job/ { processLine("A_POP", $0) }
@@ -118,7 +138,7 @@ process_taped_log()
/File successfully read from tape/ { processLine("R_RED", $0) }
/Opened disk file for writing/ { processLine("R_OPN", $0) }
/File successfully transfered to disk/ { processLine("R_TRF", $0) }
- ' cta-taped.log >cta-taped.log.$$
+ ' ${TAPED_LOG} >cta-taped.log.$$
echoc $LT_BLUE "done.\nSorting..."
sort -n cta-taped.log.$$ >cta-taped-events.log
diff --git a/continuousintegration/log_analysis/tracefile b/continuousintegration/log_analysis/tracefile
index 366e42766055c1b0c466364801284ff47807c454..bff7bc5925e9d2d411ef7fc497483a0f39f8e0e8 100755
--- a/continuousintegration/log_analysis/tracefile
+++ b/continuousintegration/log_analysis/tracefile
@@ -11,22 +11,23 @@ check_results()
{
NUM_EXPECTED=$1
NUM_RECEIVED=$(cut -d' ' -f2 | sort | uniq | wc -l)
- [ $NUM_EXPECTED -eq $NUM_RECEIVED ] && return 1
- return 0
+ [ $NUM_EXPECTED -eq $NUM_RECEIVED ] && return 0
+ return 1
}
get_mgm_times()
{
- #TMP_RESULTS=$(grep -m5 "^$1 " xrdmgm-events.log)
- TMP_RESULTS=$(grep "^$1 " xrdmgm-events.log)
+ TMP_RESULTS=$(grep -m7 "^$1 " xrdmgm-events.log)
- echo -e "${TMP_RESULTS}" | check_results 5
- [ $? -eq 0 ] && TMP_RESULTS=$(grep "^$1 " xrdmgm-events.log)
+ echo -e "${TMP_RESULTS}" | check_results 7
+ [ $? -ne 0 ] && TMP_RESULTS=$(grep "^$1 " xrdmgm-events.log)
- TIME_ARCHIVED=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 ARC" | cut -d' ' -f3)
- TIME_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLO" | cut -d' ' -f3)
TIME_CREATE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CRE" | cut -d' ' -f3)
+ TIME_ACOMMIT=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 ACO" | cut -d' ' -f3)
+ TIME_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLO" | cut -d' ' -f3)
+ TIME_ARCHIVED=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 ARC" | cut -d' ' -f3)
TIME_PREPARE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 PRE" | cut -d' ' -f3)
+ TIME_RCOMMIT=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 RCO" | cut -d' ' -f3)
TIME_RETRIEVED=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 RWC" | cut -d' ' -f3)
}
@@ -35,7 +36,7 @@ get_frontend_times()
TMP_RESULTS=$(grep -m3 "^$1 " cta-frontend-events.log)
echo -e "${TMP_RESULTS}" | check_results 3
- [ $? -eq 0 ] && TMP_RESULTS=$(grep "^$1 " cta-frontend-events.log)
+ [ $? -ne 0 ] && TMP_RESULTS=$(grep "^$1 " cta-frontend-events.log)
TIME_FE_CREATE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CRE" | cut -d' ' -f3)
TIME_FE_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLW" | cut -d' ' -f3)
@@ -44,11 +45,13 @@ get_frontend_times()
get_taped_times()
{
- # 5+5+1 messages for 2 archive copies + 7 messages for retrieve = 18 messages total
- TMP_RESULTS=$(grep -m18 "^$1 " cta-taped-events.log)
+ # 1 archive copy: 5+1 messages
+ # 2 archive copies: 5+5+1 messages
+ # retrieve: 7 messages
+ TMP_RESULTS=$(grep -m13 "^$1 " cta-taped-events.log)
echo -e "${TMP_RESULTS}" | check_results 13
- [ $? -eq 0 ] && TMP_RESULTS=$(grep "^$1 " cta-taped-events.log)
+ [ $? -ne 0 ] && TMP_RESULTS=$(grep "^$1 " cta-taped-events.log)
TIME_TS_ARCHIVE_POP=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_POP" | cut -d' ' -f3)
TIME_TS_ARCHIVE_TASKS=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_TSS" | cut -d' ' -f3)
@@ -80,7 +83,8 @@ get_times()
echo -n "$ARCHIVE_ID $FILE_ID "
echo -n "$(get_offset_time $TIME_CREATE $TIME_FE_CREATE) "
- echo -n "$(get_offset_time $TIME_FE_CREATE $TIME_CLOSEW) "
+ echo -n "$(get_offset_time $TIME_FE_CREATE $TIME_ACOMMIT) "
+ echo -n "$(get_offset_time $TIME_ACOMMIT $TIME_CLOSEW) "
echo -n "$(get_offset_time $TIME_CLOSEW $TIME_FE_CLOSEW) "
echo -n "$(get_offset_time $TIME_FE_CLOSEW $TIME_TS_ARCHIVE_POP) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_POP $TIME_TS_ARCHIVE_TASKS) "
@@ -98,7 +102,8 @@ get_times()
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_POSITION $TIME_TS_RETRIEVE_READ) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_READ $TIME_TS_RETRIEVE_OPEN) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_OPEN $TIME_TS_RETRIEVE_DONE) "
- echo "$(get_offset_time $TIME_TS_RETRIEVE_DONE $TIME_RETRIEVED);"
+ echo -n "$(get_offset_time $TIME_TS_RETRIEVE_DONE $TIME_RCOMMIT);"
+ echo "$(get_offset_time $TIME_RCOMMIT $TIME_RETRIEVED);"
}
FILE_NUM_START=${1:-1}