From 4758c8d40f061f59ece05ce5a9dd0383434e68e2 Mon Sep 17 00:00:00 2001 From: Arkadiusz Sarwa Date: Fri, 12 Jan 2018 15:13:30 +0100 Subject: [PATCH] Add runtime time report of a CTS run New section have been added to file TestResults.qpa. "#beginTestsCasesTime" - section contains a time summary for groups. bottleneck_report.py - script which helps to find bottlenecks in CTS Components: Framework VK-GL-CTS issue: 879 Change-Id: I73773d820ddcd0f5b3c50c2128b8961cd1227b0e --- doc/qpa_file_format.txt | 4 + framework/common/tcuTestLog.cpp | 12 ++ framework/common/tcuTestLog.hpp | 3 + framework/common/tcuTestSessionExecutor.cpp | 43 +++++-- framework/common/tcuTestSessionExecutor.hpp | 6 + framework/qphelper/qpTestLog.c | 48 ++++++++ framework/qphelper/qpTestLog.h | 4 + scripts/log/README.md | 66 ++++++++++ scripts/log/bottleneck_report.py | 185 ++++++++++++++++++++++++++++ 9 files changed, 363 insertions(+), 8 deletions(-) create mode 100644 scripts/log/README.md create mode 100644 scripts/log/bottleneck_report.py diff --git a/doc/qpa_file_format.txt b/doc/qpa_file_format.txt index 4ebf1a1..9993dfe 100644 --- a/doc/qpa_file_format.txt +++ b/doc/qpa_file_format.txt @@ -44,6 +44,10 @@ configName #endTestCaseResult or #terminateTestCaseResult +* After test cases, tests time summary is added +#beginTestsCasesTime
+#endTestsCasesTime + * Execution done #endSession diff --git a/framework/common/tcuTestLog.cpp b/framework/common/tcuTestLog.cpp index 4ff823e..d7ee182 100644 --- a/framework/common/tcuTestLog.cpp +++ b/framework/common/tcuTestLog.cpp @@ -459,6 +459,18 @@ void TestLog::terminateCase (qpTestResult result) throw LogWriteFailedError(); } +void TestLog::startTestsCasesTime (void) +{ + if (qpTestLog_startTestsCasesTime(m_log) == DE_FALSE) + throw LogWriteFailedError(); +} + +void TestLog::endTestsCasesTime (void) +{ + if (qpTestLog_endTestsCasesTime(m_log) == DE_FALSE) + throw LogWriteFailedError(); +} + void TestLog::startSampleList (const std::string& name, const std::string& description) { if (qpTestLog_startSampleList(m_log, name.c_str(), description.c_str()) == DE_FALSE) diff --git a/framework/common/tcuTestLog.hpp b/framework/common/tcuTestLog.hpp index 03d236e..fef2dc6 100644 --- a/framework/common/tcuTestLog.hpp +++ b/framework/common/tcuTestLog.hpp @@ -161,6 +161,9 @@ public: void endCase (qpTestResult result, const char* description); void terminateCase (qpTestResult result); + void startTestsCasesTime (void); + void endTestsCasesTime (void); + void startSampleList (const std::string& name, const std::string& description); void startSampleInfo (void); void writeValueInfo (const std::string& name, const std::string& description, const std::string& unit, qpSampleValueTag tag); diff --git a/framework/common/tcuTestSessionExecutor.cpp b/framework/common/tcuTestSessionExecutor.cpp index 7a70a1a..bf7eb24 100644 --- a/framework/common/tcuTestSessionExecutor.cpp +++ b/framework/common/tcuTestSessionExecutor.cpp @@ -47,14 +47,15 @@ static qpTestCaseType nodeTypeToTestCaseType (TestNodeType nodeType) } TestSessionExecutor::TestSessionExecutor (TestPackageRoot& root, TestContext& testCtx) - : m_testCtx (testCtx) - , m_inflater (testCtx) - , m_caseListFilter (testCtx.getCommandLine().createCaseListFilter(testCtx.getArchive())) - , m_iterator (root, m_inflater, *m_caseListFilter) - , m_state (STATE_TRAVERSE_HIERARCHY) - , m_abortSession (false) - , m_isInTestCase (false) - , m_testStartTime (0) + : m_testCtx (testCtx) + , m_inflater (testCtx) + , m_caseListFilter (testCtx.getCommandLine().createCaseListFilter(testCtx.getArchive())) + , m_iterator (root, m_inflater, *m_caseListFilter) + , m_state (STATE_TRAVERSE_HIERARCHY) + , m_abortSession (false) + , m_isInTestCase (false) + , m_testStartTime (0) + , m_packageStartTime (0) { } @@ -89,7 +90,10 @@ bool TestSessionExecutor::iterate (void) } case NODETYPE_GROUP: + { + isEnter ? enterTestGroup(m_iterator.getNodePath()) : leaveTestGroup(m_iterator.getNodePath()); break; // nada + } case NODETYPE_SELF_VALIDATE: case NODETYPE_PERFORMANCE: @@ -154,12 +158,35 @@ void TestSessionExecutor::enterTestPackage (TestPackage* testPackage) // Create test case wrapper DE_ASSERT(!m_caseExecutor); m_caseExecutor = de::MovePtr(testPackage->createExecutor()); + m_packageStartTime = deGetMicroseconds(); } void TestSessionExecutor::leaveTestPackage (TestPackage* testPackage) { DE_UNREF(testPackage); m_caseExecutor.clear(); + m_testCtx.getLog().startTestsCasesTime(); + + { + const deInt64 duration = deGetMicroseconds() - m_packageStartTime; + m_packageStartTime = 0; + m_testCtx.getLog() << TestLog::Integer(testPackage->getName(), "Total tests case duration in microseconds", "us", QP_KEY_TAG_TIME, duration); + } + + for(std::map::iterator it=m_groupsDurationTime.begin(); it != m_groupsDurationTime.end(); ++it) + m_testCtx.getLog() << TestLog::Integer(it->first, "The test group case duration in microseconds", "us", QP_KEY_TAG_TIME, it->second); + + m_testCtx.getLog().endTestsCasesTime(); +} + +void TestSessionExecutor::enterTestGroup (const std::string& casePath) +{ + m_groupsDurationTime[casePath] = deGetMicroseconds(); +} + +void TestSessionExecutor::leaveTestGroup (const std::string& casePath) +{ + m_groupsDurationTime[casePath] = deGetMicroseconds() - m_groupsDurationTime[casePath]; } bool TestSessionExecutor::enterTestCase (TestCase* testCase, const std::string& casePath) diff --git a/framework/common/tcuTestSessionExecutor.hpp b/framework/common/tcuTestSessionExecutor.hpp index ad0bcee..b793ea7 100644 --- a/framework/common/tcuTestSessionExecutor.hpp +++ b/framework/common/tcuTestSessionExecutor.hpp @@ -29,6 +29,7 @@ #include "tcuTestPackage.hpp" #include "tcuTestHierarchyIterator.hpp" #include "deUniquePtr.hpp" +#include namespace tcu { @@ -72,6 +73,9 @@ private: void enterTestPackage (TestPackage* testPackage); void leaveTestPackage (TestPackage* testPackage); + void enterTestGroup (const std::string& casePath); + void leaveTestGroup (const std::string& casePath); + bool enterTestCase (TestCase* testCase, const std::string& casePath); TestCase::IterateResult iterateTestCase (TestCase* testCase); void leaveTestCase (TestCase* testCase); @@ -96,6 +100,8 @@ private: bool m_abortSession; bool m_isInTestCase; deUint64 m_testStartTime; + deUint64 m_packageStartTime; + std::map m_groupsDurationTime; }; } // tcu diff --git a/framework/qphelper/qpTestLog.c b/framework/qphelper/qpTestLog.c index 383a9e3..5e18e88 100644 --- a/framework/qphelper/qpTestLog.c +++ b/framework/qphelper/qpTestLog.c @@ -486,6 +486,54 @@ deBool qpTestLog_endCase (qpTestLog* log, qpTestResult result, const char* resul return DE_TRUE; } +deBool qpTestLog_startTestsCasesTime (qpTestLog* log) +{ + DE_ASSERT(log); + deMutex_lock(log->lock); + + /* Flush XML and write out #beginTestCaseResult. */ + qpXmlWriter_flush(log->writer); + fprintf(log->outputFile, "\n#beginTestsCasesTime\n"); + + log->isCaseOpen = DE_TRUE; + + if (!qpXmlWriter_startDocument(log->writer) || + !qpXmlWriter_startElement(log->writer, "TestsCasesTime", 0, (const qpXmlAttribute*)DE_NULL)) + { + qpPrintf("qpTestLog_startTestsCasesTime(): Writing XML failed\n"); + deMutex_unlock(log->lock); + return DE_FALSE; + } + + deMutex_unlock(log->lock); + return DE_TRUE; +} + +deBool qpTestLog_endTestsCasesTime (qpTestLog* log) +{ + DE_ASSERT(log); + deMutex_lock(log->lock); + + DE_ASSERT(log->isCaseOpen); + + if (!qpXmlWriter_endElement(log->writer, "TestsCasesTime")) + { + qpPrintf("qpTestLog_endTestsCasesTime(): Writing XML failed\n"); + deMutex_unlock(log->lock); + return DE_FALSE; + } + + qpXmlWriter_flush(log->writer); + + fprintf(log->outputFile, "\n#endTestsCasesTime\n"); + + log->isCaseOpen = DE_FALSE; + + deMutex_unlock(log->lock); + return DE_TRUE; +} + + /*--------------------------------------------------------------------*//*! * \brief Abrupt termination of logging. * \param log qpTestLog instance diff --git a/framework/qphelper/qpTestLog.h b/framework/qphelper/qpTestLog.h index 1871e71..fcf0938 100644 --- a/framework/qphelper/qpTestLog.h +++ b/framework/qphelper/qpTestLog.h @@ -193,6 +193,10 @@ void qpTestLog_destroy (qpTestLog* log); deBool qpTestLog_startCase (qpTestLog* log, const char* testCasePath, qpTestCaseType testCaseType); deBool qpTestLog_endCase (qpTestLog* log, qpTestResult result, const char* description); + +deBool qpTestLog_startTestsCasesTime (qpTestLog* log); +deBool qpTestLog_endTestsCasesTime (qpTestLog* log); + deBool qpTestLog_terminateCase (qpTestLog* log, qpTestResult result); deBool qpTestLog_startSection (qpTestLog* log, const char* name, const char* description); diff --git a/scripts/log/README.md b/scripts/log/README.md new file mode 100644 index 0000000..1a02925 --- /dev/null +++ b/scripts/log/README.md @@ -0,0 +1,66 @@ +# Manual for bottleneck_report.py script + +## Script name and location + +| name | bottleneck_report.py | +| location | VKGLCTS_ROOT/scripts/log | + +## Description + +The script parses qpa report file and produces an output containing three lists: + +1. A list of single tests sorted descending by the duration of execution. On this list one can +find exceptionally lenghty tests. + +2. A list of groups of tests sorted descending by their total duration of execution. This list +can be used to spot a groups that either contain a large amount of tests or multiple slow tests. + +3. A list of groups of tests sorted descending by an average duration of the test in this group +(a total duration of group divided by number of tests in the group). Presents groups containing +slow tests. + +This script requires that qpa file contains tests timing data (one created with sufficiently new +version of cts framework). + +## Usage + +`python path/to/bottleneck_report.py TESTLOG COUNT` + +`TESTLOG` - a fully qualified path to read-accessible qpa report file. +`COUNT` - number of entries output in each section. + +## Example + +`python bottleneck_report.py c:\khronos\build\external\vulkancts\modules\vulkan\TestResults.qpa 5` + +Produces following output: + +``` +The biggest tests time of execution +Index Time Full name +1 624010 dEQP-VK.subgroups.ballot_other.subgroupballotfindmsb_tess_control +2 614621 dEQP-VK.subgroups.shuffle.subgroupshuffle_int_tess_control +3 549420 dEQP-VK.subgroups.quad.subgroupquadbroadcast_1_int_tess_control +4 532983 dEQP-VK.subgroups.ballot_other.subgroupballotinclusivebitcount_tess_control +5 524019 dEQP-VK.subgroups.quad.subgroupquadbroadcast_0_int_tess_control + +Groups Statistics +Total time of execution: 758611214 +Number of executed tests: 4935 + +The biggest total time of execution +Index Time Test count Full name +1 324242753 2100 dEQP-VK.subgroups.arithmetic +2 137952758 980 dEQP-VK.subgroups.quad +3 124482580 700 dEQP-VK.subgroups.clustered +4 82749504 560 dEQP-VK.subgroups.shuffle +5 49100267 287 dEQP-VK.subgroups.ballot_broadcast + +The biggest time of execution per test +Index Time Test count Avg. test time Full name +1 124482580 700 177832 dEQP-VK.subgroups.clustered +2 49100267 287 171081 dEQP-VK.subgroups.ballot_broadcast +3 324242753 2100 154401 dEQP-VK.subgroups.arithmetic +4 82749504 560 147766 dEQP-VK.subgroups.shuffle +5 1992289 14 142306 dEQP-VK.subgroups.shape +``` diff --git a/scripts/log/bottleneck_report.py b/scripts/log/bottleneck_report.py new file mode 100644 index 0000000..a957bc9 --- /dev/null +++ b/scripts/log/bottleneck_report.py @@ -0,0 +1,185 @@ +# -*- coding: utf-8 -*- + +#------------------------------------------------------------------------- +# Quality Program utilities +# -------------------------------------- +# +# Copyright 2018 +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# +#------------------------------------------------------------------------- + +import os +import copy +import sys +import xml.sax +import xml.sax.handler +from log_parser import BatchResultParser, StatusCode + +class TimeOfExecutionGroups() : + def __init__(self): + self.path = "" + self.numberOfTests = 0 + self.timeOfExecution = 0 + +class TimeOfExecutionTests() : + def __init__(self): + self.path = "" + self.timeOfExecution = 0 + +def sortKey (element ) : + return int(element.timeOfExecution) + +def sortKeyTimePerTest (element) : + return int(int(element.timeOfExecution)/int(element.numberOfTests)) + +class XMLLogHandlerTests(xml.sax.handler.ContentHandler) : + def __init__ (self): + self.list = [] + self.element = TimeOfExecutionTests() + self.testTime = False + + def startElement (self, name, attrs): + if name == "TestCaseResult" : + self.element.path = attrs.getValue("CasePath") + if name == "Number" and "TestDuration" == attrs.getValue("Name") : + self.testTime = True + + def characters(self, content) : + if self.testTime : + self.testTime = False + self.element.timeOfExecution = content + self.list.append(copy.deepcopy(self.element)) + + def bottleneck (self, resultCount) : + print "The biggest tests time of execution" + print '%-4s%12s\t%12s' % ("Index", "Time", "Full name") + self.list.sort(key = sortKey, reverse = True) + ndx = 1 + for test in self.list : + print '%-4i%12i\t%12s' % (int(ndx), int(test.timeOfExecution), test.path) + ndx+=1 + if int(ndx) > int(resultCount) : + break + +class XMLLogHandlerGroups(xml.sax.handler.ContentHandler) : + def __init__ (self, testList) : + self.list = [] + self.testList = testList + self.element = TimeOfExecutionGroups() + self.addIt = False + + def startElement (self, name, attrs) : + self.element.numberOfTests = 0 + if name == "Number" : + self.element.path = attrs.getValue("Name") + if self.element.path == "dEQP-VK" : + self.addIt = True + self.element.numberOfTests = len(self.testList) + else : + for test in self.testList : + if test.path[:test.path.rfind(".")] in self.element.path : + self.addIt = True + self.element.numberOfTests += 1 + + def characters(self, content) : + if self.addIt : + self.addIt = False + self.element.timeOfExecution = content + self.list.append(copy.deepcopy(self.element)) + + def bottleneck (self, resultCount) : + self.list.sort(key = sortKey, reverse = True) + print "\nGroups Statistics" + print "Total time of execution:\t", self.list[0].timeOfExecution + print "Number of executed tests:\t", self.list[0].numberOfTests + print "\nThe biggest total time of execution" + print '%-4s%15s%15s\t%-30s' % ("Index", "Time", "Test count", "Full name") + ndx = 1 + for test in self.list : + if test.path == "dEQP-VK" : + continue + print '%-4s%15s%15s\t%-30s' % (ndx, test.timeOfExecution, test.numberOfTests, test.path) + ndx+=1 + if int(ndx) > int(resultCount) : + break + self.list.sort(key = sortKeyTimePerTest, reverse = True) + print "\nThe biggest time of execution per test" + print '%-4s%15s%15s%15s\t%-30s' % ("Index", "Time", "Test count", "\tAvg. test time", "Full name") + ndx = 1 + for test in self.list : + if test.path == "dEQP-VK" : + continue + print '%-4s%15s%15s%15i\t%-30s' % (ndx, test.timeOfExecution, test.numberOfTests, int(test.timeOfExecution)/int(test.numberOfTests), test.path) + ndx+=1 + if int(ndx) > int(resultCount) : + break + +class LogErrorHandler(xml.sax.handler.ErrorHandler) : + def __init__ (self) : + pass + + def error (self, err) : + #print "error(%s)" % str(err) + pass + + def fatalError (self, err) : + #print "fatalError(%s)" % str(err) + pass + + def warning (self, warn) : + #print "warning(%s)" % str(warn) + pass + +def findFirstElementByName (nodes, name) : + for node in nodes: + if node.nodeName == name : + return node + chFound = findFirstElementByName(node.childNodes, name) + if chFound != None : + return chFound + return None + +def printTimes (inFile, resultCount) : + #Test section + parser = BatchResultParser() + results = parser.parseFile(inFile) + handler = XMLLogHandlerTests() + errHandler = LogErrorHandler() + for result in results : + xml.sax.parseString(result.log, handler, errHandler) + handler.bottleneck(resultCount) + + #Group section + startRecordLines = False + lines = "" + f = open(inFile, 'rb') + for line in f : + if "#endTestsCasesTime" in line : + break + if startRecordLines : + lines += line + if "#beginTestsCasesTime" in line : + startRecordLines = True + f.close() + handlerGroups = XMLLogHandlerGroups(handler.list) + xml.sax.parseString(lines, handlerGroups, errHandler) + handlerGroups.bottleneck(resultCount) + +if __name__ == "__main__" : + if len(sys.argv) != 3: + print "%s: [test log] [count of result to display]" % sys.argv[0] + print "example: python %s TestResults.qpa 10" % sys.argv[0] + sys.exit(-1) + printTimes(sys.argv[1], sys.argv[2]) -- 2.7.4