Reworks in response to concerns from Hans
Project: http://git-wip-us.apache.org/repos/asf/trafodion/repo Commit: http://git-wip-us.apache.org/repos/asf/trafodion/commit/903149ad Tree: http://git-wip-us.apache.org/repos/asf/trafodion/tree/903149ad Diff: http://git-wip-us.apache.org/repos/asf/trafodion/diff/903149ad Branch: refs/heads/master Commit: 903149ad6cf61bd366bc63743f58d05a7313bfb0 Parents: f473c0c Author: Dave Birdsall <[email protected]> Authored: Sat Feb 3 01:06:43 2018 +0000 Committer: Dave Birdsall <[email protected]> Committed: Sat Feb 3 01:06:43 2018 +0000 ---------------------------------------------------------------------- core/sqf/sql/scripts/analyzeULOG.py | 62 ++++++++++++++++++++++++++++++-- core/sql/qmscommon/QRLogger.cpp | 3 +- core/sql/sqlcomp/nadefaults.cpp | 2 +- core/sql/ustat/hs_log.cpp | 34 +++++++----------- 4 files changed, 75 insertions(+), 26 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/trafodion/blob/903149ad/core/sqf/sql/scripts/analyzeULOG.py ---------------------------------------------------------------------- diff --git a/core/sqf/sql/scripts/analyzeULOG.py b/core/sqf/sql/scripts/analyzeULOG.py index 4e17626..e1e40e3 100644 --- a/core/sqf/sql/scripts/analyzeULOG.py +++ b/core/sqf/sql/scripts/analyzeULOG.py @@ -98,9 +98,9 @@ class ParseULOG: self.beginEndIntervals = [] - def parseULOG(self): + def parseOldULOG(self): # - # Begin/End entries look like this: + # Until Trafodion release 2.3, Begin/End entries looked like this: # # [Tue Mar 21 21:02:27 2017] :| BEGIN Allocate storage for columns # [Tue Mar 21 21:02:30 2017] :| END Allocate storage for columns elapsed time (00:00:02.666) @@ -151,7 +151,58 @@ class ParseULOG: print "Could not open " + self.ULOGFileName print detail + def parseNewULOG(self): + # + # Starting in Trafodion release 2.3, Begin/End entries looked like this: + # + # 2018-02-02 23:00:28,786, INFO, SQL.USTAT, Node Number: 0, CPU: 0, PIN: 15271, Process Name: $Z000CGB,,,:| BEGIN Allocate storage for columns + # 2018-02-02 23:00:28,786, INFO, SQL.USTAT, Node Number: 0, CPU: 0, PIN: 15271, Process Name: $Z000CGB,,,:| END Allocate storage for columns elapsed time (00:00:00.000) + # + # The number of vertical bars varies and indicates levels of nesting. + # For now we ignore the timestamp, and just pick out the description + # and the elapsed time. + # + try: + f = open(self.ULOGFileName) + previousItemNumber = [] + messageNumberStr = None + messageText = None + for line in f: + #originalLine = line + line = line.rstrip('\n') # get rid of trailing return character + index = line.find(',,,') + if index >= 0: + line = line[index+3:] # strip off leading stuff + if line.startswith(':'): + line = line[1:] # strip off colon + level = 0 + while line.startswith('| '): + level = level + 1 + line = line[3:] + if line.startswith('BEGIN '): + description = line[6:] # strip off BEGIN; description is what's left + # create a BeginEnd interval and add to stack + beginEndInterval = BeginEndInterval(description,level,previousItemNumber) + previousItemNumber = list(beginEndInterval.itemNumber) + self.beginEndIntervals.append(beginEndInterval) + elif line.startswith('END '): + index = line.find(' elapsed time (') + if index >= 0: + description = line[6:index] + elapsedTime = line[index+15:] + elapsedTime = elapsedTime.rstrip(')') + # pop the last BeginEnd interval from the stack + beginEndInterval = self.beginEndIntervals.pop() + beginEndInterval.setEnd(description,elapsedTime) + beginEndInterval.generateData() + previousItemNumber = list(beginEndInterval.itemNumber) + del beginEndInterval + f.close() + + except IOError as detail: + print "Could not open " + self.ULOGFileName + print detail @@ -163,6 +214,8 @@ class ParseULOG: parser = argparse.ArgumentParser( description='This script parses out interesting data from a ULOG.') parser.add_argument("ULOGFileName", help='The name of the ULOG file you wish to parse.') +parser.add_argument("--ULOGFormat",help='"new" is current ULOG format (this is the default), "old" is the old ULOG format', + default="new", choices=["new","old"]) args = parser.parse_args() # exits and prints help if args are incorrect @@ -170,7 +223,10 @@ exitCode = 0 ULOGparser = ParseULOG(args.ULOGFileName) -ULOGparser.parseULOG() +if args.ULOGFormat == "old": + ULOGparser.parseOldULOG() +else: + ULOGparser.parseNewULOG() exit(exitCode) http://git-wip-us.apache.org/repos/asf/trafodion/blob/903149ad/core/sql/qmscommon/QRLogger.cpp ---------------------------------------------------------------------- diff --git a/core/sql/qmscommon/QRLogger.cpp b/core/sql/qmscommon/QRLogger.cpp index b300c23..dc7f9c5 100644 --- a/core/sql/qmscommon/QRLogger.cpp +++ b/core/sql/qmscommon/QRLogger.cpp @@ -608,7 +608,8 @@ NABoolean QRLogger::startLogFile(const std::string &cat, const char * logFileNam { log4cxx::LoggerPtr logger(Logger::getLogger(cat)); logger->setAdditivity(false); // make this logger non-additive - log4cxx::PatternLayout * layout = new PatternLayout("%m%n"); // want just the message text + + log4cxx::PatternLayout * layout = new PatternLayout("%d, %p, %c, %m%n"); log4cxx::LogString fileName(logFileName); log4cxx::FileAppenderPtr fap(new FileAppender(layout,fileName,false /* no append */)); http://git-wip-us.apache.org/repos/asf/trafodion/blob/903149ad/core/sql/sqlcomp/nadefaults.cpp ---------------------------------------------------------------------- diff --git a/core/sql/sqlcomp/nadefaults.cpp b/core/sql/sqlcomp/nadefaults.cpp index bd948a9..965ecc4 100644 --- a/core/sql/sqlcomp/nadefaults.cpp +++ b/core/sql/sqlcomp/nadefaults.cpp @@ -3112,7 +3112,7 @@ XDDkwd__(SUBQUERY_UNNESTING, "ON"), DDkwd__(USTAT_JIT_LOGGING, "OFF"), - DD_____(USTAT_LOG, "ULOG"), + DD_____(USTAT_LOG, ""), // if non-empty, gives second qualifier to ustat log file name DDui30_246(USTAT_MAX_CHAR_BOUNDARY_LEN, "30"), // Values can be 30-246. DDui___(USTAT_MAX_CHAR_COL_LENGTH_IN_BYTES, "256"), // When computing UECs, char cols are limited to this many bytes DDflt0_ (USTAT_MAX_CHAR_DATASIZE_FOR_IS, "1000"), // max data size in MB for char type to use http://git-wip-us.apache.org/repos/asf/trafodion/blob/903149ad/core/sql/ustat/hs_log.cpp ---------------------------------------------------------------------- diff --git a/core/sql/ustat/hs_log.cpp b/core/sql/ustat/hs_log.cpp index 4519a82..4eb2d71 100644 --- a/core/sql/ustat/hs_log.cpp +++ b/core/sql/ustat/hs_log.cpp @@ -307,20 +307,7 @@ void HSLogMan::Log(const char *data) { if (logNeeded_) { - time_t currentTime = time(0); - struct tm currentTimeExploded; - localtime_r(¤tTime,¤tTimeExploded); - char localTime[100]; // way more space than needed - strftime(localTime,sizeof(localTime),"%c",¤tTimeExploded); - - NAString temp; - temp = "["; - temp += localTime; - temp += "] "; - temp += data; - // Note: LL_FATAL always logs. The format we use doesn't include - // the severity, so "FATAL" doesn't actually show up in ULOG data - QRLogger::log1(CAT_SQL_USTAT, LL_FATAL, temp.data()); // use log1 to avoid cpu, process etc. prefix + QRLogger::log(CAT_SQL_USTAT, LL_INFO, data); } } @@ -395,19 +382,24 @@ void HSLogMan::StartLog(NABoolean needExplain) if (logFileName.size() > 0) logFileName += '/'; + logFileName += "ustat"; // file name prefix will always be "ustat" + + // if CQD USTAT_LOG is set, extract the file name part from it and insert + // that to the log file name as an additional qualifier const char * ustatLog = ActiveSchemaDB()->getDefaults().getValue(USTAT_LOG); - const char * fileNameStem = ustatLog + strlen(ustatLog); - if (ustatLog == fileNameStem) - fileNameStem = "ULOG"; // CQD USTAT_LOG is the empty string - else + if (strlen(ustatLog) > 0) { + const char * fileNameQualifier = ustatLog + strlen(ustatLog); + // strip off any directory path name; we will always use the logs directory // as configured via QRLogger - while ((fileNameStem > ustatLog) && (*(fileNameStem - 1) != '/')) - fileNameStem--; + while ((fileNameQualifier > ustatLog) && (*(fileNameQualifier - 1) != '/')) + fileNameQualifier--; + + logFileName += '.'; + logFileName += fileNameQualifier; } - logFileName += fileNameStem; logFileName += qualifiers; NABoolean logStarted = QRLogger::startLogFile(CAT_SQL_USTAT,logFileName.c_str());
